Compare commits

..
Author SHA1 Message Date
ChuckBuilds 73fff8d2d5 test(systemd): pin the arena value instead of accepting a range
Review follow-up. The range check accepted 1, 3 and 4, so a change to 4 --
which hands most of the resident saving back -- passed a test whose whole
purpose is to notice that.

Pinned to the value the unit ships, in one named constant. Raising it is still
a legitimate response to a frame-time regression, but it should be a visible
edit here rather than silent drift, and the failure message says so.

Mutation-checked: changing the unit to 4 now fails.
2026-08-20 01:55:14 -04:00
ChuckBuilds 446207ffbc perf(systemd): cap glibc malloc arenas on the display service
Measured on a live rig 2.5 hours after start:

    RSS                          1030 MB
    Private_Dirty                 988 MB
    anonymous mappings > 10 MB       23
    largest        104, 79, 66, 63, 63 MB, on 64 MB-aligned addresses
    threads                           9
    cores                             3   -> glibc ceiling = 8 x 3 = 24 arenas

23 against a ceiling of 24, all 64 MB-aligned: these are glibc's per-thread
malloc arenas, not live objects. The data the process was actually holding
accounts for perhaps 15 MB -- the widest scroll strip observed was 35,746 x 64,
about 7 MB as RGB and the same again for its numpy mirror.

It is bloat rather than a leak: sampled four times over 135 seconds, RSS sat
between 990 and 1030 MB rather than climbing. glibc gives each allocating
thread its own arena, grows them to hold peak demand, and never gives them
back. A process that builds and drops large images across several threads is
exactly the shape that produces this.

The device had 59 MB free at the time, on 1845 MB total.

MALLOC_ARENA_MAX=2 trades a little allocator concurrency for that resident
memory. It is a tuning knob rather than a fix for a defect, so the rationale
and the measurements sit next to it in the unit file, and a test asserts they
stay there -- a bare environment variable invites removal by whoever meets it
next.

Two things this is NOT, both checked rather than assumed:

- Not an OOM problem today. A grep for "oom" in the service journal returned
  24 matches, all of which were the radar logging zoom=9 and zoom=7. The kernel
  OOM killer has not fired: dmesg has zero matches.
- Not currently capped by the unit's MemoryMax=85% either. That directive is in
  this file but absent from the unit actually installed on the rig, which
  reports MemoryMax=infinity, so nothing is enforcing a ceiling there.

