mirror of
https://github.com/ChuckBuilds/LEDMatrix.git
synced 2026-08-22 02:48:15 +00:00
Compare commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
d64fa9761a |
@@ -328,11 +328,7 @@ class ScrollHelper:
|
|||||||
elapsed_time = current_time - (self.scroll_start_time or current_time)
|
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
|
# The image already includes display_width padding, so we only need total_scroll_width
|
||||||
required_total_distance = self.total_scroll_width
|
required_total_distance = self.total_scroll_width
|
||||||
# Progress telemetry, emitted every few seconds for the whole of
|
self.logger.info(
|
||||||
# every scroll. It says how far along a marquee is, which is what
|
|
||||||
# you turn debug on to watch and not something an operator needs
|
|
||||||
# in the journal on a device that scrolls all day.
|
|
||||||
self.logger.debug(
|
|
||||||
"Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
|
"Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
|
||||||
elapsed_time,
|
elapsed_time,
|
||||||
self.calculated_duration,
|
self.calculated_duration,
|
||||||
|
|||||||
+1
-84
@@ -130,12 +130,7 @@ def setup_logging(
|
|||||||
# Console handler (always add)
|
# Console handler (always add)
|
||||||
console_handler = logging.StreamHandler(sys.stdout)
|
console_handler = logging.StreamHandler(sys.stdout)
|
||||||
console_handler.setLevel(level)
|
console_handler.setLevel(level)
|
||||||
# Under systemd, tag each line so the journal records the real severity
|
console_handler.setFormatter(formatter)
|
||||||
# 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)
|
root_logger.addHandler(console_handler)
|
||||||
|
|
||||||
# File handler (if specified)
|
# File handler (if specified)
|
||||||
@@ -150,84 +145,6 @@ def setup_logging(
|
|||||||
sys.stderr.write(f"Warning: Could not set up file logging to {log_file}: {e}\n")
|
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):
|
class PluginLoggerAdapter(logging.LoggerAdapter):
|
||||||
"""LoggerAdapter that stamps every record with its plugin_id.
|
"""LoggerAdapter that stamps every record with its plugin_id.
|
||||||
|
|
||||||
|
|||||||
@@ -178,21 +178,11 @@ class PluginHealthTracker:
|
|||||||
)
|
)
|
||||||
return self._health_state[plugin_id]
|
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:
|
def record_success(self, plugin_id: str) -> None:
|
||||||
"""Record a successful plugin execution."""
|
"""Record a successful plugin execution."""
|
||||||
state = self.get_health_state(plugin_id)
|
state = self.get_health_state(plugin_id)
|
||||||
current_time = time.time()
|
current_time = time.time()
|
||||||
durable_before = self._durable(state)
|
|
||||||
|
|
||||||
# Reset consecutive failures
|
# Reset consecutive failures
|
||||||
state['consecutive_failures'] = 0
|
state['consecutive_failures'] = 0
|
||||||
state['total_successes'] = state.get('total_successes', 0) + 1
|
state['total_successes'] = state.get('total_successes', 0) + 1
|
||||||
@@ -208,20 +198,9 @@ class PluginHealthTracker:
|
|||||||
# Shouldn't happen, but handle it
|
# Shouldn't happen, but handle it
|
||||||
state['circuit_state'] = CircuitState.CLOSED.value
|
state['circuit_state'] = CircuitState.CLOSED.value
|
||||||
state['circuit_opened_time'] = None
|
state['circuit_opened_time'] = None
|
||||||
|
|
||||||
# A healthy plugin reports success every cycle, and in that steady state
|
self._save_health_state(plugin_id, 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:
|
def record_failure(self, plugin_id: str, error: Optional[Exception] = None) -> None:
|
||||||
"""Record a failed plugin execution."""
|
"""Record a failed plugin execution."""
|
||||||
state = self.get_health_state(plugin_id)
|
state = self.get_health_state(plugin_id)
|
||||||
|
|||||||
@@ -9,7 +9,7 @@ import time
|
|||||||
import logging
|
import logging
|
||||||
import threading
|
import threading
|
||||||
from typing import Dict, Optional, Any, Callable
|
from typing import Dict, Optional, Any, Callable
|
||||||
from dataclasses import dataclass, field, fields
|
from dataclasses import dataclass, field
|
||||||
|
|
||||||
try:
|
try:
|
||||||
import psutil
|
import psutil
|
||||||
@@ -49,20 +49,6 @@ class ResourceMetrics:
|
|||||||
self.total_execution_time = self.total_execution_time / self.call_count
|
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:
|
class PluginResourceMonitor:
|
||||||
"""
|
"""
|
||||||
Monitors resource usage for plugins.
|
Monitors resource usage for plugins.
|
||||||
@@ -89,10 +75,6 @@ class PluginResourceMonitor:
|
|||||||
# Resource metrics per plugin
|
# Resource metrics per plugin
|
||||||
self._metrics: Dict[str, ResourceMetrics] = {}
|
self._metrics: Dict[str, ResourceMetrics] = {}
|
||||||
self._limits: Dict[str, ResourceLimits] = {}
|
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
|
# Thread-local storage for execution tracking
|
||||||
self._local = threading.local()
|
self._local = threading.local()
|
||||||
@@ -120,66 +102,6 @@ class PluginResourceMonitor:
|
|||||||
"psutil not available - resource monitoring will be limited to execution time only"
|
"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:
|
def _get_metrics_key(self, plugin_id: str) -> str:
|
||||||
"""Get cache key for plugin metrics."""
|
"""Get cache key for plugin metrics."""
|
||||||
return f"plugin_metrics:{plugin_id}"
|
return f"plugin_metrics:{plugin_id}"
|
||||||
@@ -204,7 +126,7 @@ class PluginResourceMonitor:
|
|||||||
cache_key, max_age=None, memory_ttl=0 if force_reload else None
|
cache_key, max_age=None, memory_ttl=0 if force_reload else None
|
||||||
)
|
)
|
||||||
if cached:
|
if cached:
|
||||||
metrics = self._metrics_from_cache(plugin_id, cached)
|
metrics = ResourceMetrics(**cached)
|
||||||
else:
|
else:
|
||||||
metrics = ResourceMetrics()
|
metrics = ResourceMetrics()
|
||||||
self._metrics[plugin_id] = metrics
|
self._metrics[plugin_id] = metrics
|
||||||
@@ -310,8 +232,18 @@ class PluginResourceMonitor:
|
|||||||
# CPU is harder to measure per-call, so we track it separately
|
# CPU is harder to measure per-call, so we track it separately
|
||||||
metrics.cpu_percent = self._get_process_cpu_percent()
|
metrics.cpu_percent = self._get_process_cpu_percent()
|
||||||
|
|
||||||
# Persist metrics, at most once per interval per plugin.
|
# Persist metrics
|
||||||
self._persist_metrics(plugin_id, 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
|
||||||
|
})
|
||||||
|
|
||||||
# Check limits
|
# Check limits
|
||||||
if limits:
|
if limits:
|
||||||
@@ -431,44 +363,6 @@ class PluginResourceMonitor:
|
|||||||
summaries[plugin_id] = self.get_metrics_summary(plugin_id)
|
summaries[plugin_id] = self.get_metrics_summary(plugin_id)
|
||||||
return summaries
|
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:
|
def reset_metrics(self, plugin_id: str) -> None:
|
||||||
"""Reset metrics for a plugin."""
|
"""Reset metrics for a plugin."""
|
||||||
with self._lock:
|
with self._lock:
|
||||||
@@ -476,7 +370,4 @@ class PluginResourceMonitor:
|
|||||||
self._metrics[plugin_id] = ResourceMetrics()
|
self._metrics[plugin_id] = ResourceMetrics()
|
||||||
cache_key = self._get_metrics_key(plugin_id)
|
cache_key = self._get_metrics_key(plugin_id)
|
||||||
self.cache_manager.delete(cache_key)
|
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)
|
|
||||||
|
|
||||||
|
|||||||
@@ -31,18 +31,6 @@ if TYPE_CHECKING:
|
|||||||
logger = logging.getLogger(__name__)
|
logger = logging.getLogger(__name__)
|
||||||
|
|
||||||
|
|
||||||
#: Degradation threshold, as a fraction of target_fps. A marquee jitters a
|
|
||||||
#: little all the time, so "anything under target" would report constantly and
|
|
||||||
#: mean nothing; 90% of target is the point where a shortfall is real. At a
|
|
||||||
#: 60fps target that is 54fps -- 55fps is a normal wobble and stays at DEBUG,
|
|
||||||
#: which is deliberate, not an off-by-one.
|
|
||||||
_FPS_HEALTHY_FRACTION = 0.9
|
|
||||||
|
|
||||||
#: A healthy marquee still reports this often, so silence means stopped
|
|
||||||
#: rather than fine.
|
|
||||||
_FPS_HEARTBEAT_INTERVAL = 300.0
|
|
||||||
|
|
||||||
|
|
||||||
def _percentile(ordered: List[float], fraction: float) -> float:
|
def _percentile(ordered: List[float], fraction: float) -> float:
|
||||||
"""Nearest-rank percentile of an already-sorted list.
|
"""Nearest-rank percentile of an already-sorted list.
|
||||||
|
|
||||||
@@ -108,11 +96,6 @@ class VegasModeCoordinator:
|
|||||||
self._is_active = False
|
self._is_active = False
|
||||||
self._is_paused = False
|
self._is_paused = False
|
||||||
self._should_stop = False
|
self._should_stop = False
|
||||||
# Frame-rate health, tracked across run_iteration() calls so the
|
|
||||||
# heartbeat is one-per-interval rather than one-per-cycle, and so a
|
|
||||||
# recovery spanning two cycles is still reported. Reset on start().
|
|
||||||
self._fps_last_health_log = 0.0
|
|
||||||
self._fps_was_degraded = False
|
|
||||||
self._state_lock = threading.Lock()
|
self._state_lock = threading.Lock()
|
||||||
|
|
||||||
# Live priority tracking
|
# Live priority tracking
|
||||||
@@ -265,11 +248,6 @@ class VegasModeCoordinator:
|
|||||||
self._is_active = True
|
self._is_active = True
|
||||||
self._should_stop = False
|
self._should_stop = False
|
||||||
self._start_time = time.time()
|
self._start_time = time.time()
|
||||||
# A fresh run starts with a clean health slate: no stale
|
|
||||||
# "was degraded" from the previous run, and a heartbeat that is
|
|
||||||
# due immediately so the first sample confirms the marquee is up.
|
|
||||||
self._fps_last_health_log = 0.0
|
|
||||||
self._fps_was_degraded = False
|
|
||||||
|
|
||||||
# Line up the next group immediately, so the first extension is already
|
# Line up the next group immediately, so the first extension is already
|
||||||
# warm rather than stalling the scroll to fetch it.
|
# warm rather than stalling the scroll to fetch it.
|
||||||
@@ -417,18 +395,8 @@ class VegasModeCoordinator:
|
|||||||
duration = self.render_pipeline.get_dynamic_duration()
|
duration = self.render_pipeline.get_dynamic_duration()
|
||||||
start_time = time.time()
|
start_time = time.time()
|
||||||
frame_count = 0
|
frame_count = 0
|
||||||
fps_log_interval = 5.0 # Sample FPS every 5 seconds
|
fps_log_interval = 5.0 # Log FPS every 5 seconds
|
||||||
# Health state lives on the coordinator, not here: run_iteration() is
|
last_fps_log_time = start_time
|
||||||
# called once per cycle, so locals reset every few seconds. That made
|
|
||||||
# `last_fps_health_log = 0.0` fire the "heartbeat" on the first sample
|
|
||||||
# of every iteration rather than once per interval, and a recovery
|
|
||||||
# that crossed an iteration boundary was never reported at all --
|
|
||||||
# was_degraded had already gone back to False.
|
|
||||||
# Monotonic, and deliberately not start_time: start_time is wall
|
|
||||||
# clock and is used below to report the iteration's duration. Mixing
|
|
||||||
# the two here would make every delta hugely negative and silence the
|
|
||||||
# frame-rate reporting altogether.
|
|
||||||
last_fps_log_time = time.monotonic()
|
|
||||||
fps_frame_count = 0
|
fps_frame_count = 0
|
||||||
# A mean hides stutter completely. At 120fps a five-second window is
|
# A mean hides stutter completely. At 120fps a five-second window is
|
||||||
# ~600 frames, so a 200ms freeze -- plainly visible on a marquee --
|
# ~600 frames, so a 200ms freeze -- plainly visible on a marquee --
|
||||||
@@ -440,13 +408,7 @@ class VegasModeCoordinator:
|
|||||||
logger.info("Starting Vegas iteration for %.1fs", duration)
|
logger.info("Starting Vegas iteration for %.1fs", duration)
|
||||||
|
|
||||||
while True:
|
while True:
|
||||||
# Monotonic, like the FPS window below. These devices have no RTC,
|
frame_started = time.time()
|
||||||
# so the wall clock jumps by however wrong boot time was the moment
|
|
||||||
# NTP first syncs. A backward jump makes frame_elapsed negative,
|
|
||||||
# and `frame_interval - frame_elapsed` then sleeps for longer than
|
|
||||||
# the whole budget -- the render loop stalls for the size of the
|
|
||||||
# correction. A forward jump inflates p99 and worst-frame instead.
|
|
||||||
frame_started = time.monotonic()
|
|
||||||
|
|
||||||
# Check for STATIC mode plugin that should pause scroll
|
# Check for STATIC mode plugin that should pause scroll
|
||||||
static_plugin = self._check_static_plugin_trigger()
|
static_plugin = self._check_static_plugin_trigger()
|
||||||
@@ -474,7 +436,7 @@ class VegasModeCoordinator:
|
|||||||
# quarter of the budget spent not rendering. Subtracting the work
|
# quarter of the budget spent not rendering. Subtracting the work
|
||||||
# already done keeps the pacing target while reclaiming that time,
|
# already done keeps the pacing target while reclaiming that time,
|
||||||
# and yields the GIL either way so other threads still run.
|
# and yields the GIL either way so other threads still run.
|
||||||
frame_elapsed = time.monotonic() - frame_started
|
frame_elapsed = time.time() - frame_started
|
||||||
time.sleep(max(0.0, frame_interval - frame_elapsed))
|
time.sleep(max(0.0, frame_interval - frame_elapsed))
|
||||||
|
|
||||||
# Measured before the sleep: time spent working, not pacing.
|
# Measured before the sleep: time spent working, not pacing.
|
||||||
@@ -486,42 +448,16 @@ class VegasModeCoordinator:
|
|||||||
frame_count += 1
|
frame_count += 1
|
||||||
fps_frame_count += 1
|
fps_frame_count += 1
|
||||||
|
|
||||||
# Periodic FPS logging. Reported at INFO only when the frame rate
|
# Periodic FPS logging
|
||||||
# is actually worth an operator's attention -- a shortfall against
|
current_time = time.time()
|
||||||
# target, or the recovery from one -- with a slow heartbeat so a
|
|
||||||
# healthy marquee still shows a pulse.
|
|
||||||
#
|
|
||||||
# Measured over two hours on a running rig: 1410 samples, 98.5%
|
|
||||||
# of them within 10% of target. The 1.5% that were not included a
|
|
||||||
# reading of 8.6fps against a target of 60 -- a real stall, and
|
|
||||||
# completely invisible inside 1389 lines reading "59.6".
|
|
||||||
# Monotonic: every use of this value in the block below is a
|
|
||||||
# duration, and these devices have no RTC, so the wall clock jumps
|
|
||||||
# by however wrong boot time was the moment NTP first syncs. That
|
|
||||||
# would not only mis-fire the heartbeat, it would corrupt the
|
|
||||||
# frame rate itself, since fps is frames divided by this delta.
|
|
||||||
current_time = time.monotonic()
|
|
||||||
if current_time - last_fps_log_time >= fps_log_interval:
|
if current_time - last_fps_log_time >= fps_log_interval:
|
||||||
fps = fps_frame_count / (current_time - last_fps_log_time)
|
fps = fps_frame_count / (current_time - last_fps_log_time)
|
||||||
p99 = _percentile(sorted(frame_times), 0.99)
|
p99 = _percentile(sorted(frame_times), 0.99)
|
||||||
target = self.vegas_config.target_fps
|
logger.info(
|
||||||
degraded = target > 0 and fps < target * _FPS_HEALTHY_FRACTION
|
"Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms",
|
||||||
due = (current_time - self._fps_last_health_log
|
fps, self.vegas_config.target_fps, fps_frame_count,
|
||||||
>= _FPS_HEARTBEAT_INTERVAL)
|
p99 * 1000.0, frame_worst * 1000.0
|
||||||
if degraded or self._fps_was_degraded or due:
|
)
|
||||||
logger.info(
|
|
||||||
"Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms",
|
|
||||||
fps, target, fps_frame_count,
|
|
||||||
p99 * 1000.0, frame_worst * 1000.0
|
|
||||||
)
|
|
||||||
self._fps_last_health_log = current_time
|
|
||||||
else:
|
|
||||||
logger.debug(
|
|
||||||
"Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms",
|
|
||||||
fps, target, fps_frame_count,
|
|
||||||
p99 * 1000.0, frame_worst * 1000.0
|
|
||||||
)
|
|
||||||
self._fps_was_degraded = degraded
|
|
||||||
last_fps_log_time = current_time
|
last_fps_log_time = current_time
|
||||||
fps_frame_count = 0
|
fps_frame_count = 0
|
||||||
frame_worst = 0.0
|
frame_worst = 0.0
|
||||||
|
|||||||
@@ -83,7 +83,7 @@ class PluginAdapter:
|
|||||||
# into unrelated headlines once the strip refreshed to 9,505px.
|
# into unrelated headlines once the strip refreshed to 9,505px.
|
||||||
self._offset_shapes: dict = {}
|
self._offset_shapes: dict = {}
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"PluginAdapter initialized: display=%dx%d",
|
"PluginAdapter initialized: display=%dx%d",
|
||||||
self.display_width, self.display_height
|
self.display_width, self.display_height
|
||||||
)
|
)
|
||||||
@@ -109,7 +109,7 @@ class PluginAdapter:
|
|||||||
Returns:
|
Returns:
|
||||||
List of PIL Images representing plugin content, or None if no content
|
List of PIL Images representing plugin content, or None if no content
|
||||||
"""
|
"""
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Getting content (class=%s)",
|
"[%s] Getting content (class=%s)",
|
||||||
plugin_id, plugin.__class__.__name__
|
plugin_id, plugin.__class__.__name__
|
||||||
)
|
)
|
||||||
@@ -118,7 +118,7 @@ class PluginAdapter:
|
|||||||
cached = self._get_cached(plugin_id)
|
cached = self._get_cached(plugin_id)
|
||||||
if cached is not None:
|
if cached is not None:
|
||||||
total_width = sum(img.width for img in cached)
|
total_width = sum(img.width for img in cached)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Using cached content: %d images, %dpx total",
|
"[%s] Using cached content: %d images, %dpx total",
|
||||||
plugin_id, len(cached), total_width
|
plugin_id, len(cached), total_width
|
||||||
)
|
)
|
||||||
@@ -126,46 +126,46 @@ class PluginAdapter:
|
|||||||
|
|
||||||
# Try native Vegas content method first
|
# Try native Vegas content method first
|
||||||
has_native = hasattr(plugin, 'get_vegas_content')
|
has_native = hasattr(plugin, 'get_vegas_content')
|
||||||
logger.debug("[%s] Has get_vegas_content: %s", plugin_id, has_native)
|
logger.info("[%s] Has get_vegas_content: %s", plugin_id, has_native)
|
||||||
if has_native:
|
if has_native:
|
||||||
content = self._get_native_content(plugin, plugin_id, offscreen_only)
|
content = self._get_native_content(plugin, plugin_id, offscreen_only)
|
||||||
if content:
|
if content:
|
||||||
total_width = sum(img.width for img in content)
|
total_width = sum(img.width for img in content)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native content SUCCESS: %d images, %dpx total",
|
"[%s] Native content SUCCESS: %d images, %dpx total",
|
||||||
plugin_id, len(content), total_width
|
plugin_id, len(content), total_width
|
||||||
)
|
)
|
||||||
return self._finalize(content, plugin_id, 'native', plugin)
|
return self._finalize(content, plugin_id, 'native', plugin)
|
||||||
logger.debug("[%s] Native content returned None", plugin_id)
|
logger.info("[%s] Native content returned None", plugin_id)
|
||||||
|
|
||||||
# Try to get scroll_helper's cached image (for scrolling plugins like stocks/odds)
|
# Try to get scroll_helper's cached image (for scrolling plugins like stocks/odds)
|
||||||
has_scroll_helper = hasattr(plugin, 'scroll_helper')
|
has_scroll_helper = hasattr(plugin, 'scroll_helper')
|
||||||
logger.debug("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper)
|
logger.info("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper)
|
||||||
content = self._get_scroll_helper_content(plugin, plugin_id, offscreen_only)
|
content = self._get_scroll_helper_content(plugin, plugin_id, offscreen_only)
|
||||||
if content:
|
if content:
|
||||||
total_width = sum(img.width for img in content)
|
total_width = sum(img.width for img in content)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] ScrollHelper content SUCCESS: %d images, %dpx total",
|
"[%s] ScrollHelper content SUCCESS: %d images, %dpx total",
|
||||||
plugin_id, len(content), total_width
|
plugin_id, len(content), total_width
|
||||||
)
|
)
|
||||||
return self._finalize(content, plugin_id, 'scroll_helper', plugin)
|
return self._finalize(content, plugin_id, 'scroll_helper', plugin)
|
||||||
if has_scroll_helper:
|
if has_scroll_helper:
|
||||||
logger.debug("[%s] ScrollHelper content returned None", plugin_id)
|
logger.info("[%s] ScrollHelper content returned None", plugin_id)
|
||||||
|
|
||||||
if offscreen_only:
|
if offscreen_only:
|
||||||
# Display capture needs the shared canvas; leave it to the caller.
|
# Display capture needs the shared canvas; leave it to the caller.
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Needs display capture, deferring to the render thread",
|
"[%s] Needs display capture, deferring to the render thread",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
# Fall back to display capture
|
# Fall back to display capture
|
||||||
logger.debug("[%s] Trying fallback display capture...", plugin_id)
|
logger.info("[%s] Trying fallback display capture...", plugin_id)
|
||||||
content = self._capture_display_content(plugin, plugin_id)
|
content = self._capture_display_content(plugin, plugin_id)
|
||||||
if content:
|
if content:
|
||||||
total_width = sum(img.width for img in content)
|
total_width = sum(img.width for img in content)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback capture SUCCESS: %d images, %dpx total",
|
"[%s] Fallback capture SUCCESS: %d images, %dpx total",
|
||||||
plugin_id, len(content), total_width
|
plugin_id, len(content), total_width
|
||||||
)
|
)
|
||||||
@@ -226,7 +226,7 @@ class PluginAdapter:
|
|||||||
kept.append(result.image)
|
kept.append(result.image)
|
||||||
|
|
||||||
if not kept:
|
if not kept:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] All %d image(s) from %s were blank — contributing nothing",
|
"[%s] All %d image(s) from %s were blank — contributing nothing",
|
||||||
plugin_id, len(images), source
|
plugin_id, len(images), source
|
||||||
)
|
)
|
||||||
@@ -235,14 +235,14 @@ class PluginAdapter:
|
|||||||
trimmed_width = sum(img.width for img in kept)
|
trimmed_width = sum(img.width for img in kept)
|
||||||
|
|
||||||
if trimmed_width < self.config.min_plugin_width:
|
if trimmed_width < self.config.min_plugin_width:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping",
|
"[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping",
|
||||||
plugin_id, trimmed_width, self.config.min_plugin_width
|
plugin_id, trimmed_width, self.config.min_plugin_width
|
||||||
)
|
)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
if trimmed_width != original_width or dropped_blank:
|
if trimmed_width != original_width or dropped_blank:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), "
|
"[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), "
|
||||||
"%d image(s) kept, %d blank dropped",
|
"%d image(s) kept, %d blank dropped",
|
||||||
plugin_id, source, original_width, trimmed_width,
|
plugin_id, source, original_width, trimmed_width,
|
||||||
@@ -431,7 +431,7 @@ class PluginAdapter:
|
|||||||
"""
|
"""
|
||||||
if self._offset_shapes.get(plugin_id) != shape:
|
if self._offset_shapes.get(plugin_id) != shape:
|
||||||
if plugin_id in self._item_offsets:
|
if plugin_id in self._item_offsets:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Content is %s now, was %s — restarting the rotation "
|
"[%s] Content is %s now, was %s — restarting the rotation "
|
||||||
"rather than resuming at a position that no longer means "
|
"rather than resuming at a position that no longer means "
|
||||||
"anything", plugin_id, shape,
|
"anything", plugin_id, shape,
|
||||||
@@ -579,7 +579,7 @@ class PluginAdapter:
|
|||||||
consumed += 1
|
consumed += 1
|
||||||
|
|
||||||
if mode == 'truncate':
|
if mode == 'truncate':
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Width budget %dpx: showing the first %d of %d row(s) "
|
"[%s] Width budget %dpx: showing the first %d of %d row(s) "
|
||||||
"(%dpx incl. gaps); the rest are not shown (overflow=truncate)",
|
"(%dpx incl. gaps); the rest are not shown (overflow=truncate)",
|
||||||
plugin_id, budget, len(selected), len(images), used
|
plugin_id, budget, len(selected), len(images), used
|
||||||
@@ -587,7 +587,7 @@ class PluginAdapter:
|
|||||||
else:
|
else:
|
||||||
self._record_offset(
|
self._record_offset(
|
||||||
plugin_id, (start + consumed) % len(images), shape)
|
plugin_id, (start + consumed) % len(images), shape)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) "
|
"[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) "
|
||||||
"from offset %d; remainder deferred to a later cycle",
|
"from offset %d; remainder deferred to a later cycle",
|
||||||
plugin_id, budget, len(selected), len(images), used, start
|
plugin_id, budget, len(selected), len(images), used, start
|
||||||
@@ -636,7 +636,7 @@ class PluginAdapter:
|
|||||||
if mode != 'truncate':
|
if mode != 'truncate':
|
||||||
self._record_offset(
|
self._record_offset(
|
||||||
plugin_id, 0 if end >= img.width else end, shape)
|
plugin_id, 0 if end >= img.width else end, shape)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Width budget %dpx: cropped continuous %dpx image to "
|
"[%s] Width budget %dpx: cropped continuous %dpx image to "
|
||||||
"[%d:%d] (no item gaps of %dpx+ to align to)%s",
|
"[%d:%d] (no item gaps of %dpx+ to align to)%s",
|
||||||
plugin_id, budget, img.width, offset, end, min_run,
|
plugin_id, budget, img.width, offset, end, min_run,
|
||||||
@@ -674,7 +674,7 @@ class PluginAdapter:
|
|||||||
self._record_offset(
|
self._record_offset(
|
||||||
plugin_id, 0 if end >= img.width else end_index, shape)
|
plugin_id, 0 if end >= img.width else end_index, shape)
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Width budget %dpx: cropped single %dpx image to [%d:%d] "
|
"[%s] Width budget %dpx: cropped single %dpx image to [%d:%d] "
|
||||||
"(%dpx) at item boundaries %d-%d of %d, %s",
|
"(%dpx) at item boundaries %d-%d of %d, %s",
|
||||||
plugin_id, budget, img.width, start, end, end - start,
|
plugin_id, budget, img.width, start, end, end - start,
|
||||||
@@ -698,7 +698,7 @@ class PluginAdapter:
|
|||||||
List of images or None
|
List of images or None
|
||||||
"""
|
"""
|
||||||
try:
|
try:
|
||||||
logger.debug("[%s] Native: calling get_vegas_content()", plugin_id)
|
logger.info("[%s] Native: calling get_vegas_content()", plugin_id)
|
||||||
|
|
||||||
# Tell the plugin how much width the ticker wants it to use, and
|
# 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
|
# 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().
|
# be explicit can read get_vegas_render_width().
|
||||||
render_width = self.resolve_render_width(plugin, plugin_id)
|
render_width = self.resolve_render_width(plugin, plugin_id)
|
||||||
if render_width != self.display_width:
|
if render_width != self.display_width:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: requesting %dpx instead of %dpx",
|
"[%s] Native: requesting %dpx instead of %dpx",
|
||||||
plugin_id, render_width, self.display_width
|
plugin_id, render_width, self.display_width
|
||||||
)
|
)
|
||||||
@@ -735,19 +735,19 @@ class PluginAdapter:
|
|||||||
plugin._vegas_render_width = None
|
plugin._vegas_render_width = None
|
||||||
|
|
||||||
if result is None:
|
if result is None:
|
||||||
logger.debug("[%s] Native: get_vegas_content() returned None", plugin_id)
|
logger.info("[%s] Native: get_vegas_content() returned None", plugin_id)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
# Normalize to list
|
# Normalize to list
|
||||||
if isinstance(result, Image.Image):
|
if isinstance(result, Image.Image):
|
||||||
images = [result]
|
images = [result]
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: got single Image %dx%d",
|
"[%s] Native: got single Image %dx%d",
|
||||||
plugin_id, result.width, result.height
|
plugin_id, result.width, result.height
|
||||||
)
|
)
|
||||||
elif isinstance(result, (list, tuple)):
|
elif isinstance(result, (list, tuple)):
|
||||||
images = list(result)
|
images = list(result)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: got %d items in list/tuple",
|
"[%s] Native: got %d items in list/tuple",
|
||||||
plugin_id, len(images)
|
plugin_id, len(images)
|
||||||
)
|
)
|
||||||
@@ -768,14 +768,14 @@ class PluginAdapter:
|
|||||||
)
|
)
|
||||||
continue
|
continue
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: item[%d] is %dx%d, mode=%s",
|
"[%s] Native: item[%d] is %dx%d, mode=%s",
|
||||||
plugin_id, i, img.width, img.height, img.mode
|
plugin_id, i, img.width, img.height, img.mode
|
||||||
)
|
)
|
||||||
|
|
||||||
# Ensure correct height
|
# Ensure correct height
|
||||||
if img.height != self.display_height:
|
if img.height != self.display_height:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: resizing item[%d]: %dx%d -> %dx%d",
|
"[%s] Native: resizing item[%d]: %dx%d -> %dx%d",
|
||||||
plugin_id, i, img.width, img.height,
|
plugin_id, i, img.width, img.height,
|
||||||
img.width, self.display_height
|
img.width, self.display_height
|
||||||
@@ -793,13 +793,13 @@ class PluginAdapter:
|
|||||||
|
|
||||||
if valid_images:
|
if valid_images:
|
||||||
total_width = sum(img.width for img in valid_images)
|
total_width = sum(img.width for img in valid_images)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Native: SUCCESS - %d images, %dpx total width",
|
"[%s] Native: SUCCESS - %d images, %dpx total width",
|
||||||
plugin_id, len(valid_images), total_width
|
plugin_id, len(valid_images), total_width
|
||||||
)
|
)
|
||||||
return valid_images
|
return valid_images
|
||||||
|
|
||||||
logger.debug("[%s] Native: no valid images after validation", plugin_id)
|
logger.info("[%s] Native: no valid images after validation", plugin_id)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
except (AttributeError, TypeError, ValueError, OSError) as e:
|
except (AttributeError, TypeError, ValueError, OSError) as e:
|
||||||
@@ -833,20 +833,20 @@ class PluginAdapter:
|
|||||||
logger.debug("[%s] No scroll_helper attribute", plugin_id)
|
logger.debug("[%s] No scroll_helper attribute", plugin_id)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Found scroll_helper: %s",
|
"[%s] Found scroll_helper: %s",
|
||||||
plugin_id, type(scroll_helper).__name__
|
plugin_id, type(scroll_helper).__name__
|
||||||
)
|
)
|
||||||
|
|
||||||
cached_image = getattr(scroll_helper, 'cached_image', None)
|
cached_image = getattr(scroll_helper, 'cached_image', None)
|
||||||
if cached_image is None:
|
if cached_image is None:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] scroll_helper.cached_image is None, triggering content generation",
|
"[%s] scroll_helper.cached_image is None, triggering content generation",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
if offscreen_only:
|
if offscreen_only:
|
||||||
# Generating it calls display(), which needs the canvas.
|
# Generating it calls display(), which needs the canvas.
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] scroll_helper cache empty; deferring generation "
|
"[%s] scroll_helper cache empty; deferring generation "
|
||||||
"to the render thread", plugin_id
|
"to the render thread", plugin_id
|
||||||
)
|
)
|
||||||
@@ -859,13 +859,13 @@ class PluginAdapter:
|
|||||||
return None
|
return None
|
||||||
|
|
||||||
if not isinstance(cached_image, Image.Image):
|
if not isinstance(cached_image, Image.Image):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] scroll_helper.cached_image is not an Image: %s",
|
"[%s] scroll_helper.cached_image is not an Image: %s",
|
||||||
plugin_id, type(cached_image).__name__
|
plugin_id, type(cached_image).__name__
|
||||||
)
|
)
|
||||||
return None
|
return None
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] scroll_helper.cached_image found: %dx%d, mode=%s",
|
"[%s] scroll_helper.cached_image found: %dx%d, mode=%s",
|
||||||
plugin_id, cached_image.width, cached_image.height, cached_image.mode
|
plugin_id, cached_image.width, cached_image.height, cached_image.mode
|
||||||
)
|
)
|
||||||
@@ -888,7 +888,7 @@ class PluginAdapter:
|
|||||||
|
|
||||||
# Ensure correct height
|
# Ensure correct height
|
||||||
if img.height != self.display_height:
|
if img.height != self.display_height:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Resizing scroll_helper content: %dx%d -> %dx%d",
|
"[%s] Resizing scroll_helper content: %dx%d -> %dx%d",
|
||||||
plugin_id, img.width, img.height,
|
plugin_id, img.width, img.height,
|
||||||
img.width, self.display_height
|
img.width, self.display_height
|
||||||
@@ -902,7 +902,7 @@ class PluginAdapter:
|
|||||||
if img.mode != 'RGB':
|
if img.mode != 'RGB':
|
||||||
img = img.convert('RGB')
|
img = img.convert('RGB')
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] ScrollHelper content ready: %dx%d",
|
"[%s] ScrollHelper content ready: %dx%d",
|
||||||
plugin_id, img.width, img.height
|
plugin_id, img.width, img.height
|
||||||
)
|
)
|
||||||
@@ -1002,7 +1002,7 @@ class PluginAdapter:
|
|||||||
with self._capture():
|
with self._capture():
|
||||||
# Method 1: Try _create_scrolling_display (stocks pattern)
|
# Method 1: Try _create_scrolling_display (stocks pattern)
|
||||||
if hasattr(plugin, '_create_scrolling_display'):
|
if hasattr(plugin, '_create_scrolling_display'):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Triggering via _create_scrolling_display()",
|
"[%s] Triggering via _create_scrolling_display()",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1010,7 +1010,7 @@ class PluginAdapter:
|
|||||||
plugin._create_scrolling_display()
|
plugin._create_scrolling_display()
|
||||||
cached_image = getattr(scroll_helper, 'cached_image', None)
|
cached_image = getattr(scroll_helper, 'cached_image', None)
|
||||||
if cached_image is not None and isinstance(cached_image, Image.Image):
|
if cached_image is not None and isinstance(cached_image, Image.Image):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] _create_scrolling_display() SUCCESS: %dx%d",
|
"[%s] _create_scrolling_display() SUCCESS: %dx%d",
|
||||||
plugin_id, cached_image.width, cached_image.height
|
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
|
# Method 2: Try display(force_clear=True) which typically builds scroll content
|
||||||
if hasattr(plugin, 'display'):
|
if hasattr(plugin, 'display'):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Triggering via display(force_clear=True)",
|
"[%s] Triggering via display(force_clear=True)",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1031,12 +1031,12 @@ class PluginAdapter:
|
|||||||
plugin.display(force_clear=True)
|
plugin.display(force_clear=True)
|
||||||
cached_image = getattr(scroll_helper, 'cached_image', None)
|
cached_image = getattr(scroll_helper, 'cached_image', None)
|
||||||
if cached_image is not None and isinstance(cached_image, Image.Image):
|
if cached_image is not None and isinstance(cached_image, Image.Image):
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] display(force_clear=True) SUCCESS: %dx%d",
|
"[%s] display(force_clear=True) SUCCESS: %dx%d",
|
||||||
plugin_id, cached_image.width, cached_image.height
|
plugin_id, cached_image.width, cached_image.height
|
||||||
)
|
)
|
||||||
return cached_image
|
return cached_image
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] display(force_clear=True) did not populate cached_image",
|
"[%s] display(force_clear=True) did not populate cached_image",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1045,7 +1045,7 @@ class PluginAdapter:
|
|||||||
"[%s] display(force_clear=True) failed", plugin_id
|
"[%s] display(force_clear=True) failed", plugin_id
|
||||||
)
|
)
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Could not trigger scroll content generation",
|
"[%s] Could not trigger scroll content generation",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1077,15 +1077,15 @@ class PluginAdapter:
|
|||||||
try:
|
try:
|
||||||
# Save current display state
|
# Save current display state
|
||||||
original_image = self.display_manager.image.copy()
|
original_image = self.display_manager.image.copy()
|
||||||
logger.debug("[%s] Fallback: saved original display state", plugin_id)
|
logger.info("[%s] Fallback: saved original display state", plugin_id)
|
||||||
|
|
||||||
# Ensure plugin has fresh data before capturing
|
# Ensure plugin has fresh data before capturing
|
||||||
has_update_data = hasattr(plugin, 'update_data')
|
has_update_data = hasattr(plugin, 'update_data')
|
||||||
logger.debug("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
|
logger.info("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
|
||||||
if has_update_data:
|
if has_update_data:
|
||||||
try:
|
try:
|
||||||
plugin.update_data()
|
plugin.update_data()
|
||||||
logger.debug("[%s] Fallback: update_data() called", plugin_id)
|
logger.info("[%s] Fallback: update_data() called", plugin_id)
|
||||||
except (AttributeError, RuntimeError, OSError):
|
except (AttributeError, RuntimeError, OSError):
|
||||||
logger.exception("[%s] Fallback: update_data() failed", plugin_id)
|
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.
|
# arrangement rather than one that has to be cropped afterwards.
|
||||||
render_width = self.resolve_render_width(plugin, plugin_id)
|
render_width = self.resolve_render_width(plugin, plugin_id)
|
||||||
if render_width != self.display_width:
|
if render_width != self.display_width:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: rendering at %dpx instead of %dpx",
|
"[%s] Fallback: rendering at %dpx instead of %dpx",
|
||||||
plugin_id, render_width, self.display_width
|
plugin_id, render_width, self.display_width
|
||||||
)
|
)
|
||||||
|
|
||||||
with self._capture(), self._render_at(render_width):
|
with self._capture(), self._render_at(render_width):
|
||||||
self.display_manager.clear()
|
self.display_manager.clear()
|
||||||
logger.debug("[%s] Fallback: display cleared, calling display()", plugin_id)
|
logger.info("[%s] Fallback: display cleared, calling display()", plugin_id)
|
||||||
|
|
||||||
# First try without force_clear (some plugins behave better this way)
|
# First try without force_clear (some plugins behave better this way)
|
||||||
try:
|
try:
|
||||||
plugin.display()
|
plugin.display()
|
||||||
logger.debug("[%s] Fallback: display() called successfully", plugin_id)
|
logger.info("[%s] Fallback: display() called successfully", plugin_id)
|
||||||
except TypeError:
|
except TypeError:
|
||||||
# Plugin may require force_clear argument
|
# Plugin may require force_clear argument
|
||||||
logger.debug("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id)
|
logger.info("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id)
|
||||||
plugin.display(force_clear=True)
|
plugin.display(force_clear=True)
|
||||||
|
|
||||||
# Capture the result
|
# Capture the result
|
||||||
captured = self.display_manager.image.copy()
|
captured = self.display_manager.image.copy()
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: captured frame %dx%d, mode=%s",
|
"[%s] Fallback: captured frame %dx%d, mode=%s",
|
||||||
plugin_id, captured.width, captured.height, captured.mode
|
plugin_id, captured.width, captured.height, captured.mode
|
||||||
)
|
)
|
||||||
|
|
||||||
# Check if captured image has content (not all black)
|
# Check if captured image has content (not all black)
|
||||||
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
|
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)",
|
"[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)",
|
||||||
plugin_id, bright_ratio * 100
|
plugin_id, bright_ratio * 100
|
||||||
)
|
)
|
||||||
|
|
||||||
if is_blank:
|
if is_blank:
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: first capture blank, retrying with force_clear",
|
"[%s] Fallback: first capture blank, retrying with force_clear",
|
||||||
plugin_id
|
plugin_id
|
||||||
)
|
)
|
||||||
@@ -1142,7 +1142,7 @@ class PluginAdapter:
|
|||||||
captured = self.display_manager.image.copy()
|
captured = self.display_manager.image.copy()
|
||||||
|
|
||||||
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
|
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: retry brightness - %.3f%% bright pixels",
|
"[%s] Fallback: retry brightness - %.3f%% bright pixels",
|
||||||
plugin_id, bright_ratio * 100
|
plugin_id, bright_ratio * 100
|
||||||
)
|
)
|
||||||
@@ -1159,7 +1159,7 @@ class PluginAdapter:
|
|||||||
if captured.mode != 'RGB':
|
if captured.mode != 'RGB':
|
||||||
captured = captured.convert('RGB')
|
captured = captured.convert('RGB')
|
||||||
|
|
||||||
logger.debug(
|
logger.info(
|
||||||
"[%s] Fallback: SUCCESS - captured %dx%d",
|
"[%s] Fallback: SUCCESS - captured %dx%d",
|
||||||
plugin_id, captured.width, captured.height
|
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.
|
secret fields in plugin configurations based on JSON Schema x-secret markers.
|
||||||
"""
|
"""
|
||||||
|
|
||||||
from typing import Any, Dict, Set, Tuple
|
from typing import Any, Dict, Optional, Set, Tuple
|
||||||
|
|
||||||
|
|
||||||
def find_secret_fields(properties: Dict[str, Any], prefix: str = '') -> Set[str]:
|
def find_secret_fields(properties: Dict[str, Any], prefix: str = '') -> Set[str]:
|
||||||
@@ -202,11 +202,89 @@ def remove_empty_secrets(secrets: Dict[str, Any]) -> Dict[str, Any]:
|
|||||||
nested = remove_empty_secrets(v)
|
nested = remove_empty_secrets(v)
|
||||||
if nested:
|
if nested:
|
||||||
result[k] = 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() == ''):
|
elif v is not None and not (isinstance(v, str) and v.strip() == ''):
|
||||||
result[k] = v
|
result[k] = v
|
||||||
return result
|
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]:
|
def strip_masked_values(secrets: Dict[str, Any]) -> Dict[str, Any]:
|
||||||
"""Remove values a client echoed back rather than changed.
|
"""Remove values a client echoed back rather than changed.
|
||||||
|
|
||||||
|
|||||||
@@ -1,119 +0,0 @@
|
|||||||
"""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
|
|
||||||
@@ -1,137 +0,0 @@
|
|||||||
"""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,27 +183,15 @@ class TestSetupLogging:
|
|||||||
setup_logging()
|
setup_logging()
|
||||||
assert len(logging.getLogger().handlers) == 1
|
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):
|
def test_json_format_selects_structured_formatter(self):
|
||||||
setup_logging(format_type="json")
|
setup_logging(format_type="json")
|
||||||
assert isinstance(self._selected_formatter(), StructuredFormatter)
|
assert isinstance(
|
||||||
|
logging.getLogger().handlers[0].formatter, StructuredFormatter)
|
||||||
|
|
||||||
def test_readable_format_selects_contextual_formatter(self):
|
def test_readable_format_selects_contextual_formatter(self):
|
||||||
setup_logging(format_type="readable")
|
setup_logging(format_type="readable")
|
||||||
assert isinstance(self._selected_formatter(), ContextualFormatter)
|
assert isinstance(
|
||||||
|
logging.getLogger().handlers[0].formatter, ContextualFormatter)
|
||||||
|
|
||||||
def test_log_file_adds_file_handler(self, tmp_path):
|
def test_log_file_adds_file_handler(self, tmp_path):
|
||||||
log_file = tmp_path / "test.log"
|
log_file = tmp_path / "test.log"
|
||||||
|
|||||||
@@ -1,128 +0,0 @@
|
|||||||
"""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
|
|
||||||
@@ -11,7 +11,7 @@ Focus areas:
|
|||||||
import time
|
import time
|
||||||
|
|
||||||
import pytest
|
import pytest
|
||||||
from unittest.mock import MagicMock, patch
|
from unittest.mock import MagicMock
|
||||||
|
|
||||||
from src.plugin_system.resource_monitor import (
|
from src.plugin_system.resource_monitor import (
|
||||||
PluginResourceMonitor,
|
PluginResourceMonitor,
|
||||||
@@ -127,87 +127,3 @@ class TestForceReload:
|
|||||||
fresh = mon.get_metrics_summary("p", force_reload=True)
|
fresh = mon.get_metrics_summary("p", force_reload=True)
|
||||||
assert fresh["call_count"] == 7
|
assert fresh["call_count"] == 7
|
||||||
assert any(c.kwargs.get("memory_ttl") == 0 for c in cache.get.call_args_list)
|
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"
|
|
||||||
|
|||||||
@@ -1,99 +0,0 @@
|
|||||||
"""Frame pacing and FPS health reporting must not depend on the wall clock.
|
|
||||||
|
|
||||||
These devices have no RTC, so the system clock jumps by however wrong boot
|
|
||||||
time was the moment NTP first syncs. The render loop sleeps the *remainder*
|
|
||||||
of each frame budget:
|
|
||||||
|
|
||||||
frame_elapsed = <now> - frame_started
|
|
||||||
time.sleep(max(0.0, frame_interval - frame_elapsed))
|
|
||||||
|
|
||||||
With a wall-clock `now`, a backward jump makes frame_elapsed negative, so
|
|
||||||
`frame_interval - frame_elapsed` exceeds the whole budget and the render loop
|
|
||||||
stalls for the size of the correction. A forward jump instead inflates the
|
|
||||||
p99 and worst-frame numbers the telemetry reports.
|
|
||||||
"""
|
|
||||||
import ast
|
|
||||||
import sys
|
|
||||||
from pathlib import Path
|
|
||||||
|
|
||||||
sys.path.insert(0, str(Path(__file__).resolve().parent.parent))
|
|
||||||
|
|
||||||
COORD = (Path(__file__).resolve().parent.parent
|
|
||||||
/ "src" / "vegas_mode" / "coordinator.py")
|
|
||||||
TREE = ast.parse(COORD.read_text(encoding="utf-8"))
|
|
||||||
|
|
||||||
|
|
||||||
def _assignments_of(name):
|
|
||||||
"""Every `name = <expr>` in the module, as unparsed source."""
|
|
||||||
out = []
|
|
||||||
for node in ast.walk(TREE):
|
|
||||||
if isinstance(node, ast.Assign):
|
|
||||||
for target in node.targets:
|
|
||||||
if isinstance(target, ast.Name) and target.id == name:
|
|
||||||
out.append((node.lineno, ast.unparse(node.value)))
|
|
||||||
return out
|
|
||||||
|
|
||||||
|
|
||||||
def test_per_frame_timestamps_are_monotonic():
|
|
||||||
for name in ("frame_started", "frame_elapsed"):
|
|
||||||
assigns = _assignments_of(name)
|
|
||||||
assert assigns, f"{name} is no longer assigned -- has the loop changed?"
|
|
||||||
for lineno, expr in assigns:
|
|
||||||
assert "time.time()" not in expr, (
|
|
||||||
f"{name} at line {lineno} uses the wall clock ({expr!r}). A "
|
|
||||||
"backward NTP step makes the per-frame delta negative and the "
|
|
||||||
"loop then sleeps longer than the whole frame budget.")
|
|
||||||
assert "time.monotonic()" in expr, (
|
|
||||||
f"{name} at line {lineno} is {expr!r}, expected monotonic")
|
|
||||||
|
|
||||||
|
|
||||||
def test_the_fps_window_is_monotonic():
|
|
||||||
for lineno, expr in _assignments_of("current_time"):
|
|
||||||
assert "time.monotonic()" in expr, (
|
|
||||||
f"current_time at line {lineno} is {expr!r}; fps is frames divided "
|
|
||||||
"by this delta, so a clock step would corrupt the rate itself")
|
|
||||||
|
|
||||||
|
|
||||||
def test_health_state_is_not_reset_every_iteration():
|
|
||||||
"""run_iteration() runs once per cycle -- locals here reset every few seconds.
|
|
||||||
|
|
||||||
As locals, `last_fps_health_log = 0.0` made the 300s heartbeat fire on the
|
|
||||||
first sample of every iteration, and a recovery spanning two iterations was
|
|
||||||
never reported because was_degraded had already gone back to False.
|
|
||||||
"""
|
|
||||||
run_iteration = next(
|
|
||||||
(n for n in ast.walk(TREE)
|
|
||||||
if isinstance(n, ast.FunctionDef) and n.name == "run_iteration"), None)
|
|
||||||
assert run_iteration is not None, "run_iteration() not found"
|
|
||||||
|
|
||||||
local_names = {t.id for n in ast.walk(run_iteration)
|
|
||||||
if isinstance(n, ast.Assign)
|
|
||||||
for t in n.targets if isinstance(t, ast.Name)}
|
|
||||||
for leaked in ("last_fps_health_log", "was_degraded"):
|
|
||||||
assert leaked not in local_names, (
|
|
||||||
f"{leaked} is a local of run_iteration() again, so it resets every "
|
|
||||||
"cycle -- the heartbeat degenerates to once per iteration")
|
|
||||||
|
|
||||||
body = ast.unparse(run_iteration)
|
|
||||||
assert "self._fps_last_health_log" in body and "self._fps_was_degraded" in body, (
|
|
||||||
"the health state should live on the coordinator, across iterations")
|
|
||||||
|
|
||||||
|
|
||||||
def test_start_clears_stale_health_state():
|
|
||||||
"""A new run must not inherit "was degraded" from the previous one."""
|
|
||||||
start = next((n for n in ast.walk(TREE)
|
|
||||||
if isinstance(n, ast.FunctionDef) and n.name == "start"), None)
|
|
||||||
assert start is not None, "start() not found"
|
|
||||||
body = ast.unparse(start)
|
|
||||||
assert "self._fps_last_health_log" in body and "self._fps_was_degraded" in body, (
|
|
||||||
"start() does not reset the FPS health state")
|
|
||||||
|
|
||||||
|
|
||||||
def test_the_degraded_threshold_is_documented():
|
|
||||||
"""The 90% band is deliberate; say so where the constant is defined."""
|
|
||||||
source = COORD.read_text(encoding="utf-8")
|
|
||||||
idx = source.index("_FPS_HEALTHY_FRACTION = ")
|
|
||||||
preamble = source[max(0, idx - 700):idx]
|
|
||||||
assert "90%" in preamble or "0.9" in preamble, (
|
|
||||||
"the degradation threshold is not explained at its definition, so "
|
|
||||||
"'below target' reads as a bug rather than a deliberate band")
|
|
||||||
@@ -1,73 +0,0 @@
|
|||||||
"""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,6 +229,44 @@ class TestSavePluginConfig:
|
|||||||
"REAL-KEY-0123456789", "an unrelated edit destroyed the API key"
|
"REAL-KEY-0123456789", "an unrelated edit destroyed the API key"
|
||||||
assert env.fresh_load()[PLUGIN_ID]["city"] == "Dallas"
|
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):
|
def test_a_secret_can_still_be_changed(self, env):
|
||||||
"""Dropping blanks must not stop a real new value from being saved."""
|
"""Dropping blanks must not stop a real new value from being saved."""
|
||||||
self._save(env, {"api_key": "first-key"})
|
self._save(env, {"api_key": "first-key"})
|
||||||
|
|||||||
@@ -0,0 +1,45 @@
|
|||||||
|
"""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,6 +17,7 @@ from src.web_interface.secret_helpers import (
|
|||||||
separate_secrets,
|
separate_secrets,
|
||||||
mask_secret_fields,
|
mask_secret_fields,
|
||||||
mask_all_secret_values,
|
mask_all_secret_values,
|
||||||
|
merge_secrets,
|
||||||
remove_empty_secrets,
|
remove_empty_secrets,
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -239,3 +240,67 @@ class TestRemoveEmptySecrets:
|
|||||||
def test_keeps_falsey_non_string_values(self):
|
def test_keeps_falsey_non_string_values(self):
|
||||||
# 0 and False are neither None nor blank strings — they are kept.
|
# 0 and False are neither None nor blank strings — they are kept.
|
||||||
assert remove_empty_secrets({"a": 0, "b": False}) == {"a": 0, "b": False}
|
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"]
|
||||||
|
|||||||
@@ -22,7 +22,8 @@ logger = logging.getLogger(__name__)
|
|||||||
from src.web_interface.api_helpers import success_response, error_response, validate_request_json
|
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.errors import ErrorCode
|
||||||
from src.web_interface.secret_helpers import (find_secret_fields, mask_all_secret_values,
|
from src.web_interface.secret_helpers import (find_secret_fields, mask_all_secret_values,
|
||||||
remove_empty_secrets, separate_secrets,
|
merge_secrets, remove_empty_secrets,
|
||||||
|
separate_secrets,
|
||||||
strip_masked_values)
|
strip_masked_values)
|
||||||
from src.web_interface.error_handler import describe_exception, redact_text
|
from src.web_interface.error_handler import describe_exception, redact_text
|
||||||
from src.plugin_system.operation_types import OperationType
|
from src.plugin_system.operation_types import OperationType
|
||||||
@@ -1296,7 +1297,10 @@ def save_main_config():
|
|||||||
if secrets_config:
|
if secrets_config:
|
||||||
if plugin_id not in current_secrets:
|
if plugin_id not in current_secrets:
|
||||||
current_secrets[plugin_id] = {}
|
current_secrets[plugin_id] = {}
|
||||||
current_secrets[plugin_id] = deep_merge(current_secrets[plugin_id], secrets_config)
|
# 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)
|
||||||
# Save secrets file
|
# Save secrets file
|
||||||
api_v3.config_manager.save_raw_file_content('secrets', current_secrets)
|
api_v3.config_manager.save_raw_file_content('secrets', current_secrets)
|
||||||
|
|
||||||
@@ -5675,8 +5679,10 @@ def save_plugin_config():
|
|||||||
if schema:
|
if schema:
|
||||||
# Log what we're validating for debugging
|
# Log what we're validating for debugging
|
||||||
logger.info(f"Validating config for {plugin_id}")
|
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"Config keys being validated: {list(plugin_config.keys())}")
|
||||||
logger.info(f"Full config: {plugin_config}")
|
|
||||||
|
|
||||||
# Get enhanced schema keys (including injected core properties)
|
# Get enhanced schema keys (including injected core properties)
|
||||||
# We need to create an enhanced schema to get the actual allowed keys
|
# We need to create an enhanced schema to get the actual allowed keys
|
||||||
@@ -5699,7 +5705,8 @@ def save_plugin_config():
|
|||||||
# Log validation errors for debugging
|
# Log validation errors for debugging
|
||||||
logger.error(f"Config validation failed for {plugin_id}")
|
logger.error(f"Config validation failed for {plugin_id}")
|
||||||
logger.error(f"Validation errors: {validation_errors}")
|
logger.error(f"Validation errors: {validation_errors}")
|
||||||
logger.error(f"Config that failed: {plugin_config}")
|
# Keys only, for the same reason as above.
|
||||||
|
logger.error(f"Config keys that failed: {list(plugin_config.keys())}")
|
||||||
logger.error(f"Schema properties: {list(enhanced_schema.get('properties', {}).keys())}")
|
logger.error(f"Schema properties: {list(enhanced_schema.get('properties', {}).keys())}")
|
||||||
|
|
||||||
# Also print to console for immediate visibility
|
# Also print to console for immediate visibility
|
||||||
@@ -5750,7 +5757,9 @@ def save_plugin_config():
|
|||||||
if secrets_config:
|
if secrets_config:
|
||||||
if plugin_id not in current_secrets:
|
if plugin_id not in current_secrets:
|
||||||
current_secrets[plugin_id] = {}
|
current_secrets[plugin_id] = {}
|
||||||
current_secrets[plugin_id] = deep_merge(current_secrets[plugin_id], secrets_config)
|
# See above -- secrets lists must merge element-wise.
|
||||||
|
current_secrets[plugin_id] = merge_secrets(
|
||||||
|
current_secrets[plugin_id], secrets_config)
|
||||||
# Save secrets file
|
# Save secrets file
|
||||||
try:
|
try:
|
||||||
api_v3.config_manager.save_raw_file_content('secrets', current_secrets)
|
api_v3.config_manager.save_raw_file_content('secrets', current_secrets)
|
||||||
|
|||||||
@@ -126,7 +126,17 @@ window.showRestartPending = function(message) {
|
|||||||
} catch { /* private browsing */ }
|
} catch { /* private browsing */ }
|
||||||
const banner = document.getElementById('restart-pending-banner');
|
const banner = document.getElementById('restart-pending-banner');
|
||||||
const text = document.getElementById('restart-pending-text');
|
const text = document.getElementById('restart-pending-text');
|
||||||
if (text && message) text.textContent = message;
|
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 (banner) banner.style.display = 'block';
|
if (banner) banner.style.display = 'block';
|
||||||
};
|
};
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user