perf(health): stop rewriting a health record on every healthy 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 surfaces for display and that nothing reads back after a
restart. Nothing alerts on the age of last_successful_update; it is carried in
the metrics dataclass and shown.

Measured on a rig running 24 plugins, all steady-state (0 consecutive
failures, circuit closed): a five-minute sample caught 22 health-file
rewrites, about 4.4 a minute or 6,300 a day. Each write is ~400 bytes through
cache_manager.set(), which writes a file per call, so each one costs a
filesystem block plus an ext4 journal write.

That lands on an SD card, where the unit of cost is an erase-block cycle
rather than the bytes involved, and where wear is what eventually kills the
card. Two cards have already failed on the other rig with the same
signature -- unreadable block device, EIO on exec, sshd unable to read its
host keys.

The circuit breaker still has to survive a restart, so the write is kept for
exactly the fields it is rebuilt from: consecutive_failures, circuit_state,
circuit_opened_time, half_open_start_time. A failure, a circuit opening and a
recovery are all still written the moment they happen. In-memory state is
updated every time either way, so the health API and web UI show what they
always did.

Tested: 100 healthy cycles now perform zero writes after the first, the
counters remain accurate in memory, and a failure, a recovery and a
half-open-to-closed transition each still reach disk. One test kills and
rebuilds the tracker from the cache to prove the breaker's state genuinely
survives what is no longer written.

Mutation-checked both ways: persisting unconditionally again fails the
steady-state test, and widening _DURABLE_FIELDS to include last_success_time
fails it too. The 46 existing health tests pass.

src/common/scroll_helper.py

@@ -328,7 +328,7 @@ class ScrollHelper:
             elapsed_time = current_time - (self.scroll_start_time or current_time)
             # The image already includes display_width padding, so we only need total_scroll_width
             required_total_distance = self.total_scroll_width