The saving is unmeasured on hardware: applying it needs a service restart,
which blanks the panel, so that is the user's call rather than something to do
mid-audit. If p99 frame time regresses -- it sits at 18.4 ms against a 16.7 ms
budget for 60 FPS, so there is not much headroom -- raise the value rather than
remove it.
2026-08-20 00:17:27 -04:00
13 changed files with 185 additions and 700 deletions
+1 -1
View File
@@ -328,7 +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
self.logger.debug( self.logger.info(
"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 -66
View File
@@ -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,66 +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 is the journal.
systemd sets JOURNAL_STREAM for services whose output it captures. Without
this check the "<N>" prefixes would show up as literal noise when the
program is run from a terminal, in the emulator, or in tests.
"""
return bool(os.environ.get("JOURNAL_STREAM"))
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.
-21
View File
@@ -178,20 +178,10 @@ 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
@@ -209,17 +199,6 @@ class PluginHealthTracker:
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
# 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) 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:
+14 -100
View File
@@ -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,50 +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))
usable = {k: v for k, v in cached.items() if k in known}
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}"
@@ -188,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
@@ -294,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:
@@ -415,37 +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.
now = time.monotonic()
if not force and now - self._metrics_persisted_at.get(plugin_id, 0.0) \
< _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:
@@ -453,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)
+54 -54
View File
@@ -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
) )
+12
View File
@@ -8,6 +8,18 @@ Type=simple
User=root User=root
WorkingDirectory=__PROJECT_ROOT_DIR__ WorkingDirectory=__PROJECT_ROOT_DIR__
Environment=PYTHONDONTWRITEBYTECODE=1 Environment=PYTHONDONTWRITEBYTECODE=1
# glibc gives each allocating thread its own malloc arena, up to 8 x CPU count,
# and an arena that has grown is never handed back to the OS. This process runs
# 9 threads on a 3-core Pi, so the ceiling is 24 arenas -- and a rig measured at
# 1030 MB resident held 23 large anonymous mappings on 64 MB-aligned addresses,
# 920 MB of them, while the live data it was actually holding (widest scroll
# strip seen: 35,746 x 64) accounts for roughly 15 MB. That gap is arena bloat,
# not leaked objects: RSS was flat across repeated sampling, not climbing.
#
# Capping the arenas trades a little allocator concurrency for a large amount of
# resident memory on a device that has neither to spare. 2 is the usual value;
# raise it if frame times regress.
Environment=MALLOC_ARENA_MAX=2
ExecStart=/usr/bin/python3 __PROJECT_ROOT_DIR__/run.py ExecStart=/usr/bin/python3 __PROJECT_ROOT_DIR__/run.py
# Restart=always, not on-failure: run.py exiting 0 (a clean shutdown path taken # Restart=always, not on-failure: run.py exiting 0 (a clean shutdown path taken
# for a reason that no longer applies, e.g. a config reload) would otherwise leave # for a reason that no longer applies, e.g. a config reload) would otherwise leave
-110
View File
@@ -1,110 +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 pytest
from src.plugin_system.plugin_health import PluginHealthTracker, CircuitState
class _Cache:
"""Counts writes; serves back whatever was last written."""
def __init__(self):
self.store = {}
self.writes = 0
def set(self, key, data, ttl=None, **kwargs):
self.writes += 1
self.store[key] = data
def get(self, key, max_age=None, memory_ttl=None, **kwargs):
return 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
-101
View File
@@ -1,101 +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
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 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": "8:12345"}):
assert _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": "8:1"}, 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()
+4 -16
View File
@@ -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"
-100
View File
@@ -1,100 +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)
def test_values_of_the_wrong_type_do_not_raise():
"""A dataclass will accept these, but a later float() on them would not."""
metrics = _monitor({"call_count": "not a number"}).get_metrics("plugin-f")
assert isinstance(metrics, ResourceMetrics)
-64
View File
@@ -127,67 +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_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"
+95
View File
@@ -0,0 +1,95 @@
"""The display unit must cap glibc's malloc arenas.
glibc hands each allocating thread its own malloc arena, up to 8 x CPU count,
and an arena that has grown is never returned to the OS. This process runs
threads for the render loop, the update workers and the background fetchers, so
on a 3-core Pi the ceiling is 24 arenas.
Measured on a live rig, 2.5 hours in:
RSS 1030 MB
Private_Dirty 988 MB
anonymous mappings > 10 MB 23 (ceiling is 8 x 3 = 24)
largest few 104, 79, 66, 63, 63 MB, on 64 MB-aligned addresses
against live data that accounts for perhaps 15 MB -- the widest scroll strip
observed was 35,746 x 64, about 7 MB as RGB and the same again for its numpy
mirror. Repeated sampling showed RSS flat between 990 and 1030 MB rather than
climbing, so this is arena bloat rather than a leak: memory Python has freed
but glibc is holding per-arena.
The device had 59 MB free at the time.
Capping the arena count trades a little allocator concurrency for that resident
memory. The render loop is latency-sensitive, so if p99 frame time regresses the
right response is to raise this rather than remove it.
"""
import re
from pathlib import Path
import pytest
UNIT = (Path(__file__).resolve().parent.parent / "systemd" / "ledmatrix.service")
#: The value the unit is expected to carry. 2 is the usual choice for a
#: threaded Python process; 1-4 all keep some of the saving, but only one of
#: them is what this project ships.
EXPECTED_ARENA_MAX = 2
def _environment(unit_text):
return dict(
line.split("=", 2)[1:3] if line.count("=") >= 2 else (line.split("=", 1)[1], "")
for line in unit_text.splitlines()
if line.startswith("Environment=")
)
def test_the_unit_exists():
assert UNIT.is_file(), f"{UNIT} is missing"
def test_malloc_arena_max_is_capped():
env = _environment(UNIT.read_text(encoding="utf-8"))
assert "MALLOC_ARENA_MAX" in env, (
"the display unit does not cap glibc arenas; on a 3-core Pi the default "
"ceiling is 24 and a measured rig held 23 of them, 920 MB"
)
value = int(env["MALLOC_ARENA_MAX"])
# Pinned, not a range. A range let a change to 4 -- which hands most of the
# saving back -- pass unnoticed, which was the point of the finding that
# prompted this. Raising it is a legitimate response to a frame-time
# regression, but it should be a visible edit here rather than a silent
# drift, so the number lives in one place and changing it shows up in
# review.
assert value == EXPECTED_ARENA_MAX, (
f"MALLOC_ARENA_MAX={value}, expected {EXPECTED_ARENA_MAX}. If this was "
"raised deliberately because frame times regressed, update "
"EXPECTED_ARENA_MAX here and say so in the commit."
)
def test_the_reason_is_recorded_next_to_it():
"""A bare tuning knob invites removal by whoever meets it next."""
text = UNIT.read_text(encoding="utf-8")
index = text.index("Environment=MALLOC_ARENA_MAX")
preamble = text[:index].splitlines()[-12:]
comment = "\n".join(line for line in preamble if line.startswith("#"))
assert "arena" in comment.lower(), "no explanation precedes the setting"
assert re.search(r"\d", comment), (
"the explanation cites no measurement, so a reader cannot tell whether "
"it still applies to their hardware"
)
@pytest.mark.parametrize("unit", ["ledmatrix.service"])
def test_the_unit_still_parses_as_ini(unit):
"""systemd will refuse a malformed unit, and the panel stays dark."""
import configparser
path = UNIT.parent / unit
parser = configparser.ConfigParser(strict=False)
# systemd allows repeated keys; ConfigParser needs them merged, not rejected.
parser.read_string(path.read_text(encoding="utf-8"))
assert parser.has_section("Service")
assert parser.has_option("Service", "ExecStart")
-63
View File
@@ -1,63 +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 _info_calls(path):
"""Direct logger.info(...) 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 == "info"
and getattr(node.func.value, "id", None) == "logger"):
found.append(node.lineno)
return found
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."""
source = ADAPTER.read_text(encoding="utf-8")
loud = sum(source.count(f"logger.{level}(")
for level in ("warning", "error", "exception"))
assert loud >= 15, f"only {loud} warning/error/exception calls remain"
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