fix(plugins): one bad metrics cache entry should not stop every plugin

Caught live on a rig: every plugin failing, once each, continuously.

    ERROR - src.plugin_system.plugin_manager - plugin geochron operation failed:
    ResourceMetrics.__init__() got an unexpected keyword argument
    'consecutive_failures'

    ERROR - ... plugin text-display operation failed: ...
    ERROR - ... plugin news operation failed: ...
    ERROR - ... plugin odds-ticker operation failed: ...

with /api/v3/health reporting plugin_system: not_initialized while the display
process itself kept running and updating the panel.

`consecutive_failures` is a plugin_health field, not a metrics one.
get_metrics() does ResourceMetrics(**cached), which raises TypeError on a
single unrecognised key, and that exception escapes into plugin_manager and is
reported per plugin. One malformed cache entry takes the whole plugin system
down.

How a health-shaped record came to sit under a plugin_metrics key on that
machine is not established, and I could not finish the diagnosis: the rig went
back into its EIO failure mode partway through -- SSH resetting pre-banner,
systemctl unexecutable -- while the web API kept answering from RAM. Checked
before that: the cache files on disk are correctly shaped and separate, and
CacheManager.get() returns the right record for each key, so it is not a live
key collision. A restored backup mixing two machines' caches is the likeliest
explanation, and that rig had one restored onto it.

Either way the loader should not be brittle enough for the answer to matter.
plugin_health already repairs its records field by field rather than trusting
what is on disk; this does the same. Known fields are kept, unknown ones are
dropped and named once in the log so a genuine schema change stays visible
rather than being silently discarded, and a non-mapping entry no longer raises.

Keeping the known fields matters: discarding the record wholesale would throw
away real call counts and timings because of an unrelated stray key.

Mutation-checked: restoring ResourceMetrics(**cached) fails 6 checks, dropping
the whole record fails the field-preservation check, and dropping unknown
fields silently fails the logging check. 28 tests pass across the resource
monitor and plugin health suites.

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/plugin_system/plugin_health.py

@@ -178,21 +178,11 @@ class PluginHealthTracker:
             )
         return self._health_state[plugin_id]
     
-    # Fields the circuit breaker is rebuilt from after a restart. Everything
-    # else in a health record is reporting, read only for display.
-    _DURABLE_FIELDS = ('consecutive_failures', 'circuit_state',
-                       'circuit_opened_time', 'half_open_start_time')
-
-    def _durable(self, state: Dict[str, Any]) -> tuple:
-        """The part of a health record whose loss would change behaviour."""
-        return tuple(state.get(field) for field in self._DURABLE_FIELDS)
-
     def record_success(self, plugin_id: str) -> None:
         """Record a successful plugin execution."""
         state = self.get_health_state(plugin_id)
         current_time = time.time()
-        durable_before = self._durable(state)
-
+        
         # Reset consecutive failures
         state['consecutive_failures'] = 0
         state['total_successes'] = state.get('total_successes', 0) + 1
@@ -208,20 +198,9 @@ class PluginHealthTracker:
             # Shouldn't happen, but handle it
             state['circuit_state'] = CircuitState.CLOSED.value
             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:
         """Record a failed plugin execution."""
         state = self.get_health_state(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
+from dataclasses import dataclass, field, fields
 
 try:
     import psutil
@@ -102,6 +102,50 @@ 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}"
@@ -126,7 +170,7 @@ class PluginResourceMonitor:
                     cache_key, max_age=None, memory_ttl=0 if force_reload else None
                 )
                 if cached:
-                    metrics = ResourceMetrics(**cached)
+                    metrics = self._metrics_from_cache(plugin_id, cached)
                 else:
                     metrics = ResourceMetrics()
                 self._metrics[plugin_id] = metrics

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_health_write_churn.py

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

test/test_metrics_cache_unknown_fields.py

@@ -0,0 +1,100 @@
+"""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_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