-            self.logger.debug(
+            self.logger.info(
                 "Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
                 elapsed_time,
                 self.calculated_duration,

src/logging_config.py

@@ -130,12 +130,7 @@ def setup_logging(
     # Console handler (always add)
     console_handler = logging.StreamHandler(sys.stdout)
     console_handler.setLevel(level)
-    # Under systemd, tag each line so the journal records the real severity
-    # rather than filing everything as informational. The file handler below
-    # keeps the plain formatter: the prefix is meaningful to journald and noise
-    # anywhere else.
-    console_handler.setFormatter(
-        JournalPriorityFormatter(formatter) if _under_systemd() else formatter)
+    console_handler.setFormatter(formatter)
     root_logger.addHandler(console_handler)
     
     # 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")
 
 
-#: 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):
     """LoggerAdapter that stamps every record with its plugin_id.
 

src/plugin_system/resource_monitor.py

@@ -9,7 +9,7 @@ import time
 import logging
 import threading
 from typing import Dict, Optional, Any, Callable
-from dataclasses import dataclass, field, fields
+from dataclasses import dataclass, field
 
 try:
     import psutil
@@ -49,20 +49,6 @@ class ResourceMetrics:
             self.total_execution_time = self.total_execution_time / self.call_count
 
 
-#: How often a plugin's metrics are written to the cache, in seconds.
-#:
-#: Persisting on every call meant a small file rewritten roughly nine times a
-#: minute per plugin. On a rig with fourteen active plugins that was ~126
-#: writes a minute for metrics alone, and since each ~350-byte file costs a
-#: 4KB block plus an ext4 journal entry, it dominated the device's write
-#: volume -- on an SD card, which wears out.
-#:
-#: The in-memory copy stays authoritative and exact; only the cross-process
-#: snapshot the web UI reads is delayed, and telemetry up to half a minute old
-#: is still a fair description of a long-running plugin.
-_METRICS_PERSIST_INTERVAL = 30.0
-
-
 class PluginResourceMonitor:
     """
     Monitors resource usage for plugins.
@@ -89,10 +75,6 @@ class PluginResourceMonitor:
         # Resource metrics per plugin
         self._metrics: Dict[str, ResourceMetrics] = {}
         self._limits: Dict[str, ResourceLimits] = {}
-        # When each plugin's metrics last reached the cache. Metrics change on
-        # every call, so they cannot be de-duplicated the way health state can;
-        # they are rate-limited instead. See _METRICS_PERSIST_INTERVAL.
-        self._metrics_persisted_at: Dict[str, float] = {}
 
         # Thread-local storage for execution tracking
         self._local = threading.local()
@@ -120,50 +102,6 @@ class PluginResourceMonitor:
                 "psutil not available - resource monitoring will be limited to execution time only"
             )
     
-    def _metrics_from_cache(self, plugin_id: str, cached: Any) -> "ResourceMetrics":
-        """Build metrics from a cached record, ignoring anything unrecognised.
-
-        ResourceMetrics(**cached) raises TypeError on a single unexpected key,
-        and that exception escapes into plugin_manager, which reports it as
-        "plugin <id> operation failed". Every plugin fails, and the plugin
-        system never finishes initialising.
-
-        Seen on a live rig: every plugin failing with
-
-            ResourceMetrics.__init__() got an unexpected keyword argument
-            'consecutive_failures'
-
-        which is a plugin_health field, not a metrics one. How a health-shaped
-        record came to sit under a plugin_metrics key on that machine is not
-        established -- a restored backup that mixed two machines' caches is the
-        likeliest explanation -- but the loader should not be brittle enough for
-        it to matter. plugin_health already repairs its records field by field
-        rather than trusting whatever is on disk; this does the same.
-
-        Unknown keys are dropped and named once, so a genuine schema change is
-        visible in the log instead of silently discarded.
-        """
-        if not isinstance(cached, dict):
-            self.logger.warning(
-                "Ignoring cached metrics for %s: expected a mapping, got %s",
-                plugin_id, type(cached).__name__)
-            return ResourceMetrics()
-
-        known = {f.name for f in fields(ResourceMetrics)}
-        unknown = sorted(set(cached) - known)
-        if unknown:
-            self.logger.warning(
-                "Dropping unrecognised field(s) from cached metrics for %s: %s",
-                plugin_id, ", ".join(unknown))
-        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:
         """Get cache key for plugin metrics."""
         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
                 )
                 if cached:
-                    metrics = self._metrics_from_cache(plugin_id, cached)
+                    metrics = ResourceMetrics(**cached)
                 else:
                     metrics = ResourceMetrics()
                 self._metrics[plugin_id] = metrics
@@ -294,8 +232,18 @@ class PluginResourceMonitor:
                     # CPU is harder to measure per-call, so we track it separately
                     metrics.cpu_percent = self._get_process_cpu_percent()
                 
-                # Persist metrics, at most once per interval per plugin.
-                self._persist_metrics(plugin_id, metrics)
+                # Persist metrics
+                cache_key = self._get_metrics_key(plugin_id)
+                self.cache_manager.set(cache_key, {
+                    'memory_mb': metrics.memory_mb,
+                    'cpu_percent': metrics.cpu_percent,
+                    'execution_time': metrics.execution_time,
+                    'call_count': metrics.call_count,
+                    'total_execution_time': metrics.total_execution_time,
+                    'max_execution_time': metrics.max_execution_time,
+                    'min_execution_time': metrics.min_execution_time if metrics.min_execution_time != float('inf') else 0.0,
+                    'last_update_time': metrics.last_update_time
+                })
             
             # Check limits
             if limits:
@@ -415,37 +363,6 @@ class PluginResourceMonitor:
             summaries[plugin_id] = self.get_metrics_summary(plugin_id)
         return summaries
     
-    def _persist_metrics(self, plugin_id: str, metrics: ResourceMetrics,
-                         force: bool = False) -> None:
-        """Write a plugin's metrics to the cache, at most once per interval.
-
-        Caller must hold ``self._lock``.
-        """
-        # Monotonic, not wall clock: these devices have no RTC, so the clock
-        # jumps by however far off boot-time was the moment NTP first syncs.
-        # A forward jump would allow an early write, a backward one would
-        # stall the snapshot well past the interval.
-        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:
         """Reset metrics for a plugin."""
         with self._lock:
@@ -453,7 +370,4 @@ class PluginResourceMonitor:
                 self._metrics[plugin_id] = ResourceMetrics()
                 cache_key = self._get_metrics_key(plugin_id)
                 self.cache_manager.delete(cache_key)
-                # Let the next call persist immediately rather than leaving the
-                # deleted key absent for the rest of the interval.
-                self._metrics_persisted_at.pop(plugin_id, None)
 

src/vegas_mode/plugin_adapter.py

@@ -83,7 +83,7 @@ class PluginAdapter:
         # into unrelated headlines once the strip refreshed to 9,505px.
         self._offset_shapes: dict = {}
 
-        logger.debug(
+        logger.info(
             "PluginAdapter initialized: display=%dx%d",
             self.display_width, self.display_height
         )
@@ -109,7 +109,7 @@ class PluginAdapter:
         Returns:
             List of PIL Images representing plugin content, or None if no content
         """
-        logger.debug(
+        logger.info(
             "[%s] Getting content (class=%s)",
             plugin_id, plugin.__class__.__name__
         )
@@ -118,7 +118,7 @@ class PluginAdapter:
         cached = self._get_cached(plugin_id)
         if cached is not None:
             total_width = sum(img.width for img in cached)
-            logger.debug(
+            logger.info(
                 "[%s] Using cached content: %d images, %dpx total",
                 plugin_id, len(cached), total_width
             )
@@ -126,46 +126,46 @@ class PluginAdapter:
 
         # Try native Vegas content method first
         has_native = hasattr(plugin, 'get_vegas_content')
-        logger.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:
             content = self._get_native_content(plugin, plugin_id, offscreen_only)
             if content:
                 total_width = sum(img.width for img in content)
-                logger.debug(
+                logger.info(
                     "[%s] Native content SUCCESS: %d images, %dpx total",
                     plugin_id, len(content), total_width
                 )
                 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)
         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)
         if content:
             total_width = sum(img.width for img in content)
-            logger.debug(
+            logger.info(
                 "[%s] ScrollHelper content SUCCESS: %d images, %dpx total",
                 plugin_id, len(content), total_width
             )
             return self._finalize(content, plugin_id, 'scroll_helper', plugin)
         if has_scroll_helper:
-            logger.debug("[%s] ScrollHelper content returned None", plugin_id)
+            logger.info("[%s] ScrollHelper content returned None", plugin_id)
 
         if offscreen_only:
             # Display capture needs the shared canvas; leave it to the caller.
-            logger.debug(
+            logger.info(
                 "[%s] Needs display capture, deferring to the render thread",
                 plugin_id
             )
             return None
 
         # 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)
         if content:
             total_width = sum(img.width for img in content)
-            logger.debug(
+            logger.info(
                 "[%s] Fallback capture SUCCESS: %d images, %dpx total",
                 plugin_id, len(content), total_width
             )
@@ -226,7 +226,7 @@ class PluginAdapter:
             kept.append(result.image)
 
         if not kept:
-            logger.debug(
+            logger.info(
                 "[%s] All %d image(s) from %s were blank — contributing nothing",
                 plugin_id, len(images), source
             )
@@ -235,14 +235,14 @@ class PluginAdapter:
         trimmed_width = sum(img.width for img in kept)
 
         if trimmed_width < self.config.min_plugin_width:
-            logger.debug(
+            logger.info(
                 "[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping",
                 plugin_id, trimmed_width, self.config.min_plugin_width
             )
             return None
 
         if trimmed_width != original_width or dropped_blank:
-            logger.debug(
+            logger.info(
                 "[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), "
                 "%d image(s) kept, %d blank dropped",
                 plugin_id, source, original_width, trimmed_width,
@@ -431,7 +431,7 @@ class PluginAdapter:
         """
         if self._offset_shapes.get(plugin_id) != shape:
             if plugin_id in self._item_offsets:
-                logger.debug(
+                logger.info(
                     "[%s] Content is %s now, was %s — restarting the rotation "
                     "rather than resuming at a position that no longer means "
                     "anything", plugin_id, shape,
@@ -579,7 +579,7 @@ class PluginAdapter:
             consumed += 1
 
         if mode == 'truncate':
-            logger.debug(
+            logger.info(
                 "[%s] Width budget %dpx: showing the first %d of %d row(s) "
                 "(%dpx incl. gaps); the rest are not shown (overflow=truncate)",
                 plugin_id, budget, len(selected), len(images), used
@@ -587,7 +587,7 @@ class PluginAdapter:
         else:
             self._record_offset(
                 plugin_id, (start + consumed) % len(images), shape)
-            logger.debug(
+            logger.info(
                 "[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) "
                 "from offset %d; remainder deferred to a later cycle",
                 plugin_id, budget, len(selected), len(images), used, start
@@ -636,7 +636,7 @@ class PluginAdapter:
             if mode != 'truncate':
                 self._record_offset(
                     plugin_id, 0 if end >= img.width else end, shape)
-            logger.debug(
+            logger.info(
                 "[%s] Width budget %dpx: cropped continuous %dpx image to "
                 "[%d:%d] (no item gaps of %dpx+ to align to)%s",
                 plugin_id, budget, img.width, offset, end, min_run,
@@ -674,7 +674,7 @@ class PluginAdapter:
             self._record_offset(
                 plugin_id, 0 if end >= img.width else end_index, shape)
 
-        logger.debug(
+        logger.info(
             "[%s] Width budget %dpx: cropped single %dpx image to [%d:%d] "
             "(%dpx) at item boundaries %d-%d of %d, %s",
             plugin_id, budget, img.width, start, end, end - start,
@@ -698,7 +698,7 @@ class PluginAdapter:
             List of images or None
         """
         try:
-            logger.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
             # narrow the canvas for the duration of the call. A plugin that
@@ -707,7 +707,7 @@ class PluginAdapter:
             # be explicit can read get_vegas_render_width().
             render_width = self.resolve_render_width(plugin, plugin_id)
             if render_width != self.display_width:
-                logger.debug(
+                logger.info(
                     "[%s] Native: requesting %dpx instead of %dpx",
                     plugin_id, render_width, self.display_width
                 )
@@ -735,19 +735,19 @@ class PluginAdapter:
                 plugin._vegas_render_width = None
 
             if result is None:
-                logger.debug("[%s] Native: get_vegas_content() returned None", plugin_id)
+                logger.info("[%s] Native: get_vegas_content() returned None", plugin_id)
                 return None
 
             # Normalize to list
             if isinstance(result, Image.Image):
                 images = [result]
-                logger.debug(
+                logger.info(
                     "[%s] Native: got single Image %dx%d",
                     plugin_id, result.width, result.height
                 )
             elif isinstance(result, (list, tuple)):
                 images = list(result)
-                logger.debug(
+                logger.info(
                     "[%s] Native: got %d items in list/tuple",
                     plugin_id, len(images)
                 )
@@ -768,14 +768,14 @@ class PluginAdapter:
                     )
                     continue
 
-                logger.debug(
+                logger.info(
                     "[%s] Native: item[%d] is %dx%d, mode=%s",
                     plugin_id, i, img.width, img.height, img.mode
                 )
 
                 # Ensure correct height
                 if img.height != self.display_height:
-                    logger.debug(
+                    logger.info(
                         "[%s] Native: resizing item[%d]: %dx%d -> %dx%d",
                         plugin_id, i, img.width, img.height,
                         img.width, self.display_height
@@ -793,13 +793,13 @@ class PluginAdapter:
 
             if valid_images:
                 total_width = sum(img.width for img in valid_images)
-                logger.debug(
+                logger.info(
                     "[%s] Native: SUCCESS - %d images, %dpx total width",
                     plugin_id, len(valid_images), total_width
                 )
                 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
 
         except (AttributeError, TypeError, ValueError, OSError) as e:
@@ -833,20 +833,20 @@ class PluginAdapter:
                 logger.debug("[%s] No scroll_helper attribute", plugin_id)
                 return None
 
-            logger.debug(
+            logger.info(
                 "[%s] Found scroll_helper: %s",
                 plugin_id, type(scroll_helper).__name__
             )
 
             cached_image = getattr(scroll_helper, 'cached_image', None)
             if cached_image is None:
-                logger.debug(
+                logger.info(
                     "[%s] scroll_helper.cached_image is None, triggering content generation",
                     plugin_id
                 )
                 if offscreen_only:
                     # Generating it calls display(), which needs the canvas.
-                    logger.debug(
+                    logger.info(
                         "[%s] scroll_helper cache empty; deferring generation "
                         "to the render thread", plugin_id
                     )
@@ -859,13 +859,13 @@ class PluginAdapter:
                     return None
 
             if not isinstance(cached_image, Image.Image):
-                logger.debug(
+                logger.info(
                     "[%s] scroll_helper.cached_image is not an Image: %s",
                     plugin_id, type(cached_image).__name__
                 )
                 return None
 
-            logger.debug(
+            logger.info(
                 "[%s] scroll_helper.cached_image found: %dx%d, mode=%s",
                 plugin_id, cached_image.width, cached_image.height, cached_image.mode
             )
@@ -888,7 +888,7 @@ class PluginAdapter:
 
             # Ensure correct height
             if img.height != self.display_height:
-                logger.debug(
+                logger.info(
                     "[%s] Resizing scroll_helper content: %dx%d -> %dx%d",
                     plugin_id, img.width, img.height,
                     img.width, self.display_height
@@ -902,7 +902,7 @@ class PluginAdapter:
             if img.mode != 'RGB':
                 img = img.convert('RGB')
 
-            logger.debug(
+            logger.info(
                 "[%s] ScrollHelper content ready: %dx%d",
                 plugin_id, img.width, img.height
             )
@@ -1002,7 +1002,7 @@ class PluginAdapter:
             with self._capture():
                 # Method 1: Try _create_scrolling_display (stocks pattern)
                 if hasattr(plugin, '_create_scrolling_display'):
-                    logger.debug(
+                    logger.info(
                         "[%s] Triggering via _create_scrolling_display()",
                         plugin_id
                     )
@@ -1010,7 +1010,7 @@ class PluginAdapter:
                         plugin._create_scrolling_display()
                         cached_image = getattr(scroll_helper, 'cached_image', None)
                         if cached_image is not None and isinstance(cached_image, Image.Image):
-                            logger.debug(
+                            logger.info(
                                 "[%s] _create_scrolling_display() SUCCESS: %dx%d",
                                 plugin_id, cached_image.width, cached_image.height
                             )
@@ -1022,7 +1022,7 @@ class PluginAdapter:
 
                 # Method 2: Try display(force_clear=True) which typically builds scroll content
                 if hasattr(plugin, 'display'):
-                    logger.debug(
+                    logger.info(
                         "[%s] Triggering via display(force_clear=True)",
                         plugin_id
                     )
@@ -1031,12 +1031,12 @@ class PluginAdapter:
                         plugin.display(force_clear=True)
                         cached_image = getattr(scroll_helper, 'cached_image', None)
                         if cached_image is not None and isinstance(cached_image, Image.Image):
-                            logger.debug(
+                            logger.info(
                                 "[%s] display(force_clear=True) SUCCESS: %dx%d",
                                 plugin_id, cached_image.width, cached_image.height
                             )
                             return cached_image
-                        logger.debug(
+                        logger.info(
                             "[%s] display(force_clear=True) did not populate cached_image",
                             plugin_id
                         )
@@ -1045,7 +1045,7 @@ class PluginAdapter:
                             "[%s] display(force_clear=True) failed", plugin_id
                         )
 
-            logger.debug(
+            logger.info(
                 "[%s] Could not trigger scroll content generation",
                 plugin_id
             )
@@ -1077,15 +1077,15 @@ class PluginAdapter:
         try:
             # Save current display state
             original_image = self.display_manager.image.copy()
-            logger.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
             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:
                 try:
                     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):
                     logger.exception("[%s] Fallback: update_data() failed", plugin_id)
 
@@ -1097,41 +1097,41 @@ class PluginAdapter:
             # arrangement rather than one that has to be cropped afterwards.
             render_width = self.resolve_render_width(plugin, plugin_id)
             if render_width != self.display_width:
-                logger.debug(
+                logger.info(
                     "[%s] Fallback: rendering at %dpx instead of %dpx",
                     plugin_id, render_width, self.display_width
                 )
 
             with self._capture(), self._render_at(render_width):
                 self.display_manager.clear()
-                logger.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)
                 try:
                     plugin.display()
-                    logger.debug("[%s] Fallback: display() called successfully", plugin_id)
+                    logger.info("[%s] Fallback: display() called successfully", plugin_id)
                 except TypeError:
                     # 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)
 
                 # Capture the result
                 captured = self.display_manager.image.copy()
 
-            logger.debug(
+            logger.info(
                 "[%s] Fallback: captured frame %dx%d, mode=%s",
                 plugin_id, captured.width, captured.height, captured.mode
             )
 
             # Check if captured image has content (not all black)
             is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
-            logger.debug(
+            logger.info(
                 "[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)",
                 plugin_id, bright_ratio * 100
             )
 
             if is_blank:
-                logger.debug(
+                logger.info(
                     "[%s] Fallback: first capture blank, retrying with force_clear",
                     plugin_id
                 )
@@ -1142,7 +1142,7 @@ class PluginAdapter:
                     captured = self.display_manager.image.copy()
 
                 is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
-                logger.debug(
+                logger.info(
                     "[%s] Fallback: retry brightness - %.3f%% bright pixels",
                     plugin_id, bright_ratio * 100
                 )
@@ -1159,7 +1159,7 @@ class PluginAdapter:
             if captured.mode != 'RGB':
                 captured = captured.convert('RGB')
 
-            logger.debug(
+            logger.info(
                 "[%s] Fallback: SUCCESS - captured %dx%d",
                 plugin_id, captured.width, captured.height
             )

test/test_journald_log_priority.py

@@ -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()

test/test_logging_config.py

@@ -183,27 +183,15 @@ class TestSetupLogging:
         setup_logging()
         assert len(logging.getLogger().handlers) == 1
 
-    @staticmethod
-    def _selected_formatter():
-        """The formatter setup_logging() chose, past any journald wrapper.
-
-        Under systemd the console handler's formatter is wrapped so each line
-        carries its syslog priority. That wrapper is applied only when
-        JOURNAL_STREAM is set, which is true in CI and false in a terminal, so
-        asserting on the handler's formatter directly passes locally and fails
-        on the runner. These tests are about which formatter format_type
-        selects, so they look through the wrapper.
-        """
-        formatter = logging.getLogger().handlers[0].formatter
-        return getattr(formatter, "inner", formatter)
-
     def test_json_format_selects_structured_formatter(self):
         setup_logging(format_type="json")
-        assert isinstance(self._selected_formatter(), StructuredFormatter)
+        assert isinstance(
+            logging.getLogger().handlers[0].formatter, StructuredFormatter)
 
     def test_readable_format_selects_contextual_formatter(self):
         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):
         log_file = tmp_path / "test.log"

test/test_metrics_cache_unknown_fields.py

@@ -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)

test/test_resource_monitor.py

@@ -127,67 +127,3 @@ class TestForceReload:
         fresh = mon.get_metrics_summary("p", force_reload=True)
         assert fresh["call_count"] == 7
         assert any(c.kwargs.get("memory_ttl") == 0 for c in cache.get.call_args_list)
-
-
-class TestMetricsPersistenceChurn:
-    """Metrics are telemetry; writing them on every call wore the SD card.
-
-    Each write is a ~350-byte file, which on ext4 costs a 4KB block plus a
-    journal entry. At roughly nine calls a minute per plugin across fourteen
-    plugins it dominated the device's write volume.
-    """
-
-    def test_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"

test/test_vegas_log_volume.py

@@ -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