mirror of
https://github.com/ChuckBuilds/LEDMatrix.git
synced 2026-08-22 19:08:17 +00:00
Compare commits
4
Commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
6b74506695 | ||
|
|
5f29243e87 | ||
|
|
1fbe244e49 | ||
|
|
863e4a1ecd |
@@ -18,7 +18,7 @@ tooling against it.
|
||||
| `web_display_autostart` | bool, `true` | Whether the web interface service starts with the system | `scripts/utils/start_web_conditionally.py` |
|
||||
| `timezone` | string, `"America/New_York"` | IANA timezone for schedules and displays | `ConfigManager.get_timezone()` |
|
||||
| `target_fps` | int, `100` | Frame-rate ceiling for plugin rendering | `src/plugin_system/base_plugin.py`, `src/common/sports_scroll.py` |
|
||||
| `location` | object | `city` / `state` / `country`, offered to plugins that need a location (weather, etc.) | plugins via merged config |
|
||||
| `location` | object | `city` / `state` / `country`. Supplies the **default** for a plugin's own `location_city` / `location_state` / `location_country` setting, so weather, radar and friends follow this device without being configured twice. A value saved on the plugin itself still overrides it. | `SchemaManager.apply_device_location()`, then plugins via merged config |
|
||||
|
||||
## `schedule` — display on/off hours
|
||||
|
||||
|
||||
@@ -145,8 +145,7 @@ class SportsUpcoming(SportsCore):
|
||||
if (game['home_abbr'] in self.favorite_teams or
|
||||
game['away_abbr'] in self.favorite_teams):
|
||||
favorite_games_found += 1
|
||||
if self.show_odds:
|
||||
self._fetch_odds(game)
|
||||
# Odds are NOT fetched here -- see after selection below.
|
||||
|
||||
# Enhanced logging for debugging
|
||||
self.logger.info(f"Found {all_upcoming_games} total upcoming games in data")
|
||||
@@ -190,6 +189,20 @@ class SportsUpcoming(SportsCore):
|
||||
# Limit to the specified number of upcoming games
|
||||
team_games = team_games[:self.upcoming_games_to_show]
|
||||
|
||||
# Odds are fetched here, for the games that survived selection,
|
||||
# rather than in the loop that collects them. That loop walks every
|
||||
# upcoming game in the schedule window, and for a college league
|
||||
# the window is enormous -- a live rig logged 946 upcoming games in
|
||||
# one cycle and displayed 1 of them. The comment up there claimed
|
||||
# odds were fetched "only for games that will be displayed", but
|
||||
# the only narrowing it applied was show_favorite_teams_only, which
|
||||
# is not the default; in the usual case nothing narrowed it at all
|
||||
# and every game cost a separate ESPN request on a Pi that is also
|
||||
# driving the panel.
|
||||
if self.show_odds:
|
||||
for game in team_games:
|
||||
self._fetch_odds(game)
|
||||
|
||||
# Log changes or periodically
|
||||
should_log = (
|
||||
current_time - self.last_log_time >= self.log_interval or
|
||||
|
||||
@@ -328,7 +328,7 @@ class ScrollHelper:
|
||||
elapsed_time = current_time - (self.scroll_start_time or current_time)
|
||||
# The image already includes display_width padding, so we only need total_scroll_width
|
||||
required_total_distance = self.total_scroll_width
|
||||
self.logger.info(
|
||||
self.logger.debug(
|
||||
"Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
|
||||
elapsed_time,
|
||||
self.calculated_duration,
|
||||
|
||||
+84
-1
@@ -130,7 +130,12 @@ def setup_logging(
|
||||
# Console handler (always add)
|
||||
console_handler = logging.StreamHandler(sys.stdout)
|
||||
console_handler.setLevel(level)
|
||||
console_handler.setFormatter(formatter)
|
||||
# Under systemd, tag each line so the journal records the real severity
|
||||
# rather than filing everything as informational. The file handler below
|
||||
# keeps the plain formatter: the prefix is meaningful to journald and noise
|
||||
# anywhere else.
|
||||
console_handler.setFormatter(
|
||||
JournalPriorityFormatter(formatter) if _under_systemd() else formatter)
|
||||
root_logger.addHandler(console_handler)
|
||||
|
||||
# File handler (if specified)
|
||||
@@ -145,6 +150,84 @@ def setup_logging(
|
||||
sys.stderr.write(f"Warning: Could not set up file logging to {log_file}: {e}\n")
|
||||
|
||||
|
||||
#: syslog priorities, which is what systemd parses from a "<N>" prefix on
|
||||
#: stdout. Mapped from Python's levels.
|
||||
_SYSLOG_PRIORITY = {
|
||||
logging.CRITICAL: 2, # LOG_CRIT
|
||||
logging.ERROR: 3, # LOG_ERR
|
||||
logging.WARNING: 4, # LOG_WARNING
|
||||
logging.INFO: 6, # LOG_INFO
|
||||
logging.DEBUG: 7, # LOG_DEBUG
|
||||
}
|
||||
|
||||
|
||||
class JournalPriorityFormatter(logging.Formatter):
|
||||
"""Wraps a formatter, prefixing each line with its syslog priority.
|
||||
|
||||
Under systemd everything this process writes to stdout lands in the journal
|
||||
as PRIORITY=6, whatever the Python level was. Measured on a live rig: 55
|
||||
ERROR lines and 13 WARNING lines in a day, every one of them recorded as
|
||||
informational, so `journalctl -p err -u ledmatrix` returned nothing at all
|
||||
while errors were being logged. Anyone triaging has to grep the message
|
||||
text instead, which is both slower and wrong -- a search for "oom" matches
|
||||
the radar logging "zoom=9".
|
||||
|
||||
systemd reads a leading "<N>" on each line and uses it as the priority
|
||||
(sd-daemon(3)), so this needs no extra dependency. Multi-line records get
|
||||
the prefix on every line, since the journal splits them and an unprefixed
|
||||
continuation would fall back to the default.
|
||||
"""
|
||||
|
||||
def __init__(self, inner: logging.Formatter):
|
||||
super().__init__()
|
||||
self._inner = inner
|
||||
|
||||
@property
|
||||
def inner(self) -> logging.Formatter:
|
||||
"""The formatter doing the actual work.
|
||||
|
||||
Whether journald tagging is applied depends on JOURNAL_STREAM, so it is
|
||||
on under systemd and off in a terminal -- and anything asserting which
|
||||
formatter setup_logging() selected would otherwise get a different
|
||||
answer in CI than on a developer's machine. Exposing the inner one lets
|
||||
those checks stay about format_type, which is what they mean.
|
||||
"""
|
||||
return self._inner
|
||||
|
||||
def format(self, record: logging.LogRecord) -> str:
|
||||
text = self._inner.format(record)
|
||||
prefix = f"<{_SYSLOG_PRIORITY.get(record.levelno, 6)}>"
|
||||
return "\n".join(prefix + line for line in text.split("\n"))
|
||||
|
||||
|
||||
def _under_systemd() -> bool:
|
||||
"""True when stdout really is the journal.
|
||||
|
||||
systemd sets JOURNAL_STREAM to "dev:ino" for services whose output it
|
||||
captures. Presence alone is not enough to act on: the variable is
|
||||
inherited by child processes and survives redirection, so a subprocess
|
||||
whose stdout is a pipe or a file still sees it and would emit the "<N>"
|
||||
priority prefixes as literal noise into that output. systemd's own
|
||||
guidance is to fstat the descriptor and compare st_dev/st_ino, which is
|
||||
what distinguishes "the journal is somewhere in my ancestry" from "my
|
||||
stdout is the journal".
|
||||
"""
|
||||
declared = os.environ.get("JOURNAL_STREAM")
|
||||
if not declared:
|
||||
return False
|
||||
try:
|
||||
dev_text, ino_text = declared.split(":", 1)
|
||||
declared_ids = (int(dev_text), int(ino_text))
|
||||
except (ValueError, AttributeError):
|
||||
return False
|
||||
try:
|
||||
stat_result = os.fstat(sys.stdout.fileno())
|
||||
except (OSError, ValueError, AttributeError):
|
||||
# No usable stdout: captured by pytest, detached, or already closed.
|
||||
return False
|
||||
return (stat_result.st_dev, stat_result.st_ino) == declared_ids
|
||||
|
||||
|
||||
class PluginLoggerAdapter(logging.LoggerAdapter):
|
||||
"""LoggerAdapter that stamps every record with its plugin_id.
|
||||
|
||||
|
||||
@@ -178,11 +178,21 @@ class PluginHealthTracker:
|
||||
)
|
||||
return self._health_state[plugin_id]
|
||||
|
||||
# Fields the circuit breaker is rebuilt from after a restart. Everything
|
||||
# else in a health record is reporting, read only for display.
|
||||
_DURABLE_FIELDS = ('consecutive_failures', 'circuit_state',
|
||||
'circuit_opened_time', 'half_open_start_time')
|
||||
|
||||
def _durable(self, state: Dict[str, Any]) -> tuple:
|
||||
"""The part of a health record whose loss would change behaviour."""
|
||||
return tuple(state.get(field) for field in self._DURABLE_FIELDS)
|
||||
|
||||
def record_success(self, plugin_id: str) -> None:
|
||||
"""Record a successful plugin execution."""
|
||||
state = self.get_health_state(plugin_id)
|
||||
current_time = time.time()
|
||||
|
||||
durable_before = self._durable(state)
|
||||
|
||||
# Reset consecutive failures
|
||||
state['consecutive_failures'] = 0
|
||||
state['total_successes'] = state.get('total_successes', 0) + 1
|
||||
@@ -198,9 +208,20 @@ class PluginHealthTracker:
|
||||
# Shouldn't happen, but handle it
|
||||
state['circuit_state'] = CircuitState.CLOSED.value
|
||||
state['circuit_opened_time'] = None
|
||||
|
||||
self._save_health_state(plugin_id, state)
|
||||
|
||||
|
||||
# A healthy plugin reports success every cycle, and in that steady state
|
||||
# the only fields changed above are a counter and a timestamp that
|
||||
# nothing reads back after a restart. Persisting them anyway rewrites a
|
||||
# small file per plugin per cycle: on a rig running 24 plugins, a
|
||||
# five-minute sample measured 22 rewrites, about 4.4 a minute or 6,300 a
|
||||
# day. Those land on an SD card, where the cost is an erase-block cycle
|
||||
# rather than the 400 bytes involved, and where wear is what eventually
|
||||
# kills the card.
|
||||
# In-memory state is still updated every time, so the health API and web
|
||||
# UI show exactly what they did before; only the write is skipped.
|
||||
if self._durable(state) != durable_before:
|
||||
self._save_health_state(plugin_id, state)
|
||||
|
||||
def record_failure(self, plugin_id: str, error: Optional[Exception] = None) -> None:
|
||||
"""Record a failed plugin execution."""
|
||||
state = self.get_health_state(plugin_id)
|
||||
|
||||
@@ -71,11 +71,15 @@ class PluginManager:
|
||||
self.plugin_loader = PluginLoader(logger=self.logger)
|
||||
self.plugin_executor = PluginExecutor(default_timeout=30.0, logger=self.logger)
|
||||
self.state_manager = PluginStateManager(logger=self.logger)
|
||||
self.schema_manager = SchemaManager(plugins_dir=self.plugins_dir, logger=self.logger)
|
||||
self.schema_manager = SchemaManager(plugins_dir=self.plugins_dir, logger=self.logger,
|
||||
config_manager=self.config_manager)
|
||||
|
||||
# Lock protecting plugin_manifests and plugin_directories from
|
||||
# concurrent mutation (background reconciliation) and reads (requests).
|
||||
self._discovery_lock = threading.RLock()
|
||||
#: Directories already reported as unloadable, so the warning is
|
||||
#: emitted once rather than on every discovery scan.
|
||||
self._skip_reported: set = set()
|
||||
|
||||
# Lock protecting plugin_last_update from concurrent mutation/iteration.
|
||||
# It's written from run_scheduled_updates()/update_all_plugins() (main
|
||||
@@ -195,18 +199,59 @@ class PluginManager:
|
||||
continue
|
||||
|
||||
manifest_path = item / "manifest.json"
|
||||
if manifest_path.exists():
|
||||
try:
|
||||
with open(manifest_path, 'r', encoding='utf-8') as f:
|
||||
manifest = json.load(f)
|
||||
plugin_id = manifest.get('id')
|
||||
if plugin_id:
|
||||
plugin_ids.append(plugin_id)
|
||||
new_manifests[plugin_id] = manifest
|
||||
new_directories[plugin_id] = item
|
||||
except (json.JSONDecodeError, PermissionError, OSError) as e:
|
||||
self.logger.warning("Error reading manifest from %s: %s", manifest_path, e, exc_info=True)
|
||||
continue
|
||||
if not manifest_path.exists():
|
||||
# Once per directory per process. Discovery runs on every
|
||||
# web UI page load and every config reconcile, so warning
|
||||
# unconditionally would put a line in the journal each
|
||||
# time someone opened a page -- the same log-volume
|
||||
# problem this is meant to help diagnose.
|
||||
# A directory here that carries no manifest is not a
|
||||
# plugin. Said once, because the alternative is a plugin
|
||||
# that is enabled in config, enabled in plugin state,
|
||||
# present on disk, and simply absent from the running
|
||||
# process with nothing anywhere to say why. Working that
|
||||
# out afterwards means reading cache-file mtimes.
|
||||
if item.name not in self._skip_reported:
|
||||
self._skip_reported.add(item.name)
|
||||
self.logger.warning(
|
||||
"Skipping %s: no manifest.json, so it cannot be "
|
||||
"loaded as a plugin", item.name)
|
||||
continue
|
||||
try:
|
||||
with open(manifest_path, 'r', encoding='utf-8') as f:
|
||||
manifest = json.load(f)
|
||||
except (json.JSONDecodeError, PermissionError, OSError) as e:
|
||||
self.logger.warning("Error reading manifest from %s: %s", manifest_path, e, exc_info=True)
|
||||
continue
|
||||
|
||||
# json.load accepts any JSON value, so a manifest holding
|
||||
# null, [] or "text" parses and then raises AttributeError on
|
||||
# .get(). Nothing here catches that -- the outer handler takes
|
||||
# OSError/PermissionError only -- so a single malformed
|
||||
# manifest aborted the whole scan and every other plugin on
|
||||
# disk, however healthy, silently failed to register.
|
||||
if not isinstance(manifest, dict):
|
||||
if item.name not in self._skip_reported:
|
||||
self._skip_reported.add(item.name)
|
||||
self.logger.warning(
|
||||
"Skipping %s: its manifest.json is %s, not a JSON "
|
||||
"object", item.name, type(manifest).__name__)
|
||||
continue
|
||||
|
||||
plugin_id = manifest.get('id')
|
||||
if not plugin_id:
|
||||
# Parsed but unusable. This was the quietest path of all:
|
||||
# the manifest is read successfully and then dropped.
|
||||
if item.name not in self._skip_reported:
|
||||
self._skip_reported.add(item.name)
|
||||
self.logger.warning(
|
||||
"Skipping %s: its manifest.json has no \"id\", so "
|
||||
"there is nothing to register it under", item.name)
|
||||
continue
|
||||
|
||||
plugin_ids.append(plugin_id)
|
||||
new_manifests[plugin_id] = manifest
|
||||
new_directories[plugin_id] = item
|
||||
except (OSError, PermissionError) as e:
|
||||
self.logger.error("Error scanning directory %s: %s", directory, e, exc_info=True)
|
||||
|
||||
|
||||
@@ -9,7 +9,7 @@ import time
|
||||
import logging
|
||||
import threading
|
||||
from typing import Dict, Optional, Any, Callable
|
||||
from dataclasses import dataclass, field
|
||||
from dataclasses import dataclass, field, fields
|
||||
|
||||
try:
|
||||
import psutil
|
||||
@@ -49,6 +49,20 @@ class ResourceMetrics:
|
||||
self.total_execution_time = self.total_execution_time / self.call_count
|
||||
|
||||
|
||||
#: How often a plugin's metrics are written to the cache, in seconds.
|
||||
#:
|
||||
#: Persisting on every call meant a small file rewritten roughly nine times a
|
||||
#: minute per plugin. On a rig with fourteen active plugins that was ~126
|
||||
#: writes a minute for metrics alone, and since each ~350-byte file costs a
|
||||
#: 4KB block plus an ext4 journal entry, it dominated the device's write
|
||||
#: volume -- on an SD card, which wears out.
|
||||
#:
|
||||
#: The in-memory copy stays authoritative and exact; only the cross-process
|
||||
#: snapshot the web UI reads is delayed, and telemetry up to half a minute old
|
||||
#: is still a fair description of a long-running plugin.
|
||||
_METRICS_PERSIST_INTERVAL = 30.0
|
||||
|
||||
|
||||
class PluginResourceMonitor:
|
||||
"""
|
||||
Monitors resource usage for plugins.
|
||||
@@ -75,6 +89,10 @@ class PluginResourceMonitor:
|
||||
# Resource metrics per plugin
|
||||
self._metrics: Dict[str, ResourceMetrics] = {}
|
||||
self._limits: Dict[str, ResourceLimits] = {}
|
||||
# When each plugin's metrics last reached the cache. Metrics change on
|
||||
# every call, so they cannot be de-duplicated the way health state can;
|
||||
# they are rate-limited instead. See _METRICS_PERSIST_INTERVAL.
|
||||
self._metrics_persisted_at: Dict[str, float] = {}
|
||||
|
||||
# Thread-local storage for execution tracking
|
||||
self._local = threading.local()
|
||||
@@ -102,6 +120,66 @@ class PluginResourceMonitor:
|
||||
"psutil not available - resource monitoring will be limited to execution time only"
|
||||
)
|
||||
|
||||
def _metrics_from_cache(self, plugin_id: str, cached: Any) -> "ResourceMetrics":
|
||||
"""Build metrics from a cached record, ignoring anything unrecognised.
|
||||
|
||||
ResourceMetrics(**cached) raises TypeError on a single unexpected key,
|
||||
and that exception escapes into plugin_manager, which reports it as
|
||||
"plugin <id> operation failed". Every plugin fails, and the plugin
|
||||
system never finishes initialising.
|
||||
|
||||
Seen on a live rig: every plugin failing with
|
||||
|
||||
ResourceMetrics.__init__() got an unexpected keyword argument
|
||||
'consecutive_failures'
|
||||
|
||||
which is a plugin_health field, not a metrics one. How a health-shaped
|
||||
record came to sit under a plugin_metrics key on that machine is not
|
||||
established -- a restored backup that mixed two machines' caches is the
|
||||
likeliest explanation -- but the loader should not be brittle enough for
|
||||
it to matter. plugin_health already repairs its records field by field
|
||||
rather than trusting whatever is on disk; this does the same.
|
||||
|
||||
Unknown keys are dropped and named once, so a genuine schema change is
|
||||
visible in the log instead of silently discarded.
|
||||
"""
|
||||
if not isinstance(cached, dict):
|
||||
self.logger.warning(
|
||||
"Ignoring cached metrics for %s: expected a mapping, got %s",
|
||||
plugin_id, type(cached).__name__)
|
||||
return ResourceMetrics()
|
||||
|
||||
known = {f.name for f in fields(ResourceMetrics)}
|
||||
unknown = sorted(set(cached) - known)
|
||||
if unknown:
|
||||
self.logger.warning(
|
||||
"Dropping unrecognised field(s) from cached metrics for %s: %s",
|
||||
plugin_id, ", ".join(unknown))
|
||||
# A dataclass does not enforce its annotations, so
|
||||
# ResourceMetrics(call_count="not a number") builds happily and only
|
||||
# blows up later, deep inside monitor_call ("can only concatenate str
|
||||
# (not \"int\") to str"). Coerce here, where there is still a cache
|
||||
# key to name in the warning.
|
||||
declared = {f.name: f.type for f in fields(ResourceMetrics)}
|
||||
usable = {}
|
||||
for key, value in cached.items():
|
||||
if key not in known:
|
||||
continue
|
||||
try:
|
||||
usable[key] = int(value) if declared[key] in ('int', int) else float(value)
|
||||
except (TypeError, ValueError):
|
||||
self.logger.warning(
|
||||
"Cached metrics for %s have a bad %s (%r); starting fresh",
|
||||
plugin_id, key, value)
|
||||
return ResourceMetrics()
|
||||
try:
|
||||
return ResourceMetrics(**usable)
|
||||
except (TypeError, ValueError) as e:
|
||||
self.logger.warning(
|
||||
"Cached metrics for %s unusable (%s); starting fresh",
|
||||
plugin_id, e)
|
||||
return ResourceMetrics()
|
||||
|
||||
def _get_metrics_key(self, plugin_id: str) -> str:
|
||||
"""Get cache key for plugin metrics."""
|
||||
return f"plugin_metrics:{plugin_id}"
|
||||
@@ -126,7 +204,7 @@ class PluginResourceMonitor:
|
||||
cache_key, max_age=None, memory_ttl=0 if force_reload else None
|
||||
)
|
||||
if cached:
|
||||
metrics = ResourceMetrics(**cached)
|
||||
metrics = self._metrics_from_cache(plugin_id, cached)
|
||||
else:
|
||||
metrics = ResourceMetrics()
|
||||
self._metrics[plugin_id] = metrics
|
||||
@@ -232,18 +310,8 @@ class PluginResourceMonitor:
|
||||
# CPU is harder to measure per-call, so we track it separately
|
||||
metrics.cpu_percent = self._get_process_cpu_percent()
|
||||
|
||||
# Persist metrics
|
||||
cache_key = self._get_metrics_key(plugin_id)
|
||||
self.cache_manager.set(cache_key, {
|
||||
'memory_mb': metrics.memory_mb,
|
||||
'cpu_percent': metrics.cpu_percent,
|
||||
'execution_time': metrics.execution_time,
|
||||
'call_count': metrics.call_count,
|
||||
'total_execution_time': metrics.total_execution_time,
|
||||
'max_execution_time': metrics.max_execution_time,
|
||||
'min_execution_time': metrics.min_execution_time if metrics.min_execution_time != float('inf') else 0.0,
|
||||
'last_update_time': metrics.last_update_time
|
||||
})
|
||||
# Persist metrics, at most once per interval per plugin.
|
||||
self._persist_metrics(plugin_id, metrics)
|
||||
|
||||
# Check limits
|
||||
if limits:
|
||||
@@ -363,6 +431,44 @@ class PluginResourceMonitor:
|
||||
summaries[plugin_id] = self.get_metrics_summary(plugin_id)
|
||||
return summaries
|
||||
|
||||
def _persist_metrics(self, plugin_id: str, metrics: ResourceMetrics,
|
||||
force: bool = False) -> None:
|
||||
"""Write a plugin's metrics to the cache, at most once per interval.
|
||||
|
||||
Caller must hold ``self._lock``.
|
||||
"""
|
||||
# Monotonic, not wall clock: these devices have no RTC, so the clock
|
||||
# jumps by however far off boot-time was the moment NTP first syncs.
|
||||
# A forward jump would allow an early write, a backward one would
|
||||
# stall the snapshot well past the interval.
|
||||
#
|
||||
# The sentinel for "never written" is None, not 0.0. monotonic() is
|
||||
# time since boot on Linux, and systemd starts this service *at* boot,
|
||||
# so `now - 0.0 < 30` was true for the first half-minute of every
|
||||
# single run -- the throttle swallowed the very first snapshot, which
|
||||
# is the one that matters most after a restart.
|
||||
now = time.monotonic()
|
||||
last_written = self._metrics_persisted_at.get(plugin_id)
|
||||
if (not force and last_written is not None
|
||||
and now - last_written < _METRICS_PERSIST_INTERVAL):
|
||||
return
|
||||
cache_key = self._get_metrics_key(plugin_id)
|
||||
self.cache_manager.set(cache_key, {
|
||||
'memory_mb': metrics.memory_mb,
|
||||
'cpu_percent': metrics.cpu_percent,
|
||||
'execution_time': metrics.execution_time,
|
||||
'call_count': metrics.call_count,
|
||||
'total_execution_time': metrics.total_execution_time,
|
||||
'max_execution_time': metrics.max_execution_time,
|
||||
'min_execution_time': (metrics.min_execution_time
|
||||
if metrics.min_execution_time != float('inf')
|
||||
else 0.0),
|
||||
'last_update_time': metrics.last_update_time,
|
||||
})
|
||||
# Only after the write lands. Marking it first would mean a failed
|
||||
# set() bought the next interval's silence without leaving a snapshot.
|
||||
self._metrics_persisted_at[plugin_id] = now
|
||||
|
||||
def reset_metrics(self, plugin_id: str) -> None:
|
||||
"""Reset metrics for a plugin."""
|
||||
with self._lock:
|
||||
@@ -370,4 +476,7 @@ class PluginResourceMonitor:
|
||||
self._metrics[plugin_id] = ResourceMetrics()
|
||||
cache_key = self._get_metrics_key(plugin_id)
|
||||
self.cache_manager.delete(cache_key)
|
||||
# Let the next call persist immediately rather than leaving the
|
||||
# deleted key absent for the rest of the interval.
|
||||
self._metrics_persisted_at.pop(plugin_id, None)
|
||||
|
||||
|
||||
@@ -26,7 +26,25 @@ class SchemaManager:
|
||||
- Cache invalidation on plugin changes
|
||||
"""
|
||||
|
||||
def __init__(self, plugins_dir: Optional[Path] = None, project_root: Optional[Path] = None, logger: Optional[logging.Logger] = None):
|
||||
# Plugin config keys that mean "where this device is". A plugin declaring
|
||||
# any of these in its schema gets the device-wide ``location`` block from
|
||||
# config.json as the *default* for that field, instead of whatever city the
|
||||
# plugin author happened to ship. A value the user set on the plugin itself
|
||||
# always wins -- this only ever replaces the schema default, so an explicit
|
||||
# per-plugin location is still honoured.
|
||||
#
|
||||
# Only these fully-namespaced keys are substituted. A bare ``state`` or
|
||||
# ``city`` key is deliberately left alone: plugins use those for unrelated
|
||||
# things (ledmatrix-elections' ``state`` is a two-letter code, not a place
|
||||
# name), and silently rewriting them would break those plugins.
|
||||
DEVICE_LOCATION_KEYS: Dict[str, str] = {
|
||||
'location_city': 'city',
|
||||
'location_state': 'state',
|
||||
'location_country': 'country',
|
||||
}
|
||||
|
||||
def __init__(self, plugins_dir: Optional[Path] = None, project_root: Optional[Path] = None,
|
||||
logger: Optional[logging.Logger] = None, config_manager: Optional[Any] = None):
|
||||
"""
|
||||
Initialize the Schema Manager.
|
||||
|
||||
@@ -34,10 +52,14 @@ class SchemaManager:
|
||||
plugins_dir: Base plugins directory path
|
||||
project_root: Project root directory path
|
||||
logger: Optional logger instance
|
||||
config_manager: Optional config manager, used to resolve the
|
||||
device-wide ``location`` that seeds plugin location defaults.
|
||||
Omitting it simply leaves schema defaults untouched.
|
||||
"""
|
||||
self.logger = logger or logging.getLogger(__name__)
|
||||
self.plugins_dir = plugins_dir
|
||||
self.project_root = project_root or Path.cwd()
|
||||
self.config_manager = config_manager
|
||||
|
||||
# Schema cache: plugin_id -> schema dict
|
||||
self._schema_cache: Dict[str, Dict[str, Any]] = {}
|
||||
@@ -212,10 +234,70 @@ class SchemaManager:
|
||||
|
||||
return defaults
|
||||
|
||||
def get_device_location(self) -> Optional[Dict[str, Any]]:
|
||||
"""
|
||||
Return the device-wide ``location`` block from config.json, or None.
|
||||
|
||||
This is the City/State/Country the user sets once under General
|
||||
settings. Returns None when there is no config manager wired, the
|
||||
config can't be read, or no location has been configured.
|
||||
"""
|
||||
if self.config_manager is None:
|
||||
return None
|
||||
try:
|
||||
config = self.config_manager.load_config()
|
||||
except Exception as e:
|
||||
# A config that can't be read must never stop defaults being
|
||||
# generated -- the plugin's own schema defaults still apply.
|
||||
self.logger.debug(f"Could not read device location from config: {e}")
|
||||
return None
|
||||
if not isinstance(config, dict):
|
||||
return None
|
||||
location = config.get('location')
|
||||
return location if isinstance(location, dict) else None
|
||||
|
||||
def apply_device_location(self, defaults: Dict[str, Any]) -> Dict[str, Any]:
|
||||
"""
|
||||
Replace location-shaped schema defaults with the device's own location.
|
||||
|
||||
Without this, a plugin that ships ``"location_city": "Dallas"`` as its
|
||||
schema default silently reports Dallas weather (and centres its radar
|
||||
there) for every user who never opened that plugin's config form --
|
||||
even though they set their real city under General settings. The
|
||||
substituted value is still only a *default*: ``merge_with_defaults``
|
||||
lets any per-plugin value the user saved win over it.
|
||||
|
||||
Mutates and returns ``defaults`` for convenience.
|
||||
"""
|
||||
if not defaults:
|
||||
return defaults
|
||||
if not any(key in defaults for key in self.DEVICE_LOCATION_KEYS):
|
||||
return defaults
|
||||
|
||||
location = self.get_device_location()
|
||||
if not location:
|
||||
return defaults
|
||||
|
||||
for key, field in self.DEVICE_LOCATION_KEYS.items():
|
||||
if key not in defaults:
|
||||
continue
|
||||
value = location.get(field)
|
||||
# Only a non-empty string is a real answer; a blank or missing
|
||||
# field means "not configured", which leaves the schema default.
|
||||
if isinstance(value, str) and value.strip():
|
||||
defaults[key] = value.strip()
|
||||
|
||||
return defaults
|
||||
|
||||
def generate_default_config(self, plugin_id: str, use_cache: bool = True) -> Dict[str, Any]:
|
||||
"""
|
||||
Generate default configuration for a plugin from its schema.
|
||||
|
||||
Location fields (see ``DEVICE_LOCATION_KEYS``) default to the device's
|
||||
configured location rather than the plugin author's. That substitution
|
||||
is applied on the way out rather than being cached, so changing the
|
||||
device location takes effect without invalidating the defaults cache.
|
||||
|
||||
Args:
|
||||
plugin_id: Plugin identifier
|
||||
use_cache: If True, return cached defaults if available
|
||||
@@ -225,7 +307,7 @@ class SchemaManager:
|
||||
"""
|
||||
# Check cache first
|
||||
if use_cache and plugin_id in self._defaults_cache:
|
||||
return self._defaults_cache[plugin_id].copy()
|
||||
return self.apply_device_location(self._defaults_cache[plugin_id].copy())
|
||||
|
||||
schema = self.load_schema(plugin_id, use_cache=use_cache)
|
||||
if not schema:
|
||||
@@ -249,10 +331,11 @@ class SchemaManager:
|
||||
if 'live_priority' not in defaults:
|
||||
defaults['live_priority'] = schema.get('properties', {}).get('live_priority', {}).get('default', False)
|
||||
|
||||
# Cache the defaults
|
||||
# Cache the defaults *before* the device location is layered on, so a
|
||||
# later change to the device location is picked up by the next call.
|
||||
self._defaults_cache[plugin_id] = defaults.copy()
|
||||
|
||||
return defaults
|
||||
return self.apply_device_location(defaults)
|
||||
|
||||
def validate_config_against_schema(self, config: Dict[str, Any], schema: Dict[str, Any],
|
||||
plugin_id: Optional[str] = None) -> Tuple[bool, List[str]]:
|
||||
|
||||
@@ -83,7 +83,7 @@ class PluginAdapter:
|
||||
# into unrelated headlines once the strip refreshed to 9,505px.
|
||||
self._offset_shapes: dict = {}
|
||||
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"PluginAdapter initialized: display=%dx%d",
|
||||
self.display_width, self.display_height
|
||||
)
|
||||
@@ -109,7 +109,7 @@ class PluginAdapter:
|
||||
Returns:
|
||||
List of PIL Images representing plugin content, or None if no content
|
||||
"""
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Getting content (class=%s)",
|
||||
plugin_id, plugin.__class__.__name__
|
||||
)
|
||||
@@ -118,7 +118,7 @@ class PluginAdapter:
|
||||
cached = self._get_cached(plugin_id)
|
||||
if cached is not None:
|
||||
total_width = sum(img.width for img in cached)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Using cached content: %d images, %dpx total",
|
||||
plugin_id, len(cached), total_width
|
||||
)
|
||||
@@ -126,46 +126,46 @@ class PluginAdapter:
|
||||
|
||||
# Try native Vegas content method first
|
||||
has_native = hasattr(plugin, 'get_vegas_content')
|
||||
logger.info("[%s] Has get_vegas_content: %s", plugin_id, has_native)
|
||||
logger.debug("[%s] Has get_vegas_content: %s", plugin_id, has_native)
|
||||
if has_native:
|
||||
content = self._get_native_content(plugin, plugin_id, offscreen_only)
|
||||
if content:
|
||||
total_width = sum(img.width for img in content)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Native content SUCCESS: %d images, %dpx total",
|
||||
plugin_id, len(content), total_width
|
||||
)
|
||||
return self._finalize(content, plugin_id, 'native', plugin)
|
||||
logger.info("[%s] Native content returned None", plugin_id)
|
||||
logger.debug("[%s] Native content returned None", plugin_id)
|
||||
|
||||
# Try to get scroll_helper's cached image (for scrolling plugins like stocks/odds)
|
||||
has_scroll_helper = hasattr(plugin, 'scroll_helper')
|
||||
logger.info("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper)
|
||||
logger.debug("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper)
|
||||
content = self._get_scroll_helper_content(plugin, plugin_id, offscreen_only)
|
||||
if content:
|
||||
total_width = sum(img.width for img in content)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] ScrollHelper content SUCCESS: %d images, %dpx total",
|
||||
plugin_id, len(content), total_width
|
||||
)
|
||||
return self._finalize(content, plugin_id, 'scroll_helper', plugin)
|
||||
if has_scroll_helper:
|
||||
logger.info("[%s] ScrollHelper content returned None", plugin_id)
|
||||
logger.debug("[%s] ScrollHelper content returned None", plugin_id)
|
||||
|
||||
if offscreen_only:
|
||||
# Display capture needs the shared canvas; leave it to the caller.
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Needs display capture, deferring to the render thread",
|
||||
plugin_id
|
||||
)
|
||||
return None
|
||||
|
||||
# Fall back to display capture
|
||||
logger.info("[%s] Trying fallback display capture...", plugin_id)
|
||||
logger.debug("[%s] Trying fallback display capture...", plugin_id)
|
||||
content = self._capture_display_content(plugin, plugin_id)
|
||||
if content:
|
||||
total_width = sum(img.width for img in content)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Fallback capture SUCCESS: %d images, %dpx total",
|
||||
plugin_id, len(content), total_width
|
||||
)
|
||||
@@ -226,7 +226,7 @@ class PluginAdapter:
|
||||
kept.append(result.image)
|
||||
|
||||
if not kept:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] All %d image(s) from %s were blank — contributing nothing",
|
||||
plugin_id, len(images), source
|
||||
)
|
||||
@@ -235,14 +235,14 @@ class PluginAdapter:
|
||||
trimmed_width = sum(img.width for img in kept)
|
||||
|
||||
if trimmed_width < self.config.min_plugin_width:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping",
|
||||
plugin_id, trimmed_width, self.config.min_plugin_width
|
||||
)
|
||||
return None
|
||||
|
||||
if trimmed_width != original_width or dropped_blank:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), "
|
||||
"%d image(s) kept, %d blank dropped",
|
||||
plugin_id, source, original_width, trimmed_width,
|
||||
@@ -431,7 +431,7 @@ class PluginAdapter:
|
||||
"""
|
||||
if self._offset_shapes.get(plugin_id) != shape:
|
||||
if plugin_id in self._item_offsets:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Content is %s now, was %s — restarting the rotation "
|
||||
"rather than resuming at a position that no longer means "
|
||||
"anything", plugin_id, shape,
|
||||
@@ -579,7 +579,7 @@ class PluginAdapter:
|
||||
consumed += 1
|
||||
|
||||
if mode == 'truncate':
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Width budget %dpx: showing the first %d of %d row(s) "
|
||||
"(%dpx incl. gaps); the rest are not shown (overflow=truncate)",
|
||||
plugin_id, budget, len(selected), len(images), used
|
||||
@@ -587,7 +587,7 @@ class PluginAdapter:
|
||||
else:
|
||||
self._record_offset(
|
||||
plugin_id, (start + consumed) % len(images), shape)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) "
|
||||
"from offset %d; remainder deferred to a later cycle",
|
||||
plugin_id, budget, len(selected), len(images), used, start
|
||||
@@ -636,7 +636,7 @@ class PluginAdapter:
|
||||
if mode != 'truncate':
|
||||
self._record_offset(
|
||||
plugin_id, 0 if end >= img.width else end, shape)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Width budget %dpx: cropped continuous %dpx image to "
|
||||
"[%d:%d] (no item gaps of %dpx+ to align to)%s",
|
||||
plugin_id, budget, img.width, offset, end, min_run,
|
||||
@@ -674,7 +674,7 @@ class PluginAdapter:
|
||||
self._record_offset(
|
||||
plugin_id, 0 if end >= img.width else end_index, shape)
|
||||
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Width budget %dpx: cropped single %dpx image to [%d:%d] "
|
||||
"(%dpx) at item boundaries %d-%d of %d, %s",
|
||||
plugin_id, budget, img.width, start, end, end - start,
|
||||
@@ -698,7 +698,7 @@ class PluginAdapter:
|
||||
List of images or None
|
||||
"""
|
||||
try:
|
||||
logger.info("[%s] Native: calling get_vegas_content()", plugin_id)
|
||||
logger.debug("[%s] Native: calling get_vegas_content()", plugin_id)
|
||||
|
||||
# Tell the plugin how much width the ticker wants it to use, and
|
||||
# narrow the canvas for the duration of the call. A plugin that
|
||||
@@ -707,7 +707,7 @@ class PluginAdapter:
|
||||
# be explicit can read get_vegas_render_width().
|
||||
render_width = self.resolve_render_width(plugin, plugin_id)
|
||||
if render_width != self.display_width:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Native: requesting %dpx instead of %dpx",
|
||||
plugin_id, render_width, self.display_width
|
||||
)
|
||||
@@ -735,19 +735,19 @@ class PluginAdapter:
|
||||
plugin._vegas_render_width = None
|
||||
|
||||
if result is None:
|
||||
logger.info("[%s] Native: get_vegas_content() returned None", plugin_id)
|
||||
logger.debug("[%s] Native: get_vegas_content() returned None", plugin_id)
|
||||
return None
|
||||
|
||||
# Normalize to list
|
||||
if isinstance(result, Image.Image):
|
||||
images = [result]
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Native: got single Image %dx%d",
|
||||
plugin_id, result.width, result.height
|
||||
)
|
||||
elif isinstance(result, (list, tuple)):
|
||||
images = list(result)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Native: got %d items in list/tuple",
|
||||
plugin_id, len(images)
|
||||
)
|
||||
@@ -768,14 +768,14 @@ class PluginAdapter:
|
||||
)
|
||||
continue
|
||||
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Native: item[%d] is %dx%d, mode=%s",
|
||||
plugin_id, i, img.width, img.height, img.mode
|
||||
)
|
||||
|
||||
# Ensure correct height
|
||||
if img.height != self.display_height:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Native: resizing item[%d]: %dx%d -> %dx%d",
|
||||
plugin_id, i, img.width, img.height,
|
||||
img.width, self.display_height
|
||||
@@ -793,13 +793,13 @@ class PluginAdapter:
|
||||
|
||||
if valid_images:
|
||||
total_width = sum(img.width for img in valid_images)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Native: SUCCESS - %d images, %dpx total width",
|
||||
plugin_id, len(valid_images), total_width
|
||||
)
|
||||
return valid_images
|
||||
|
||||
logger.info("[%s] Native: no valid images after validation", plugin_id)
|
||||
logger.debug("[%s] Native: no valid images after validation", plugin_id)
|
||||
return None
|
||||
|
||||
except (AttributeError, TypeError, ValueError, OSError) as e:
|
||||
@@ -833,20 +833,20 @@ class PluginAdapter:
|
||||
logger.debug("[%s] No scroll_helper attribute", plugin_id)
|
||||
return None
|
||||
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Found scroll_helper: %s",
|
||||
plugin_id, type(scroll_helper).__name__
|
||||
)
|
||||
|
||||
cached_image = getattr(scroll_helper, 'cached_image', None)
|
||||
if cached_image is None:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] scroll_helper.cached_image is None, triggering content generation",
|
||||
plugin_id
|
||||
)
|
||||
if offscreen_only:
|
||||
# Generating it calls display(), which needs the canvas.
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] scroll_helper cache empty; deferring generation "
|
||||
"to the render thread", plugin_id
|
||||
)
|
||||
@@ -859,13 +859,13 @@ class PluginAdapter:
|
||||
return None
|
||||
|
||||
if not isinstance(cached_image, Image.Image):
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] scroll_helper.cached_image is not an Image: %s",
|
||||
plugin_id, type(cached_image).__name__
|
||||
)
|
||||
return None
|
||||
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] scroll_helper.cached_image found: %dx%d, mode=%s",
|
||||
plugin_id, cached_image.width, cached_image.height, cached_image.mode
|
||||
)
|
||||
@@ -888,7 +888,7 @@ class PluginAdapter:
|
||||
|
||||
# Ensure correct height
|
||||
if img.height != self.display_height:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Resizing scroll_helper content: %dx%d -> %dx%d",
|
||||
plugin_id, img.width, img.height,
|
||||
img.width, self.display_height
|
||||
@@ -902,7 +902,7 @@ class PluginAdapter:
|
||||
if img.mode != 'RGB':
|
||||
img = img.convert('RGB')
|
||||
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] ScrollHelper content ready: %dx%d",
|
||||
plugin_id, img.width, img.height
|
||||
)
|
||||
@@ -1002,7 +1002,7 @@ class PluginAdapter:
|
||||
with self._capture():
|
||||
# Method 1: Try _create_scrolling_display (stocks pattern)
|
||||
if hasattr(plugin, '_create_scrolling_display'):
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Triggering via _create_scrolling_display()",
|
||||
plugin_id
|
||||
)
|
||||
@@ -1010,7 +1010,7 @@ class PluginAdapter:
|
||||
plugin._create_scrolling_display()
|
||||
cached_image = getattr(scroll_helper, 'cached_image', None)
|
||||
if cached_image is not None and isinstance(cached_image, Image.Image):
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] _create_scrolling_display() SUCCESS: %dx%d",
|
||||
plugin_id, cached_image.width, cached_image.height
|
||||
)
|
||||
@@ -1022,7 +1022,7 @@ class PluginAdapter:
|
||||
|
||||
# Method 2: Try display(force_clear=True) which typically builds scroll content
|
||||
if hasattr(plugin, 'display'):
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Triggering via display(force_clear=True)",
|
||||
plugin_id
|
||||
)
|
||||
@@ -1031,12 +1031,12 @@ class PluginAdapter:
|
||||
plugin.display(force_clear=True)
|
||||
cached_image = getattr(scroll_helper, 'cached_image', None)
|
||||
if cached_image is not None and isinstance(cached_image, Image.Image):
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] display(force_clear=True) SUCCESS: %dx%d",
|
||||
plugin_id, cached_image.width, cached_image.height
|
||||
)
|
||||
return cached_image
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] display(force_clear=True) did not populate cached_image",
|
||||
plugin_id
|
||||
)
|
||||
@@ -1045,7 +1045,7 @@ class PluginAdapter:
|
||||
"[%s] display(force_clear=True) failed", plugin_id
|
||||
)
|
||||
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Could not trigger scroll content generation",
|
||||
plugin_id
|
||||
)
|
||||
@@ -1077,15 +1077,15 @@ class PluginAdapter:
|
||||
try:
|
||||
# Save current display state
|
||||
original_image = self.display_manager.image.copy()
|
||||
logger.info("[%s] Fallback: saved original display state", plugin_id)
|
||||
logger.debug("[%s] Fallback: saved original display state", plugin_id)
|
||||
|
||||
# Ensure plugin has fresh data before capturing
|
||||
has_update_data = hasattr(plugin, 'update_data')
|
||||
logger.info("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
|
||||
logger.debug("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
|
||||
if has_update_data:
|
||||
try:
|
||||
plugin.update_data()
|
||||
logger.info("[%s] Fallback: update_data() called", plugin_id)
|
||||
logger.debug("[%s] Fallback: update_data() called", plugin_id)
|
||||
except (AttributeError, RuntimeError, OSError):
|
||||
logger.exception("[%s] Fallback: update_data() failed", plugin_id)
|
||||
|
||||
@@ -1097,41 +1097,41 @@ class PluginAdapter:
|
||||
# arrangement rather than one that has to be cropped afterwards.
|
||||
render_width = self.resolve_render_width(plugin, plugin_id)
|
||||
if render_width != self.display_width:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Fallback: rendering at %dpx instead of %dpx",
|
||||
plugin_id, render_width, self.display_width
|
||||
)
|
||||
|
||||
with self._capture(), self._render_at(render_width):
|
||||
self.display_manager.clear()
|
||||
logger.info("[%s] Fallback: display cleared, calling display()", plugin_id)
|
||||
logger.debug("[%s] Fallback: display cleared, calling display()", plugin_id)
|
||||
|
||||
# First try without force_clear (some plugins behave better this way)
|
||||
try:
|
||||
plugin.display()
|
||||
logger.info("[%s] Fallback: display() called successfully", plugin_id)
|
||||
logger.debug("[%s] Fallback: display() called successfully", plugin_id)
|
||||
except TypeError:
|
||||
# Plugin may require force_clear argument
|
||||
logger.info("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id)
|
||||
logger.debug("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id)
|
||||
plugin.display(force_clear=True)
|
||||
|
||||
# Capture the result
|
||||
captured = self.display_manager.image.copy()
|
||||
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Fallback: captured frame %dx%d, mode=%s",
|
||||
plugin_id, captured.width, captured.height, captured.mode
|
||||
)
|
||||
|
||||
# Check if captured image has content (not all black)
|
||||
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)",
|
||||
plugin_id, bright_ratio * 100
|
||||
)
|
||||
|
||||
if is_blank:
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Fallback: first capture blank, retrying with force_clear",
|
||||
plugin_id
|
||||
)
|
||||
@@ -1142,7 +1142,7 @@ class PluginAdapter:
|
||||
captured = self.display_manager.image.copy()
|
||||
|
||||
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Fallback: retry brightness - %.3f%% bright pixels",
|
||||
plugin_id, bright_ratio * 100
|
||||
)
|
||||
@@ -1159,7 +1159,7 @@ class PluginAdapter:
|
||||
if captured.mode != 'RGB':
|
||||
captured = captured.convert('RGB')
|
||||
|
||||
logger.info(
|
||||
logger.debug(
|
||||
"[%s] Fallback: SUCCESS - captured %dx%d",
|
||||
plugin_id, captured.width, captured.height
|
||||
)
|
||||
|
||||
@@ -5,7 +5,7 @@ Provides functions for identifying, masking, separating, and filtering
|
||||
secret fields in plugin configurations based on JSON Schema x-secret markers.
|
||||
"""
|
||||
|
||||
from typing import Any, Dict, Optional, Set, Tuple
|
||||
from typing import Any, Dict, Set, Tuple
|
||||
|
||||
|
||||
def find_secret_fields(properties: Dict[str, Any], prefix: str = '') -> Set[str]:
|
||||
@@ -202,89 +202,11 @@ def remove_empty_secrets(secrets: Dict[str, Any]) -> Dict[str, Any]:
|
||||
nested = remove_empty_secrets(v)
|
||||
if nested:
|
||||
result[k] = nested
|
||||
elif isinstance(v, list):
|
||||
# Lists used to fall through to the scalar branch below and be
|
||||
# kept verbatim, blanks and all. Because lists merge by
|
||||
# *replacement*, saving any unrelated setting then wrote
|
||||
# [{"token": ""}, ...] straight over the stored list and
|
||||
# destroyed every credential in it.
|
||||
pruned = _prune_secret_list(v)
|
||||
if pruned is not None:
|
||||
result[k] = pruned
|
||||
elif v is not None and not (isinstance(v, str) and v.strip() == ''):
|
||||
result[k] = v
|
||||
return result
|
||||
|
||||
|
||||
def _prune_secret_list(items: list) -> Optional[list]:
|
||||
"""Strip blanks from inside a list of secrets, preserving every index.
|
||||
|
||||
The rest of the system treats a secrets list as *parallel* to the regular
|
||||
one -- ``sec[i]`` holds the secret fields of item ``i``, and ``{}`` means
|
||||
"item i has none" (see ConfigManager._strip_secrets_recursive). So an
|
||||
emptied dict item stays ``{}``: putting ``None`` there makes that list stop
|
||||
looking parallel, and the stripper then drops the whole key from the main
|
||||
config, taking the non-secret fields with it.
|
||||
|
||||
A blank *scalar* becomes ``None``, meaning "no update at this index" --
|
||||
:func:`merge_secrets` substitutes whatever is stored there. Returns
|
||||
``None`` when nothing in the list carries a real value, so the caller drops
|
||||
the key and leaves the stored list untouched.
|
||||
"""
|
||||
pruned: list = []
|
||||
has_real_value = False
|
||||
for item in items:
|
||||
if isinstance(item, dict):
|
||||
kept = remove_empty_secrets(item)
|
||||
pruned.append(kept)
|
||||
has_real_value = has_real_value or bool(kept)
|
||||
elif isinstance(item, list):
|
||||
sub = _prune_secret_list(item)
|
||||
pruned.append(sub if sub is not None else [])
|
||||
has_real_value = has_real_value or sub is not None
|
||||
elif item is not None and not (isinstance(item, str) and item.strip() == ''):
|
||||
pruned.append(item)
|
||||
has_real_value = True
|
||||
else:
|
||||
pruned.append(None)
|
||||
return pruned if has_real_value else None
|
||||
|
||||
|
||||
def merge_secrets(stored: Any, incoming: Any) -> Any:
|
||||
"""Merge submitted secrets over stored ones, element-wise inside lists.
|
||||
|
||||
``deep_merge`` replaces a list wholesale. For secrets that is destructive:
|
||||
an incoming list that carries a real value for one entry and ``None`` for
|
||||
the rest would drop the stored credentials of every other entry. Here a
|
||||
list merges by index, and ``None`` means "keep what is stored".
|
||||
|
||||
Entries are matched by *position*, which is what the config form gives us
|
||||
-- there is no schema-declared identity to key on, and it is the same
|
||||
contract ConfigManager._strip_secrets_recursive already relies on. The
|
||||
incoming list's length wins, so deleting an item deletes its secrets;
|
||||
an item the client left blank keeps whatever is stored at that index.
|
||||
"""
|
||||
if isinstance(stored, dict) and isinstance(incoming, dict):
|
||||
merged = dict(stored)
|
||||
for key, value in incoming.items():
|
||||
merged[key] = (merge_secrets(stored[key], value)
|
||||
if key in stored else value)
|
||||
return merged
|
||||
if isinstance(stored, list) and isinstance(incoming, list):
|
||||
# The incoming list sets the length -- the regular config's list is
|
||||
# authoritative about how many items exist, and this one runs parallel
|
||||
# to it. Removing an entry must therefore remove its secrets too.
|
||||
merged_list = []
|
||||
for index, item in enumerate(incoming):
|
||||
stored_item = stored[index] if index < len(stored) else None
|
||||
merged_list.append(stored_item if item is None
|
||||
else merge_secrets(stored_item, item))
|
||||
return merged_list
|
||||
if incoming is None:
|
||||
return stored
|
||||
return incoming
|
||||
|
||||
|
||||
def strip_masked_values(secrets: Dict[str, Any]) -> Dict[str, Any]:
|
||||
"""Remove values a client echoed back rather than changed.
|
||||
|
||||
|
||||
@@ -0,0 +1,119 @@
|
||||
"""A healthy plugin must not rewrite its health record every cycle.
|
||||
|
||||
Every successful plugin update called record_success(), which persisted the
|
||||
record unconditionally. In steady state the only fields that had changed were
|
||||
total_successes and last_success_time -- a counter and a timestamp that
|
||||
health_monitor reads for display and that nothing reads back after a restart.
|
||||
|
||||
Measured on a rig running 24 plugins: about 17 health-file rewrites a minute,
|
||||
roughly 25,000 a day. Each is ~400 bytes, but they land on an SD card where
|
||||
the unit of cost is an erase-block cycle, not the byte count, and where wear is
|
||||
what eventually kills the card.
|
||||
|
||||
The circuit breaker still needs its own state to survive a restart, so the
|
||||
write is kept for exactly the fields it is rebuilt from -- and a failure, a
|
||||
circuit opening, or a recovery must still be written the moment it happens.
|
||||
"""
|
||||
import time
|
||||
|
||||
import copy
|
||||
|
||||
import pytest
|
||||
|
||||
from src.plugin_system.plugin_health import PluginHealthTracker, CircuitState
|
||||
|
||||
|
||||
class _Cache:
|
||||
"""Counts writes; serves back whatever was last written.
|
||||
|
||||
Both directions deep-copy, so this behaves like a real cache that
|
||||
serialises through a file. Storing by reference let the tracker keep
|
||||
mutating the object already in the store, so a record could appear to
|
||||
have been persisted when no write ever happened -- which is precisely
|
||||
what test_durable_state_survives_a_restart is supposed to detect.
|
||||
"""
|
||||
|
||||
def __init__(self):
|
||||
self.store = {}
|
||||
self.writes = 0
|
||||
|
||||
def set(self, key, data, ttl=None, **kwargs):
|
||||
self.writes += 1
|
||||
self.store[key] = copy.deepcopy(data)
|
||||
|
||||
def get(self, key, max_age=None, memory_ttl=None, **kwargs):
|
||||
return copy.deepcopy(self.store.get(key))
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def tracker():
|
||||
cache = _Cache()
|
||||
t = PluginHealthTracker(cache_manager=cache)
|
||||
return t, cache
|
||||
|
||||
|
||||
def test_steady_state_success_stops_writing(tracker):
|
||||
"""The regression: 100 healthy cycles used to be 100 SD writes."""
|
||||
t, cache = tracker
|
||||
t.record_success("weather")
|
||||
first = cache.writes
|
||||
for _ in range(100):
|
||||
t.record_success("weather")
|
||||
assert cache.writes == first, (
|
||||
f"{cache.writes - first} redundant writes across 100 healthy cycles"
|
||||
)
|
||||
|
||||
|
||||
def test_the_counters_are_still_accurate_in_memory(tracker):
|
||||
"""Skipping the write must not skip the bookkeeping."""
|
||||
t, _ = tracker
|
||||
for _ in range(10):
|
||||
t.record_success("weather")
|
||||
state = t.get_health_state("weather")
|
||||
assert state["total_successes"] == 10
|
||||
assert state["last_success_time"] is not None
|
||||
assert state["last_success_time"] <= time.time()
|
||||
|
||||
|
||||
def test_a_failure_is_written_immediately(tracker):
|
||||
t, cache = tracker
|
||||
t.record_success("weather")
|
||||
before = cache.writes
|
||||
t.record_failure("weather", RuntimeError("boom"))
|
||||
assert cache.writes > before, "a failure must reach disk"
|
||||
|
||||
|
||||
def test_recovery_after_failure_is_written(tracker):
|
||||
"""consecutive_failures returning to 0 is durable state changing."""
|
||||
t, cache = tracker
|
||||
t.record_failure("weather", RuntimeError("boom"))
|
||||
before = cache.writes
|
||||
t.record_success("weather")
|
||||
assert cache.writes > before, "recovery must reach disk"
|
||||
assert t.get_health_state("weather")["consecutive_failures"] == 0
|
||||
|
||||
|
||||
def test_a_closing_circuit_is_written(tracker):
|
||||
"""Success in half-open closes the circuit -- that must survive a restart."""
|
||||
t, cache = tracker
|
||||
state = t.get_health_state("weather")
|
||||
state["circuit_state"] = CircuitState.HALF_OPEN.value
|
||||
state["half_open_start_time"] = time.time()
|
||||
before = cache.writes
|
||||
t.record_success("weather")
|
||||
assert cache.writes > before, "a circuit transition must reach disk"
|
||||
assert t.get_health_state("weather")["circuit_state"] == CircuitState.CLOSED.value
|
||||
|
||||
|
||||
def test_durable_state_survives_a_restart(tracker):
|
||||
"""What is skipped must genuinely not matter to the breaker."""
|
||||
t, cache = tracker
|
||||
for _ in range(3):
|
||||
t.record_failure("weather", RuntimeError("boom"))
|
||||
for _ in range(50):
|
||||
t.record_success("weather")
|
||||
|
||||
revived = PluginHealthTracker(cache_manager=cache)
|
||||
state = revived.get_health_state("weather")
|
||||
assert state["consecutive_failures"] == 0
|
||||
assert state["circuit_state"] == CircuitState.CLOSED.value
|
||||
@@ -0,0 +1,137 @@
|
||||
"""Log lines must reach the journal with their real severity.
|
||||
|
||||
Everything this process writes to stdout lands in the journal as PRIORITY=6,
|
||||
whatever the Python level was, because journald has no other signal. Measured
|
||||
on a live rig over 24 hours: 55 lines containing " - ERROR - " and 13
|
||||
containing " - WARNING - ", every one of them recorded as informational. So
|
||||
|
||||
journalctl -p err -u ledmatrix
|
||||
|
||||
returned nothing while errors were being logged, and anyone triaging has to
|
||||
grep the message text instead. That is slower and it is wrong: a search for
|
||||
"oom" also matches the radar logging "zoom=9", which is exactly the false
|
||||
positive it produced during this audit.
|
||||
|
||||
systemd reads a leading "<N>" on each stdout line and uses it as the priority
|
||||
(sd-daemon(3)), so this needs no extra dependency -- and it must only be
|
||||
applied when systemd is actually reading, or the prefixes become literal noise
|
||||
in a terminal, the emulator, and test output.
|
||||
"""
|
||||
import logging
|
||||
import os
|
||||
import sys
|
||||
from unittest.mock import patch
|
||||
|
||||
import pytest
|
||||
|
||||
from src.logging_config import JournalPriorityFormatter, _SYSLOG_PRIORITY, _under_systemd
|
||||
|
||||
|
||||
class _Plain(logging.Formatter):
|
||||
def format(self, record):
|
||||
return record.getMessage()
|
||||
|
||||
|
||||
def _record(level, msg="hello"):
|
||||
return logging.LogRecord("t", level, "f.py", 1, msg, None, None)
|
||||
|
||||
|
||||
@pytest.mark.parametrize("level,expected", [
|
||||
(logging.CRITICAL, 2),
|
||||
(logging.ERROR, 3),
|
||||
(logging.WARNING, 4),
|
||||
(logging.INFO, 6),
|
||||
(logging.DEBUG, 7),
|
||||
])
|
||||
def test_each_level_maps_to_its_syslog_priority(level, expected):
|
||||
out = JournalPriorityFormatter(_Plain()).format(_record(level))
|
||||
assert out.startswith(f"<{expected}>"), out
|
||||
assert _SYSLOG_PRIORITY[level] == expected
|
||||
|
||||
|
||||
def test_error_and_info_are_distinguishable():
|
||||
"""The whole point: journalctl -p err must be able to tell them apart."""
|
||||
fmt = JournalPriorityFormatter(_Plain())
|
||||
assert fmt.format(_record(logging.ERROR))[:3] != fmt.format(_record(logging.INFO))[:3]
|
||||
|
||||
|
||||
def test_every_line_of_a_multiline_record_is_tagged():
|
||||
"""The journal splits them, and an untagged continuation loses its level.
|
||||
|
||||
A traceback is the case that matters -- it is the most important thing in
|
||||
the log and the longest.
|
||||
"""
|
||||
out = JournalPriorityFormatter(_Plain()).format(
|
||||
_record(logging.ERROR, "Traceback:\nline one\nline two"))
|
||||
lines = out.split("\n")
|
||||
assert len(lines) == 3
|
||||
assert all(line.startswith("<3>") for line in lines), lines
|
||||
|
||||
|
||||
def test_the_message_survives_intact():
|
||||
out = JournalPriorityFormatter(_Plain()).format(_record(logging.WARNING, "disk full"))
|
||||
assert out == "<4>disk full"
|
||||
|
||||
|
||||
def test_an_unknown_level_falls_back_to_info():
|
||||
out = JournalPriorityFormatter(_Plain()).format(_record(25))
|
||||
assert out.startswith("<6>")
|
||||
|
||||
|
||||
def _stdout_ids():
|
||||
"""The dev:ino systemd would publish for this process's stdout."""
|
||||
st = os.fstat(sys.stdout.fileno())
|
||||
return f"{st.st_dev}:{st.st_ino}"
|
||||
|
||||
|
||||
def test_prefixing_is_off_outside_systemd():
|
||||
"""Otherwise a terminal run, the emulator and pytest all show `<6>`."""
|
||||
with patch.dict(os.environ, {}, clear=True):
|
||||
assert not _under_systemd()
|
||||
with patch.dict(os.environ, {"JOURNAL_STREAM": _stdout_ids()}):
|
||||
assert _under_systemd()
|
||||
|
||||
|
||||
def test_an_inherited_journal_stream_does_not_count():
|
||||
"""The variable outlives the descriptor it describes.
|
||||
|
||||
systemd sets JOURNAL_STREAM for the service, and every child inherits it
|
||||
-- including one whose stdout has been redirected to a pipe or a file.
|
||||
Trusting the variable alone put literal "<6>" prefixes into that captured
|
||||
output. Only a descriptor whose dev:ino actually matches is the journal.
|
||||
"""
|
||||
with patch.dict(os.environ, {"JOURNAL_STREAM": "8:12345"}):
|
||||
assert not _under_systemd(), \
|
||||
"a stale inherited JOURNAL_STREAM was treated as the journal"
|
||||
|
||||
|
||||
@pytest.mark.parametrize("value", ["", "not-a-pair", "8", "8:", ":12345",
|
||||
"eight:12345", "8:12345:9"])
|
||||
def test_a_malformed_journal_stream_is_not_the_journal(value):
|
||||
with patch.dict(os.environ, {"JOURNAL_STREAM": value}):
|
||||
assert not _under_systemd()
|
||||
|
||||
|
||||
def test_a_closed_stdout_is_not_the_journal():
|
||||
"""os.fstat raises rather than answers; that must not propagate."""
|
||||
with patch.dict(os.environ, {"JOURNAL_STREAM": "8:12345"}), \
|
||||
patch("src.logging_config.sys.stdout") as fake_stdout:
|
||||
fake_stdout.fileno.side_effect = ValueError("I/O operation on closed file")
|
||||
assert not _under_systemd()
|
||||
|
||||
|
||||
def test_setup_uses_the_wrapper_only_under_systemd():
|
||||
from src.logging_config import setup_logging
|
||||
|
||||
for env, expect_wrapped in (({}, False),
|
||||
({"JOURNAL_STREAM": _stdout_ids()}, True)):
|
||||
with patch.dict(os.environ, env, clear=True):
|
||||
setup_logging()
|
||||
handlers = [h for h in logging.getLogger().handlers
|
||||
if isinstance(h, logging.StreamHandler)]
|
||||
assert handlers, "no stream handler installed"
|
||||
wrapped = any(isinstance(h.formatter, JournalPriorityFormatter)
|
||||
for h in handlers)
|
||||
assert wrapped is expect_wrapped, (
|
||||
f"JOURNAL_STREAM={env}: wrapped={wrapped}, expected {expect_wrapped}")
|
||||
logging.getLogger().handlers.clear()
|
||||
@@ -183,15 +183,27 @@ class TestSetupLogging:
|
||||
setup_logging()
|
||||
assert len(logging.getLogger().handlers) == 1
|
||||
|
||||
@staticmethod
|
||||
def _selected_formatter():
|
||||
"""The formatter setup_logging() chose, past any journald wrapper.
|
||||
|
||||
Under systemd the console handler's formatter is wrapped so each line
|
||||
carries its syslog priority. That wrapper is applied only when
|
||||
JOURNAL_STREAM is set, which is true in CI and false in a terminal, so
|
||||
asserting on the handler's formatter directly passes locally and fails
|
||||
on the runner. These tests are about which formatter format_type
|
||||
selects, so they look through the wrapper.
|
||||
"""
|
||||
formatter = logging.getLogger().handlers[0].formatter
|
||||
return getattr(formatter, "inner", formatter)
|
||||
|
||||
def test_json_format_selects_structured_formatter(self):
|
||||
setup_logging(format_type="json")
|
||||
assert isinstance(
|
||||
logging.getLogger().handlers[0].formatter, StructuredFormatter)
|
||||
assert isinstance(self._selected_formatter(), StructuredFormatter)
|
||||
|
||||
def test_readable_format_selects_contextual_formatter(self):
|
||||
setup_logging(format_type="readable")
|
||||
assert isinstance(
|
||||
logging.getLogger().handlers[0].formatter, ContextualFormatter)
|
||||
assert isinstance(self._selected_formatter(), ContextualFormatter)
|
||||
|
||||
def test_log_file_adds_file_handler(self, tmp_path):
|
||||
log_file = tmp_path / "test.log"
|
||||
|
||||
@@ -0,0 +1,128 @@
|
||||
"""A malformed metrics cache entry must not take every plugin down with it.
|
||||
|
||||
`ResourceMetrics(**cached)` raises TypeError on a single unexpected key, and
|
||||
that exception escapes into plugin_manager, which reports it per plugin as
|
||||
"plugin <id> operation failed". Every plugin fails and the plugin system never
|
||||
finishes initialising -- the health endpoint reports
|
||||
`plugin_system: not_initialized` while the display itself keeps running.
|
||||
|
||||
Seen on a live rig, once per plugin, continuously:
|
||||
|
||||
ERROR - src.plugin_system.plugin_manager - plugin geochron operation failed:
|
||||
ResourceMetrics.__init__() got an unexpected keyword argument
|
||||
'consecutive_failures'
|
||||
|
||||
`consecutive_failures` belongs to plugin_health, not to metrics. How a
|
||||
health-shaped record came to sit under a plugin_metrics key on that machine is
|
||||
not established -- a restored backup that mixed two machines' caches is the
|
||||
likeliest explanation, and the same rig had one restored onto it -- but a
|
||||
loader that turns one bad cache entry into a total outage is the part worth
|
||||
fixing. plugin_health already repairs its own records field by field rather
|
||||
than trusting what is on disk.
|
||||
"""
|
||||
import logging
|
||||
from dataclasses import fields
|
||||
from unittest.mock import MagicMock
|
||||
|
||||
import pytest
|
||||
|
||||
from src.plugin_system.resource_monitor import PluginResourceMonitor, ResourceMetrics
|
||||
|
||||
|
||||
class _Cache:
|
||||
def __init__(self, payload=None):
|
||||
self.payload = payload
|
||||
|
||||
def get(self, key, max_age=None, memory_ttl=None, **kwargs):
|
||||
return self.payload
|
||||
|
||||
def set(self, key, data, ttl=None, **kwargs):
|
||||
pass
|
||||
|
||||
|
||||
def _monitor(payload):
|
||||
m = PluginResourceMonitor(cache_manager=_Cache(payload))
|
||||
m.logger = logging.getLogger("test")
|
||||
return m
|
||||
|
||||
|
||||
#: What the rig actually had under the metrics key.
|
||||
HEALTH_SHAPED = {
|
||||
"consecutive_failures": 0, "circuit_state": "closed",
|
||||
"circuit_opened_time": None, "half_open_start_time": None,
|
||||
"last_error": None, "last_failure_time": None,
|
||||
"last_success_time": 1_700_000_000.0, "total_failures": 0,
|
||||
"total_successes": 42,
|
||||
}
|
||||
|
||||
|
||||
def test_a_health_record_under_the_metrics_key_does_not_raise():
|
||||
"""The exact failure: it must degrade, not take the plugin system down."""
|
||||
monitor = _monitor(HEALTH_SHAPED)
|
||||
metrics = monitor.get_metrics(" plugin-a".strip())
|
||||
assert isinstance(metrics, ResourceMetrics)
|
||||
|
||||
|
||||
def test_recognised_fields_in_a_mixed_record_are_kept():
|
||||
"""Dropping the record wholesale would lose real history unnecessarily."""
|
||||
mixed = dict(HEALTH_SHAPED, call_count=7, memory_mb=12.5)
|
||||
metrics = _monitor(mixed).get_metrics("plugin-b")
|
||||
assert metrics.call_count == 7
|
||||
assert metrics.memory_mb == 12.5
|
||||
|
||||
|
||||
def test_a_clean_record_still_loads_unchanged():
|
||||
clean = {f.name: 3 for f in fields(ResourceMetrics)}
|
||||
metrics = _monitor(clean).get_metrics("plugin-c")
|
||||
for name in (f.name for f in fields(ResourceMetrics)):
|
||||
assert getattr(metrics, name) == 3
|
||||
|
||||
|
||||
def test_unknown_fields_are_named_in_the_log(caplog):
|
||||
"""Silently discarding them would hide a real schema change."""
|
||||
with caplog.at_level(logging.WARNING):
|
||||
_monitor(HEALTH_SHAPED).get_metrics("plugin-d")
|
||||
# getMessage(), not .message: the latter is only populated once a handler
|
||||
# formats the record, so the obvious spelling silently never matches.
|
||||
assert any("consecutive_failures" in r.getMessage() for r in caplog.records), \
|
||||
caplog.text
|
||||
|
||||
|
||||
@pytest.mark.parametrize("payload", ["a string", 42, ["a", "list"]])
|
||||
def test_a_non_mapping_cache_entry_does_not_raise(payload):
|
||||
metrics = _monitor(payload).get_metrics("plugin-e")
|
||||
assert isinstance(metrics, ResourceMetrics)
|
||||
|
||||
|
||||
@pytest.mark.parametrize("bad", [
|
||||
{"call_count": "not a number"},
|
||||
{"memory_mb": None},
|
||||
{"execution_time": {"nested": "junk"}},
|
||||
{"min_execution_time": ["a", "list"]},
|
||||
])
|
||||
def test_values_of_the_wrong_type_fall_back_to_usable_defaults(bad):
|
||||
"""isinstance() alone was not enough.
|
||||
|
||||
A dataclass does not enforce its annotations, so the bad value was simply
|
||||
stored and the old assertion passed -- then monitor_call() raised
|
||||
"can only concatenate str (not \"int\") to str" on the next call. The
|
||||
metrics must come back *usable*, not merely constructed.
|
||||
"""
|
||||
monitor = _monitor(bad)
|
||||
metrics = monitor.get_metrics("plugin-f")
|
||||
assert isinstance(metrics, ResourceMetrics)
|
||||
|
||||
field_name = next(iter(bad))
|
||||
assert isinstance(getattr(metrics, field_name), (int, float)), \
|
||||
f"{field_name} came back as {getattr(metrics, field_name)!r}"
|
||||
|
||||
# The real proof: arithmetic on the loaded metrics must not explode.
|
||||
metrics.call_count += 1
|
||||
metrics.total_execution_time += 0.5
|
||||
metrics.update_average_execution_time()
|
||||
|
||||
|
||||
def test_a_numeric_string_is_accepted_rather_than_discarded():
|
||||
"""JSON round-trips can widen an int to a string; that is recoverable."""
|
||||
metrics = _monitor({"call_count": "7"}).get_metrics("plugin-g")
|
||||
assert metrics.call_count == 7
|
||||
@@ -0,0 +1,126 @@
|
||||
#!/usr/bin/env python3
|
||||
"""Discovery must say when it skips a directory.
|
||||
|
||||
A plugin can be enabled in config, enabled in plugin state, present on disk
|
||||
with a valid entry point -- and simply absent from the running process, with
|
||||
nothing in the journal to say why. Working that out afterwards meant comparing
|
||||
cache-file mtimes to find when it had last run.
|
||||
|
||||
Two paths were silent. A directory with no manifest.json was ignored, and --
|
||||
quieter still -- a manifest that parsed but carried no "id" was read
|
||||
successfully and then dropped on the floor.
|
||||
"""
|
||||
import json
|
||||
import logging
|
||||
import sys
|
||||
from pathlib import Path
|
||||
from unittest.mock import MagicMock
|
||||
|
||||
import pytest
|
||||
|
||||
sys.path.insert(0, str(Path(__file__).resolve().parent.parent))
|
||||
|
||||
from src.plugin_system.plugin_manager import PluginManager # noqa: E402
|
||||
|
||||
|
||||
def _manager(tmp_path):
|
||||
pm = PluginManager.__new__(PluginManager)
|
||||
pm.plugins_dir = tmp_path
|
||||
pm.logger = logging.getLogger("test.discovery")
|
||||
pm.plugin_manifests = {}
|
||||
pm.plugin_directories = {}
|
||||
pm._discovery_lock = __import__("threading").RLock()
|
||||
pm._skip_reported = set()
|
||||
pm.schema_manager = MagicMock()
|
||||
return pm
|
||||
|
||||
|
||||
def test_a_directory_without_a_manifest_is_reported(tmp_path, caplog):
|
||||
(tmp_path / "not-a-plugin").mkdir()
|
||||
pm = _manager(tmp_path)
|
||||
with caplog.at_level(logging.WARNING, logger="test.discovery"):
|
||||
pm._scan_directory_for_plugins(tmp_path)
|
||||
joined = " ".join(r.message for r in caplog.records)
|
||||
assert "not-a-plugin" in joined and "manifest" in joined, (
|
||||
f"skip was silent; log said: {joined!r}")
|
||||
|
||||
|
||||
def test_a_manifest_without_an_id_is_reported(tmp_path, caplog):
|
||||
d = tmp_path / "idless"
|
||||
d.mkdir()
|
||||
(d / "manifest.json").write_text(json.dumps({"name": "No Id", "version": "1.0.0"}))
|
||||
pm = _manager(tmp_path)
|
||||
with caplog.at_level(logging.WARNING, logger="test.discovery"):
|
||||
pm._scan_directory_for_plugins(tmp_path)
|
||||
joined = " ".join(r.message for r in caplog.records)
|
||||
assert "idless" in joined and "id" in joined, (
|
||||
f"a parsed-but-unusable manifest vanished silently; log said: {joined!r}")
|
||||
|
||||
|
||||
def test_a_good_plugin_still_registers(tmp_path, caplog):
|
||||
d = tmp_path / "real-plugin"
|
||||
d.mkdir()
|
||||
(d / "manifest.json").write_text(json.dumps(
|
||||
{"id": "real-plugin", "name": "Real", "version": "1.0.0"}))
|
||||
pm = _manager(tmp_path)
|
||||
pm._scan_directory_for_plugins(tmp_path)
|
||||
assert "real-plugin" in pm.plugin_manifests, "a valid plugin was not registered"
|
||||
|
||||
|
||||
def test_the_warning_does_not_repeat_on_every_scan(tmp_path, caplog):
|
||||
"""Discovery runs on every web UI page load and every config reconcile.
|
||||
|
||||
Warning unconditionally would put a line in the journal each time someone
|
||||
opened a page -- the same log-volume problem this is meant to help
|
||||
diagnose.
|
||||
"""
|
||||
(tmp_path / "not-a-plugin").mkdir()
|
||||
pm = _manager(tmp_path)
|
||||
with caplog.at_level(logging.WARNING, logger="test.discovery"):
|
||||
for _ in range(5):
|
||||
pm._scan_directory_for_plugins(tmp_path)
|
||||
hits = [r for r in caplog.records if "not-a-plugin" in r.message]
|
||||
assert len(hits) == 1, f"warned {len(hits)} times across 5 scans"
|
||||
|
||||
|
||||
def _plugin(tmp_path, name, body):
|
||||
d = tmp_path / name
|
||||
d.mkdir()
|
||||
(d / "manifest.json").write_text(json.dumps(body))
|
||||
return d
|
||||
|
||||
|
||||
VALID = {"name": "V", "version": "1.0.0", "class_name": "X", "display_modes": ["m"]}
|
||||
|
||||
|
||||
@pytest.mark.parametrize("body", [None, [1, 2], "not an object", 42, True])
|
||||
def test_a_manifest_that_is_not_an_object_is_skipped_not_fatal(tmp_path, caplog, body):
|
||||
"""json.load accepts any JSON value, not just objects.
|
||||
|
||||
manifest.get('id') then raised AttributeError, which nothing here caught --
|
||||
the outer handler takes OSError/PermissionError only. A single malformed
|
||||
manifest aborted the entire scan, so every other plugin on disk, however
|
||||
healthy, silently failed to register.
|
||||
"""
|
||||
_plugin(tmp_path, "aaa-good", dict(VALID, id="aaa-good"))
|
||||
_plugin(tmp_path, "mmm-bad", body)
|
||||
_plugin(tmp_path, "zzz-good", dict(VALID, id="zzz-good"))
|
||||
|
||||
pm = _manager(tmp_path)
|
||||
with caplog.at_level(logging.WARNING, logger="test.discovery"):
|
||||
found = pm._scan_directory_for_plugins(tmp_path)
|
||||
|
||||
assert sorted(found) == ["aaa-good", "zzz-good"], (
|
||||
"one unusable manifest took the healthy plugins down with it")
|
||||
joined = " ".join(r.message for r in caplog.records)
|
||||
assert "mmm-bad" in joined, f"the skip was silent; log said: {joined!r}"
|
||||
|
||||
|
||||
def test_the_bad_manifest_is_named_with_what_it_actually_was(tmp_path, caplog):
|
||||
_plugin(tmp_path, "listy", [1, 2])
|
||||
pm = _manager(tmp_path)
|
||||
with caplog.at_level(logging.WARNING, logger="test.discovery"):
|
||||
pm._scan_directory_for_plugins(tmp_path)
|
||||
joined = " ".join(r.message for r in caplog.records)
|
||||
assert "listy" in joined and "list" in joined, (
|
||||
f"the warning does not say what the manifest was: {joined!r}")
|
||||
@@ -11,7 +11,7 @@ Focus areas:
|
||||
import time
|
||||
|
||||
import pytest
|
||||
from unittest.mock import MagicMock
|
||||
from unittest.mock import MagicMock, patch
|
||||
|
||||
from src.plugin_system.resource_monitor import (
|
||||
PluginResourceMonitor,
|
||||
@@ -127,3 +127,87 @@ class TestForceReload:
|
||||
fresh = mon.get_metrics_summary("p", force_reload=True)
|
||||
assert fresh["call_count"] == 7
|
||||
assert any(c.kwargs.get("memory_ttl") == 0 for c in cache.get.call_args_list)
|
||||
|
||||
|
||||
class TestMetricsPersistenceChurn:
|
||||
"""Metrics are telemetry; writing them on every call wore the SD card.
|
||||
|
||||
Each write is a ~350-byte file, which on ext4 costs a 4KB block plus a
|
||||
journal entry. At roughly nine calls a minute per plugin across fourteen
|
||||
plugins it dominated the device's write volume.
|
||||
"""
|
||||
|
||||
def test_the_first_snapshot_is_written_even_seconds_after_boot(self):
|
||||
"""The throttle must key off "have we written?", not process uptime.
|
||||
|
||||
time.monotonic() is time since boot on Linux, and systemd starts this
|
||||
service at boot. With 0.0 as the missing-timestamp default,
|
||||
`now - 0.0 < 30` was true for the first half-minute of every run, so
|
||||
the very first metrics write -- the one that matters most after a
|
||||
restart -- was silently skipped.
|
||||
"""
|
||||
import src.plugin_system.resource_monitor as rm
|
||||
cache = _cache()
|
||||
mon = PluginResourceMonitor(cache, enable_monitoring=False)
|
||||
# 12 seconds after boot: inside the interval, but nothing written yet.
|
||||
with patch.object(rm.time, "monotonic", return_value=12.0):
|
||||
mon.monitor_call("p", lambda: None)
|
||||
writes = [c for c in cache.set.call_args_list
|
||||
if "plugin_metrics:" in str(c)]
|
||||
assert writes, \
|
||||
"the first snapshot was dropped because the process was young"
|
||||
|
||||
def test_repeated_calls_persist_once_per_interval(self):
|
||||
cache = _cache()
|
||||
mon = PluginResourceMonitor(cache, enable_monitoring=False)
|
||||
for _ in range(50):
|
||||
mon.monitor_call("p", lambda: None)
|
||||
writes = [c for c in cache.set.call_args_list
|
||||
if c.args and str(c.args[0]).startswith("plugin_metrics:")]
|
||||
assert len(writes) == 1, (
|
||||
f"50 calls produced {len(writes)} metric writes; expected 1")
|
||||
|
||||
def test_the_interval_elapsing_allows_the_next_write(self, monkeypatch):
|
||||
import src.plugin_system.resource_monitor as rm
|
||||
cache = _cache()
|
||||
mon = PluginResourceMonitor(cache, enable_monitoring=False)
|
||||
mon.monitor_call("p", lambda: None)
|
||||
# pretend the interval has passed
|
||||
mon._metrics_persisted_at["p"] -= rm._METRICS_PERSIST_INTERVAL + 1
|
||||
mon.monitor_call("p", lambda: None)
|
||||
writes = [c for c in cache.set.call_args_list
|
||||
if c.args and str(c.args[0]).startswith("plugin_metrics:")]
|
||||
assert len(writes) == 2
|
||||
|
||||
def test_in_memory_metrics_stay_exact_while_writes_are_skipped(self):
|
||||
mon = PluginResourceMonitor(_cache(), enable_monitoring=False)
|
||||
for _ in range(20):
|
||||
mon.monitor_call("p", lambda: None)
|
||||
assert mon.get_metrics("p").call_count == 20
|
||||
|
||||
def test_reset_lets_the_next_call_persist_immediately(self):
|
||||
cache = _cache()
|
||||
mon = PluginResourceMonitor(cache, enable_monitoring=False)
|
||||
mon.monitor_call("p", lambda: None)
|
||||
mon.reset_metrics("p")
|
||||
mon.monitor_call("p", lambda: None)
|
||||
writes = [c for c in cache.set.call_args_list
|
||||
if c.args and str(c.args[0]).startswith("plugin_metrics:")]
|
||||
assert len(writes) == 2, "reset should clear the throttle timestamp"
|
||||
|
||||
def test_a_failed_write_does_not_buy_the_next_interval_of_silence(self):
|
||||
"""A set() that raises must not count as having persisted.
|
||||
|
||||
Marking the timestamp before the write would leave no snapshot in the
|
||||
cache and still suppress the next 30 seconds of attempts.
|
||||
"""
|
||||
cache = _cache()
|
||||
cache.set.side_effect = [OSError("disk full"), None]
|
||||
mon = PluginResourceMonitor(cache, enable_monitoring=False)
|
||||
with pytest.raises(OSError):
|
||||
mon.monitor_call("p", lambda: None)
|
||||
# the very next call must try again rather than skip the interval
|
||||
mon.monitor_call("p", lambda: None)
|
||||
writes = [c for c in cache.set.call_args_list
|
||||
if c.args and str(c.args[0]).startswith("plugin_metrics:")]
|
||||
assert len(writes) == 2, "a failed write should be retried, not skipped"
|
||||
|
||||
@@ -0,0 +1,179 @@
|
||||
"""
|
||||
Tests for the device-location default: a plugin that ships a location field in
|
||||
its schema must default to the device's configured City/State/Country, not to
|
||||
whatever place the plugin author hard-coded.
|
||||
|
||||
The bug this pins: ledmatrix-weather ships ``"location_city": "Dallas"`` as a
|
||||
schema default, so a user who set Kansas City under General settings but never
|
||||
opened the weather plugin's own config form got Dallas weather — and a radar
|
||||
centred on Dallas — with nothing in config.json to explain it.
|
||||
"""
|
||||
|
||||
import json
|
||||
|
||||
import pytest
|
||||
|
||||
from src.plugin_system.schema_manager import SchemaManager
|
||||
|
||||
|
||||
class FakeConfigManager:
|
||||
"""Minimal stand-in exposing the load_config() SchemaManager relies on."""
|
||||
|
||||
def __init__(self, config):
|
||||
self.config = config
|
||||
self.load_count = 0
|
||||
|
||||
def load_config(self):
|
||||
self.load_count += 1
|
||||
return self.config
|
||||
|
||||
|
||||
class ExplodingConfigManager:
|
||||
def load_config(self):
|
||||
raise OSError("config.json is unreadable")
|
||||
|
||||
|
||||
WEATHER_SCHEMA = {
|
||||
"type": "object",
|
||||
"properties": {
|
||||
"location_city": {"type": "string", "default": "Dallas"},
|
||||
"location_state": {"type": "string", "default": "Texas"},
|
||||
"location_country": {"type": "string", "default": "US"},
|
||||
"units": {"type": "string", "default": "imperial"},
|
||||
},
|
||||
}
|
||||
|
||||
|
||||
def write_plugin(plugins_dir, plugin_id, schema):
|
||||
plugin_dir = plugins_dir / plugin_id
|
||||
plugin_dir.mkdir(parents=True, exist_ok=True)
|
||||
(plugin_dir / "config_schema.json").write_text(json.dumps(schema))
|
||||
return plugin_dir
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def plugins_dir(tmp_path):
|
||||
d = tmp_path / "plugin-repos"
|
||||
d.mkdir()
|
||||
return d
|
||||
|
||||
|
||||
def make_sm(plugins_dir, tmp_path, location):
|
||||
config = {} if location is None else {"location": location}
|
||||
cm = FakeConfigManager(config)
|
||||
sm = SchemaManager(plugins_dir=plugins_dir, project_root=tmp_path,
|
||||
config_manager=cm)
|
||||
return sm, cm
|
||||
|
||||
|
||||
class TestDeviceLocationDefaults:
|
||||
def test_device_location_replaces_plugin_default(self, plugins_dir, tmp_path):
|
||||
write_plugin(plugins_dir, "ledmatrix-weather", WEATHER_SCHEMA)
|
||||
sm, _ = make_sm(plugins_dir, tmp_path,
|
||||
{"city": "Kansas City", "state": "Missouri", "country": "US"})
|
||||
|
||||
defaults = sm.generate_default_config("ledmatrix-weather")
|
||||
|
||||
assert defaults["location_city"] == "Kansas City"
|
||||
assert defaults["location_state"] == "Missouri"
|
||||
assert defaults["location_country"] == "US"
|
||||
# Non-location defaults are untouched.
|
||||
assert defaults["units"] == "imperial"
|
||||
|
||||
def test_user_set_plugin_value_still_wins(self, plugins_dir, tmp_path):
|
||||
write_plugin(plugins_dir, "ledmatrix-weather", WEATHER_SCHEMA)
|
||||
sm, _ = make_sm(plugins_dir, tmp_path,
|
||||
{"city": "Kansas City", "state": "Missouri", "country": "US"})
|
||||
|
||||
defaults = sm.generate_default_config("ledmatrix-weather")
|
||||
merged = sm.merge_with_defaults({"location_city": "Denver"}, defaults)
|
||||
|
||||
assert merged["location_city"] == "Denver"
|
||||
# Fields the user did not override still follow the device.
|
||||
assert merged["location_state"] == "Missouri"
|
||||
|
||||
def test_blank_and_missing_device_fields_leave_schema_default(self, plugins_dir, tmp_path):
|
||||
write_plugin(plugins_dir, "ledmatrix-weather", WEATHER_SCHEMA)
|
||||
sm, _ = make_sm(plugins_dir, tmp_path, {"city": "Kansas City", "state": " "})
|
||||
|
||||
defaults = sm.generate_default_config("ledmatrix-weather")
|
||||
|
||||
assert defaults["location_city"] == "Kansas City"
|
||||
assert defaults["location_state"] == "Texas" # blank -> not configured
|
||||
assert defaults["location_country"] == "US" # absent -> schema default
|
||||
|
||||
def test_no_device_location_configured_is_a_no_op(self, plugins_dir, tmp_path):
|
||||
write_plugin(plugins_dir, "ledmatrix-weather", WEATHER_SCHEMA)
|
||||
sm, _ = make_sm(plugins_dir, tmp_path, None)
|
||||
|
||||
defaults = sm.generate_default_config("ledmatrix-weather")
|
||||
|
||||
assert defaults["location_city"] == "Dallas"
|
||||
|
||||
def test_no_config_manager_is_a_no_op(self, plugins_dir, tmp_path):
|
||||
write_plugin(plugins_dir, "ledmatrix-weather", WEATHER_SCHEMA)
|
||||
sm = SchemaManager(plugins_dir=plugins_dir, project_root=tmp_path)
|
||||
|
||||
assert sm.generate_default_config("ledmatrix-weather")["location_city"] == "Dallas"
|
||||
|
||||
def test_unreadable_config_falls_back_to_schema_defaults(self, plugins_dir, tmp_path):
|
||||
write_plugin(plugins_dir, "ledmatrix-weather", WEATHER_SCHEMA)
|
||||
sm = SchemaManager(plugins_dir=plugins_dir, project_root=tmp_path,
|
||||
config_manager=ExplodingConfigManager())
|
||||
|
||||
assert sm.generate_default_config("ledmatrix-weather")["location_city"] == "Dallas"
|
||||
|
||||
|
||||
class TestScopedToNamespacedKeys:
|
||||
def test_bare_state_key_is_not_rewritten(self, plugins_dir, tmp_path):
|
||||
"""ledmatrix-elections' ``state`` is a two-letter code, not a place name."""
|
||||
write_plugin(plugins_dir, "ledmatrix-elections", {
|
||||
"type": "object",
|
||||
"properties": {
|
||||
"state": {"type": "string", "default": "CA"},
|
||||
"city": {"type": "string", "default": "Springfield"},
|
||||
},
|
||||
})
|
||||
sm, _ = make_sm(plugins_dir, tmp_path,
|
||||
{"city": "Kansas City", "state": "Missouri", "country": "US"})
|
||||
|
||||
defaults = sm.generate_default_config("ledmatrix-elections")
|
||||
|
||||
assert defaults["state"] == "CA"
|
||||
assert defaults["city"] == "Springfield"
|
||||
|
||||
def test_plugin_without_location_fields_never_reads_config(self, plugins_dir, tmp_path):
|
||||
write_plugin(plugins_dir, "clock-simple", {
|
||||
"type": "object",
|
||||
"properties": {"format": {"type": "string", "default": "12h"}},
|
||||
})
|
||||
sm, cm = make_sm(plugins_dir, tmp_path, {"city": "Kansas City"})
|
||||
|
||||
defaults = sm.generate_default_config("clock-simple")
|
||||
|
||||
assert defaults["format"] == "12h"
|
||||
assert cm.load_count == 0
|
||||
|
||||
|
||||
class TestCachingStaysFresh:
|
||||
def test_location_change_is_picked_up_through_the_defaults_cache(self, plugins_dir, tmp_path):
|
||||
write_plugin(plugins_dir, "ledmatrix-weather", WEATHER_SCHEMA)
|
||||
sm, cm = make_sm(plugins_dir, tmp_path, {"city": "Kansas City"})
|
||||
|
||||
assert sm.generate_default_config("ledmatrix-weather")["location_city"] == "Kansas City"
|
||||
|
||||
cm.config["location"]["city"] = "Omaha"
|
||||
|
||||
# Second call is served from the defaults cache, but must not serve a
|
||||
# stale location.
|
||||
assert sm.generate_default_config("ledmatrix-weather")["location_city"] == "Omaha"
|
||||
|
||||
def test_cached_defaults_are_not_mutated_by_the_overlay(self, plugins_dir, tmp_path):
|
||||
write_plugin(plugins_dir, "ledmatrix-weather", WEATHER_SCHEMA)
|
||||
sm, cm = make_sm(plugins_dir, tmp_path, {"city": "Kansas City"})
|
||||
|
||||
sm.generate_default_config("ledmatrix-weather")
|
||||
assert sm._defaults_cache["ledmatrix-weather"]["location_city"] == "Dallas"
|
||||
|
||||
cm.config.pop("location")
|
||||
assert sm.generate_default_config("ledmatrix-weather")["location_city"] == "Dallas"
|
||||
@@ -0,0 +1,136 @@
|
||||
"""Odds must be fetched for the games shown, not every game in the window.
|
||||
|
||||
SportsUpcoming.update() collected every upcoming game in the schedule window
|
||||
and called _fetch_odds() on each one *inside* that collection loop, narrowing
|
||||
to upcoming_games_to_show only afterwards. The comment there said odds were
|
||||
fetched "only for games that will be displayed", but the sole narrowing it
|
||||
applied was show_favorite_teams_only, which is not the default -- so in the
|
||||
usual configuration nothing narrowed it at all.
|
||||
|
||||
Measured on a live rig: a college league produced 946 upcoming games in one
|
||||
cycle and displayed 1 of them. The same shape on the football plugin produced
|
||||
a burst of 467 sequential ESPN requests that ran for 35s and blew that
|
||||
plugin's 30s update budget, and it repeats every time the 1h odds TTL expires.
|
||||
|
||||
SportsLive is deliberately different: it walks the raw event list because it
|
||||
has to find which games are live, but only fetches odds for a game that has
|
||||
already passed the is_live/is_halftime test, so the fan-out is bounded by how
|
||||
many games are actually in progress.
|
||||
"""
|
||||
import ast
|
||||
from pathlib import Path
|
||||
|
||||
import pytest
|
||||
|
||||
MODES = (Path(__file__).resolve().parent.parent
|
||||
/ "src" / "base_classes" / "sports" / "modes.py")
|
||||
TREE = ast.parse(MODES.read_text(encoding="utf-8"))
|
||||
|
||||
|
||||
def _fetch_sites():
|
||||
"""(class name, method name, lineno) for every self._fetch_odds(...) call."""
|
||||
calls = [n.lineno for n in ast.walk(TREE)
|
||||
if isinstance(n, ast.Call) and isinstance(n.func, ast.Attribute)
|
||||
and n.func.attr == "_fetch_odds"]
|
||||
sites = []
|
||||
for cls in [n for n in ast.walk(TREE) if isinstance(n, ast.ClassDef)]:
|
||||
for fn in [n for n in cls.body if isinstance(n, ast.FunctionDef)]:
|
||||
for lineno in calls:
|
||||
if fn.lineno <= lineno <= (fn.end_lineno or fn.lineno):
|
||||
sites.append((cls.name, fn.name, lineno))
|
||||
assert len(sites) == len(calls), "a _fetch_odds call sits outside any method"
|
||||
return sites
|
||||
|
||||
|
||||
def _innermost_loop_iterable(lineno):
|
||||
best = None
|
||||
for node in ast.walk(TREE):
|
||||
if isinstance(node, ast.For) and \
|
||||
node.lineno <= lineno <= (node.end_lineno or node.lineno):
|
||||
if best is None or node.lineno > best.lineno:
|
||||
best = node
|
||||
return None if best is None else ast.unparse(best.iter)
|
||||
|
||||
|
||||
def _spans(body, lineno):
|
||||
"""True when `lineno` falls inside this list of statements."""
|
||||
return any(n.lineno <= lineno <= (n.end_lineno or n.lineno) for n in body)
|
||||
|
||||
|
||||
def _parents(tree):
|
||||
table = {}
|
||||
for node in ast.walk(tree):
|
||||
for child in ast.iter_child_nodes(node):
|
||||
table[child] = node
|
||||
return table
|
||||
|
||||
|
||||
PARENTS = _parents(TREE)
|
||||
|
||||
|
||||
def _mentions_positively(test, names):
|
||||
"""True when `test` references every name, none of them under a `not`.
|
||||
|
||||
Structural, not textual. Matching the unparsed source would accept
|
||||
`not (details["is_live"] or details["is_halftime"])` -- which selects
|
||||
exactly the non-live games this guard exists to exclude -- because the
|
||||
names still appear in the text.
|
||||
"""
|
||||
found = set()
|
||||
for node in ast.walk(test):
|
||||
if not (isinstance(node, ast.Constant) and node.value in names):
|
||||
continue
|
||||
negated = False
|
||||
cursor = node
|
||||
while cursor is not test and cursor in PARENTS:
|
||||
cursor = PARENTS[cursor]
|
||||
if isinstance(cursor, ast.UnaryOp) and isinstance(cursor.op, ast.Not):
|
||||
negated = True
|
||||
break
|
||||
if not negated:
|
||||
found.add(node.value)
|
||||
return found >= set(names)
|
||||
|
||||
|
||||
def _guarded_by_positive(lineno, names):
|
||||
"""True when some enclosing `if` runs this line only if `names` hold.
|
||||
|
||||
Only the TRUE branch counts: an `if` whose `else` contains the call would
|
||||
otherwise look like a guard while doing the opposite.
|
||||
"""
|
||||
for node in ast.walk(TREE):
|
||||
if isinstance(node, ast.If) and _spans(node.body, lineno) \
|
||||
and _mentions_positively(node.test, names):
|
||||
return True
|
||||
return False
|
||||
|
||||
|
||||
def test_every_fetch_site_is_accounted_for():
|
||||
"""A new call site must be classified deliberately, not inherited silently."""
|
||||
found = {(cls, fn) for cls, fn, _ in _fetch_sites()}
|
||||
assert found == {("SportsUpcoming", "update"), ("SportsLive", "update")}, (
|
||||
f"unexpected _fetch_odds call sites: {sorted(found)}. Each one is a "
|
||||
"sequential ESPN request per game -- classify it here on purpose.")
|
||||
|
||||
|
||||
def test_upcoming_fetches_only_the_selected_games():
|
||||
for cls, _fn, lineno in _fetch_sites():
|
||||
if cls != "SportsUpcoming":
|
||||
continue
|
||||
iterable = _innermost_loop_iterable(lineno)
|
||||
assert iterable == "team_games", (
|
||||
f"SportsUpcoming._fetch_odds at line {lineno} iterates over "
|
||||
f"{iterable!r}. It must run over team_games -- already narrowed to "
|
||||
"upcoming_games_to_show -- not over every event in the schedule "
|
||||
"window. Each item costs one sequential ESPN request.")
|
||||
|
||||
|
||||
def test_live_only_fetches_for_games_actually_in_progress():
|
||||
for cls, _fn, lineno in _fetch_sites():
|
||||
if cls != "SportsLive":
|
||||
continue
|
||||
assert _guarded_by_positive(lineno, {"is_live", "is_halftime"}), (
|
||||
f"SportsLive._fetch_odds at line {lineno} does not sit in the true "
|
||||
"branch of a test requiring the game to be in progress. Without "
|
||||
"that, it fans out across the whole event list -- one sequential "
|
||||
"ESPN request per game.")
|
||||
@@ -0,0 +1,73 @@
|
||||
"""The Vegas content path must trace at DEBUG, not INFO.
|
||||
|
||||
plugin_adapter narrates every step of acquiring content from every plugin --
|
||||
"Has get_vegas_content", "Native: calling get_vegas_content()", "Native content
|
||||
returned None", "Has scroll_helper", the per-item sizes -- and it does that for
|
||||
each plugin on each cycle.
|
||||
|
||||
Measured on a live rig: 13,408 log lines an hour, of which 13,366 were INFO and
|
||||
35 were WARNING. plugin_adapter alone produced 2,457 of them. That is ~223
|
||||
lines a minute of string formatting on a Pi that is also driving the panel, all
|
||||
of it written through journald to the SD card, and it buries the 35 lines that
|
||||
actually indicate a problem.
|
||||
|
||||
Nothing is lost by moving it to DEBUG: the 19 warning/error/exception calls in
|
||||
the module are untouched, so real failures still surface at their own level.
|
||||
|
||||
One INFO call is deliberate and stays -- the padding-strip message chooses its
|
||||
level at runtime (`logger.warning if (left and right) else logger.info`) and
|
||||
test_vegas_plugin_adapter.py pins it.
|
||||
"""
|
||||
import ast
|
||||
from pathlib import Path
|
||||
|
||||
import pytest
|
||||
|
||||
ADAPTER = (Path(__file__).resolve().parent.parent / "src" / "vegas_mode"
|
||||
/ "plugin_adapter.py")
|
||||
|
||||
|
||||
def _logger_calls(path, *levels):
|
||||
"""Direct logger.<level>(...) call sites in a module."""
|
||||
tree = ast.parse(path.read_text(encoding="utf-8"))
|
||||
found = []
|
||||
for node in ast.walk(tree):
|
||||
if (isinstance(node, ast.Call)
|
||||
and isinstance(node.func, ast.Attribute)
|
||||
and node.func.attr in levels
|
||||
and getattr(node.func.value, "id", None) == "logger"):
|
||||
found.append(node.lineno)
|
||||
return found
|
||||
|
||||
|
||||
def _info_calls(path):
|
||||
"""Direct logger.info(...) call sites in a module."""
|
||||
return _logger_calls(path, "info")
|
||||
|
||||
|
||||
def test_the_content_path_does_not_trace_at_info():
|
||||
calls = _info_calls(ADAPTER)
|
||||
assert not calls, (
|
||||
"plugin_adapter should trace at DEBUG; found logger.info at lines "
|
||||
f"{calls}. This path runs per plugin per cycle and its output goes to "
|
||||
"the SD card via journald."
|
||||
)
|
||||
|
||||
|
||||
def test_real_failures_still_have_a_level_of_their_own():
|
||||
"""Demoting the trace must not have swept up the error reporting.
|
||||
|
||||
Counted from the AST rather than with source.count(): the text form also
|
||||
matches comments, docstrings and string literals -- including this
|
||||
module's own docstring, which names these levels -- so a real
|
||||
logger.error() could be demoted while the tally stayed put.
|
||||
"""
|
||||
loud = _logger_calls(ADAPTER, "warning", "error", "exception")
|
||||
assert len(loud) >= 15, \
|
||||
f"only {len(loud)} warning/error/exception calls remain: {loud}"
|
||||
|
||||
|
||||
def test_the_deliberate_runtime_chosen_level_survives():
|
||||
"""The padding-strip message picks its level at runtime; leave it alone."""
|
||||
source = ADAPTER.read_text(encoding="utf-8")
|
||||
assert "logger.warning if (left and right) else logger.info" in source
|
||||
@@ -229,44 +229,6 @@ class TestSavePluginConfig:
|
||||
"REAL-KEY-0123456789", "an unrelated edit destroyed the API key"
|
||||
assert env.fresh_load()[PLUGIN_ID]["city"] == "Dallas"
|
||||
|
||||
def test_an_unrelated_edit_does_not_erase_array_item_secrets(self, env):
|
||||
"""The scalar api_key case above, but for a list of credentials.
|
||||
|
||||
remove_empty_secrets recursed into dicts only, so a list went into
|
||||
deep_merge untouched -- and lists merge by *replacement*. Saving any
|
||||
unrelated field posted [{"token": ""}, ...] straight over the stored
|
||||
array and destroyed every token in it at once.
|
||||
"""
|
||||
assert self._save(env, {"accounts": [
|
||||
{"name": "a", "token": "REAL-A"},
|
||||
{"name": "b", "token": "REAL-B"},
|
||||
], "city": "Austin"}).status_code == 200
|
||||
|
||||
# the user changes the city; both masked tokens ride along blank
|
||||
assert self._save(env, {"accounts": [
|
||||
{"name": "a", "token": ""},
|
||||
{"name": "b", "token": ""},
|
||||
], "city": "Dallas"}).status_code == 200
|
||||
|
||||
merged = env.fresh_load()[PLUGIN_ID]
|
||||
assert [a.get("token") for a in merged["accounts"]] == \
|
||||
["REAL-A", "REAL-B"], "an unrelated edit destroyed the array secrets"
|
||||
assert [a["name"] for a in merged["accounts"]] == ["a", "b"]
|
||||
assert merged["city"] == "Dallas"
|
||||
|
||||
def test_one_array_secret_can_be_changed_without_losing_the_rest(self, env):
|
||||
assert self._save(env, {"accounts": [
|
||||
{"name": "a", "token": "REAL-A"},
|
||||
{"name": "b", "token": "REAL-B"},
|
||||
]}).status_code == 200
|
||||
assert self._save(env, {"accounts": [
|
||||
{"name": "a", "token": ""},
|
||||
{"name": "b", "token": "NEW-B"},
|
||||
]}).status_code == 200
|
||||
|
||||
merged = env.fresh_load()[PLUGIN_ID]
|
||||
assert [a.get("token") for a in merged["accounts"]] == ["REAL-A", "NEW-B"]
|
||||
|
||||
def test_a_secret_can_still_be_changed(self, env):
|
||||
"""Dropping blanks must not stop a real new value from being saved."""
|
||||
self._save(env, {"api_key": "first-key"})
|
||||
|
||||
@@ -1,45 +0,0 @@
|
||||
"""The validation logging ran before separate_secrets, so it logged credentials.
|
||||
|
||||
api_v3's plugin-config save logged `Full config: {plugin_config}` at INFO and
|
||||
`Config that failed: {plugin_config}` at ERROR. Both run *before*
|
||||
separate_secrets(), so plugin_config still held the values the user just typed
|
||||
into the form -- API keys and tokens went to the journal in clear text.
|
||||
"""
|
||||
import re
|
||||
from pathlib import Path
|
||||
|
||||
import pytest
|
||||
|
||||
SOURCE = (Path(__file__).resolve().parents[2]
|
||||
/ "web_interface" / "blueprints" / "api_v3.py")
|
||||
|
||||
#: Objects that still hold submitted secret values at the point these log
|
||||
#: calls run. Interpolating one whole into a log message leaks credentials.
|
||||
UNREDACTED = ("plugin_config", "secrets_config", "current_secrets")
|
||||
|
||||
|
||||
def _logging_lines():
|
||||
for number, line in enumerate(SOURCE.read_text(encoding="utf-8").splitlines(), 1):
|
||||
stripped = line.strip()
|
||||
if stripped.startswith("#"):
|
||||
continue
|
||||
if re.match(r"logger\.(debug|info|warning|error|critical|exception)\(", stripped):
|
||||
yield number, stripped
|
||||
|
||||
|
||||
@pytest.mark.parametrize("name", UNREDACTED)
|
||||
def test_no_log_call_interpolates_a_whole_secret_bearing_object(name):
|
||||
# {name} or {name['k']} leaks; {list(name.keys())} and {len(name)} do not.
|
||||
bare = re.compile(r"\{" + re.escape(name) + r"(\[[^\]]*\])*\}")
|
||||
offenders = [f"{n}: {text}" for n, text in _logging_lines() if bare.search(text)]
|
||||
assert not offenders, (
|
||||
f"{name} still holds submitted secrets where these log calls run:\n "
|
||||
+ "\n ".join(offenders))
|
||||
|
||||
|
||||
def test_the_guard_would_notice_a_reintroduced_leak():
|
||||
"""Pin the detector itself, so a rewrite cannot silently stop matching."""
|
||||
bare = re.compile(r"\{" + re.escape("plugin_config") + r"(\[[^\]]*\])*\}")
|
||||
assert bare.search('logger.info(f"Full config: {plugin_config}")')
|
||||
assert bare.search("logger.error(f\"{plugin_config['api_key']}\")")
|
||||
assert not bare.search('logger.info(f"{list(plugin_config.keys())}")')
|
||||
@@ -17,7 +17,6 @@ from src.web_interface.secret_helpers import (
|
||||
separate_secrets,
|
||||
mask_secret_fields,
|
||||
mask_all_secret_values,
|
||||
merge_secrets,
|
||||
remove_empty_secrets,
|
||||
)
|
||||
|
||||
@@ -240,67 +239,3 @@ class TestRemoveEmptySecrets:
|
||||
def test_keeps_falsey_non_string_values(self):
|
||||
# 0 and False are neither None nor blank strings — they are kept.
|
||||
assert remove_empty_secrets({"a": 0, "b": False}) == {"a": 0, "b": False}
|
||||
|
||||
|
||||
class TestArrayItemSecrets:
|
||||
"""Lists merge by replacement, so a blanked array wipes stored credentials.
|
||||
|
||||
remove_empty_secrets recursed into dicts but let a list through untouched,
|
||||
so [{"token": ""}] went straight into deep_merge and overwrote the stored
|
||||
list. Saving any unrelated setting destroyed every token in the array.
|
||||
"""
|
||||
|
||||
STORED = {"accounts": [{"name": "a", "token": "REAL-A"},
|
||||
{"name": "b", "token": "REAL-B"}]}
|
||||
|
||||
def test_an_unrelated_save_keeps_every_stored_token(self):
|
||||
posted = {"accounts": [{"name": "a", "token": ""},
|
||||
{"name": "b", "token": ""}]}
|
||||
merged = merge_secrets(self.STORED, remove_empty_secrets(posted))
|
||||
assert [a["token"] for a in merged["accounts"]] == ["REAL-A", "REAL-B"]
|
||||
|
||||
def test_editing_one_entry_leaves_the_others_alone(self):
|
||||
posted = {"accounts": [{"name": "a", "token": ""},
|
||||
{"name": "b", "token": "NEW-B"}]}
|
||||
merged = merge_secrets(self.STORED, remove_empty_secrets(posted))
|
||||
assert [a["token"] for a in merged["accounts"]] == ["REAL-A", "NEW-B"]
|
||||
|
||||
def test_a_new_entry_is_appended(self):
|
||||
posted = {"accounts": [{"name": "a", "token": ""},
|
||||
{"name": "b", "token": ""},
|
||||
{"name": "c", "token": "NEW-C"}]}
|
||||
merged = merge_secrets(self.STORED, remove_empty_secrets(posted))
|
||||
assert [a["token"] for a in merged["accounts"]] == \
|
||||
["REAL-A", "REAL-B", "NEW-C"]
|
||||
|
||||
def test_a_list_of_bare_strings_merges_by_index(self):
|
||||
merged = merge_secrets({"keys": ["K1", "K2", "K3"]},
|
||||
remove_empty_secrets({"keys": ["", "K2-NEW", ""]}))
|
||||
assert merged["keys"] == ["K1", "K2-NEW", "K3"]
|
||||
|
||||
def test_an_all_blank_list_is_dropped_entirely(self):
|
||||
posted = {"accounts": [{"token": ""}, {"token": ""}]}
|
||||
assert "accounts" not in remove_empty_secrets(posted)
|
||||
|
||||
def test_plain_dict_secrets_are_unaffected(self):
|
||||
merged = merge_secrets({"api_key": "OLD", "other": "keep"},
|
||||
remove_empty_secrets({"api_key": "", "other": "changed"}))
|
||||
assert merged == {"api_key": "OLD", "other": "changed"}
|
||||
|
||||
def test_a_removed_entry_takes_its_secret_with_it(self):
|
||||
"""The regular config's list is authoritative about how many items
|
||||
exist, and the secrets list runs parallel to it -- see
|
||||
ConfigManager._strip_secrets_recursive. So a shorter incoming list
|
||||
must shorten the stored secrets too, or the two fall out of step."""
|
||||
posted = {"accounts": [{"name": "a", "token": "NEW-A"}]}
|
||||
merged = merge_secrets(self.STORED, remove_empty_secrets(posted))
|
||||
assert [a["token"] for a in merged["accounts"]] == ["NEW-A"]
|
||||
|
||||
def test_an_emptied_item_stays_a_dict_not_none(self):
|
||||
"""None there stops the list looking parallel, and
|
||||
_strip_secrets_recursive then drops the whole key from the main
|
||||
config -- deleting the item's non-secret fields as well."""
|
||||
pruned = remove_empty_secrets(
|
||||
{"accounts": [{"token": "real"}, {"token": ""}]})
|
||||
assert pruned["accounts"] == [{"token": "real"}, {}]
|
||||
assert None not in pruned["accounts"]
|
||||
|
||||
@@ -118,7 +118,8 @@ saved_repositories_manager = SavedRepositoriesManager()
|
||||
schema_manager = SchemaManager(
|
||||
plugins_dir=plugins_dir,
|
||||
project_root=project_root,
|
||||
logger=None
|
||||
logger=None,
|
||||
config_manager=config_manager
|
||||
)
|
||||
|
||||
# Initialize operation queue for plugin operations
|
||||
|
||||
@@ -22,8 +22,7 @@ logger = logging.getLogger(__name__)
|
||||
from src.web_interface.api_helpers import success_response, error_response, validate_request_json
|
||||
from src.web_interface.errors import ErrorCode
|
||||
from src.web_interface.secret_helpers import (find_secret_fields, mask_all_secret_values,
|
||||
merge_secrets, remove_empty_secrets,
|
||||
separate_secrets,
|
||||
remove_empty_secrets, separate_secrets,
|
||||
strip_masked_values)
|
||||
from src.web_interface.error_handler import describe_exception, redact_text
|
||||
from src.plugin_system.operation_types import OperationType
|
||||
@@ -1297,10 +1296,7 @@ def save_main_config():
|
||||
if secrets_config:
|
||||
if plugin_id not in current_secrets:
|
||||
current_secrets[plugin_id] = {}
|
||||
# Lists merge by replacement, so deep_merge here wrote a
|
||||
# blanked array straight over the stored credentials.
|
||||
current_secrets[plugin_id] = merge_secrets(
|
||||
current_secrets[plugin_id], secrets_config)
|
||||
current_secrets[plugin_id] = deep_merge(current_secrets[plugin_id], secrets_config)
|
||||
# Save secrets file
|
||||
api_v3.config_manager.save_raw_file_content('secrets', current_secrets)
|
||||
|
||||
@@ -5679,10 +5675,8 @@ def save_plugin_config():
|
||||
if schema:
|
||||
# Log what we're validating for debugging
|
||||
logger.info(f"Validating config for {plugin_id}")
|
||||
# Only the shape. plugin_config still holds the submitted secret
|
||||
# values at this point -- separate_secrets does not run until
|
||||
# below -- so logging it wrote live credentials to the journal.
|
||||
logger.info(f"Config keys being validated: {list(plugin_config.keys())}")
|
||||
logger.info(f"Full config: {plugin_config}")
|
||||
|
||||
# Get enhanced schema keys (including injected core properties)
|
||||
# We need to create an enhanced schema to get the actual allowed keys
|
||||
@@ -5705,8 +5699,7 @@ def save_plugin_config():
|
||||
# Log validation errors for debugging
|
||||
logger.error(f"Config validation failed for {plugin_id}")
|
||||
logger.error(f"Validation errors: {validation_errors}")
|
||||
# Keys only, for the same reason as above.
|
||||
logger.error(f"Config keys that failed: {list(plugin_config.keys())}")
|
||||
logger.error(f"Config that failed: {plugin_config}")
|
||||
logger.error(f"Schema properties: {list(enhanced_schema.get('properties', {}).keys())}")
|
||||
|
||||
# Also print to console for immediate visibility
|
||||
@@ -5757,9 +5750,7 @@ def save_plugin_config():
|
||||
if secrets_config:
|
||||
if plugin_id not in current_secrets:
|
||||
current_secrets[plugin_id] = {}
|
||||
# See above -- secrets lists must merge element-wise.
|
||||
current_secrets[plugin_id] = merge_secrets(
|
||||
current_secrets[plugin_id], secrets_config)
|
||||
current_secrets[plugin_id] = deep_merge(current_secrets[plugin_id], secrets_config)
|
||||
# Save secrets file
|
||||
try:
|
||||
api_v3.config_manager.save_raw_file_content('secrets', current_secrets)
|
||||
|
||||
@@ -126,17 +126,7 @@ window.showRestartPending = function(message) {
|
||||
} catch { /* private browsing */ }
|
||||
const banner = document.getElementById('restart-pending-banner');
|
||||
const text = document.getElementById('restart-pending-text');
|
||||
if (text) {
|
||||
// Without the else-branch a config save inherited whatever wording the
|
||||
// previous update left in the DOM: showRestartPending() clears the
|
||||
// stored text but used to leave the element itself alone. The default
|
||||
// is read back from the server-rendered copy rather than duplicated
|
||||
// here, so the template stays the one place that owns the string.
|
||||
if (text.dataset.defaultText === undefined) {
|
||||
text.dataset.defaultText = text.textContent.trim();
|
||||
}
|
||||
text.textContent = message || text.dataset.defaultText;
|
||||
}
|
||||
if (text && message) text.textContent = message;
|
||||
if (banner) banner.style.display = 'block';
|
||||
};
|
||||
|
||||
|
||||
@@ -95,7 +95,7 @@
|
||||
<!-- Location Information -->
|
||||
<div class="grid grid-cols-1 md:grid-cols-3 xl:grid-cols-3 2xl:grid-cols-3 gap-4">
|
||||
<div class="form-group" id="setting-general-city" data-setting-key="location.city">
|
||||
<label for="city" class="block text-sm font-medium text-gray-700">City{{ ui.help_tip('City used for weather, sunrise/sunset, and other location-based content.\nExample: Dallas.', 'City') }}</label>
|
||||
<label for="city" class="block text-sm font-medium text-gray-700">City{{ ui.help_tip('City used for weather, sunrise/sunset, radar, and other location-based content.\nExample: Kansas City.\nUsed as the default for the location_city setting on plugins that have one; a value saved on the plugin itself overrides it.', 'City') }}</label>
|
||||
<input type="text"
|
||||
id="city"
|
||||
name="city"
|
||||
@@ -104,7 +104,7 @@
|
||||
</div>
|
||||
|
||||
<div class="form-group" id="setting-general-state" data-setting-key="location.state">
|
||||
<label for="state" class="block text-sm font-medium text-gray-700">State{{ ui.help_tip('State or region for your location.\nExample: Texas. Improves location-lookup accuracy.', 'State') }}</label>
|
||||
<label for="state" class="block text-sm font-medium text-gray-700">State{{ ui.help_tip('State or region for your location.\nExample: Missouri. Improves location-lookup accuracy.\nUsed as the default for the location_state setting on plugins that have one.', 'State') }}</label>
|
||||
<input type="text"
|
||||
id="state"
|
||||
name="state"
|
||||
@@ -113,7 +113,7 @@
|
||||
</div>
|
||||
|
||||
<div class="form-group" id="setting-general-country" data-setting-key="location.country">
|
||||
<label for="country" class="block text-sm font-medium text-gray-700">Country{{ ui.help_tip('Country code or name for your location.\nExample: US. Used with City and State for weather and geolocation.', 'Country') }}</label>
|
||||
<label for="country" class="block text-sm font-medium text-gray-700">Country{{ ui.help_tip('Country code or name for your location.\nExample: US. Used with City and State for weather, radar, and geolocation.\nUsed as the default for the location_country setting on plugins that have one.', 'Country') }}</label>
|
||||
<input type="text"
|
||||
id="country"
|
||||
name="country"
|
||||
|
||||
Reference in New Issue
Block a user