From ceabe5d4f928e357abad8b322d93f0735ecc367c Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Wed, 19 Aug 2026 18:47:21 -0400 Subject: [PATCH 1/4] 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. (cherry picked from commit 14abea2d24df454f70ecff1044f6b79f93be63bc) (cherry picked from commit 0f77bd2345427a994a5e2d736304b2dd44c9e264) --- src/plugin_system/plugin_health.py | 29 ++++++-- test/test_health_write_churn.py | 110 +++++++++++++++++++++++++++++ 2 files changed, 135 insertions(+), 4 deletions(-) create mode 100644 test/test_health_write_churn.py diff --git a/src/plugin_system/plugin_health.py b/src/plugin_system/plugin_health.py index d9b4f2c5..3908d9ca 100644 --- a/src/plugin_system/plugin_health.py +++ b/src/plugin_system/plugin_health.py @@ -178,11 +178,21 @@ class PluginHealthTracker: ) return self._health_state[plugin_id] + # Fields the circuit breaker is rebuilt from after a restart. Everything + # else in a health record is reporting, read only for display. + _DURABLE_FIELDS = ('consecutive_failures', 'circuit_state', + 'circuit_opened_time', 'half_open_start_time') + + def _durable(self, state: Dict[str, Any]) -> tuple: + """The part of a health record whose loss would change behaviour.""" + return tuple(state.get(field) for field in self._DURABLE_FIELDS) + def record_success(self, plugin_id: str) -> None: """Record a successful plugin execution.""" state = self.get_health_state(plugin_id) current_time = time.time() - + durable_before = self._durable(state) + # Reset consecutive failures state['consecutive_failures'] = 0 state['total_successes'] = state.get('total_successes', 0) + 1 @@ -198,9 +208,20 @@ class PluginHealthTracker: # Shouldn't happen, but handle it state['circuit_state'] = CircuitState.CLOSED.value state['circuit_opened_time'] = None - - self._save_health_state(plugin_id, state) - + + # A healthy plugin reports success every cycle, and in that steady state + # the only fields changed above are a counter and a timestamp that + # nothing reads back after a restart. Persisting them anyway rewrites a + # small file per plugin per cycle: on a rig running 24 plugins, a + # five-minute sample measured 22 rewrites, about 4.4 a minute or 6,300 a + # day. Those land on an SD card, where the cost is an erase-block cycle + # rather than the 400 bytes involved, and where wear is what eventually + # kills the card. + # In-memory state is still updated every time, so the health API and web + # UI show exactly what they did before; only the write is skipped. + if self._durable(state) != durable_before: + self._save_health_state(plugin_id, state) + def record_failure(self, plugin_id: str, error: Optional[Exception] = None) -> None: """Record a failed plugin execution.""" state = self.get_health_state(plugin_id) diff --git a/test/test_health_write_churn.py b/test/test_health_write_churn.py new file mode 100644 index 00000000..dba3df5b --- /dev/null +++ b/test/test_health_write_churn.py @@ -0,0 +1,110 @@ +"""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 From 5b64dbe8478d309f8702343cc49d8d9bbdc880b1 Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Wed, 19 Aug 2026 19:56:03 -0400 Subject: [PATCH 2/4] perf(vegas): trace the content path at DEBUG instead of 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", per-item sizes -- once per plugin per cycle, all at INFO. Measured on a live rig: 13,408 log lines an hour, of which 13,366 were INFO and 35 were WARNING. Roughly 223 lines a minute of string formatting on a Pi that is also driving the panel, written through journald to the SD card, with the 35 lines that actually indicate a problem buried among them. Top repeated messages in that hour: 717 Scroll progress: elapsed=... total_scrolled=.../... px 399 [plugin] --> INCLUDED in Vegas scroll 323 [plugin] content_type=static, display_mode=fixed 195 [plugin] Has get_vegas_content: True 195 [plugin] Native: calling get_vegas_content() 168 [plugin] Native: get_vegas_content() returned None 168 [plugin] Native content returned None <- the same fact, twice 54 logger.info calls in plugin_adapter become logger.debug, along with the per-frame scroll-progress line in scroll_helper. Together those are 3,174 of the 13,408 lines an hour, a 23% cut, and the ~3,600 odds-manager lines are addressed separately by ledmatrix-plugins#300. Nothing is lost: the 19 warning/error/exception calls in the module are untouched, so real failures still surface at their own level. This is a logging-level change only -- no control flow, no behaviour. One INFO call is deliberate and stays. The padding-strip message picks its level at runtime (`logger.warning if (left and right) else logger.info`) and test_vegas_plugin_adapter.py pins that choice; it survives because it is not a direct logger.info call site. That test still passes. Mutation-checked both ways: reintroducing a single INFO trace fails the guard, and demoting the warning/error calls along with the trace fails a second guard written for exactly that mistake. 537 vegas and scroll tests pass. (cherry picked from commit e496d95dfe7709e5637b6118be5695cfbab025fb) (cherry picked from commit 8d1e43c15aaf68ae6de32f2be7a9ff30e39871d9) --- src/common/scroll_helper.py | 2 +- src/vegas_mode/plugin_adapter.py | 108 +++++++++++++++---------------- test/test_vegas_log_volume.py | 63 ++++++++++++++++++ 3 files changed, 118 insertions(+), 55 deletions(-) create mode 100644 test/test_vegas_log_volume.py diff --git a/src/common/scroll_helper.py b/src/common/scroll_helper.py index 4f2e215e..88c6d498 100644 --- a/src/common/scroll_helper.py +++ b/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.info( + self.logger.debug( "Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)", elapsed_time, self.calculated_duration, diff --git a/src/vegas_mode/plugin_adapter.py b/src/vegas_mode/plugin_adapter.py index 0ea71571..01ef8cca 100644 --- a/src/vegas_mode/plugin_adapter.py +++ b/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.info( + logger.debug( "PluginAdapter initialized: display=%dx%d", self.display_width, self.display_height ) @@ -109,7 +109,7 @@ class PluginAdapter: Returns: List of PIL Images representing plugin content, or None if no content """ - logger.info( + logger.debug( "[%s] Getting content (class=%s)", plugin_id, plugin.__class__.__name__ ) @@ -118,7 +118,7 @@ class PluginAdapter: cached = self._get_cached(plugin_id) if cached is not None: total_width = sum(img.width for img in cached) - logger.info( + logger.debug( "[%s] Using cached content: %d images, %dpx total", plugin_id, len(cached), total_width ) @@ -126,46 +126,46 @@ class PluginAdapter: # Try native Vegas content method first has_native = hasattr(plugin, 'get_vegas_content') - logger.info("[%s] Has get_vegas_content: %s", plugin_id, has_native) + logger.debug("[%s] Has get_vegas_content: %s", plugin_id, has_native) if has_native: content = self._get_native_content(plugin, plugin_id, offscreen_only) if content: total_width = sum(img.width for img in content) - logger.info( + logger.debug( "[%s] Native content SUCCESS: %d images, %dpx total", plugin_id, len(content), total_width ) return self._finalize(content, plugin_id, 'native', plugin) - logger.info("[%s] Native content returned None", plugin_id) + logger.debug("[%s] Native content returned None", plugin_id) # Try to get scroll_helper's cached image (for scrolling plugins like stocks/odds) has_scroll_helper = hasattr(plugin, 'scroll_helper') - logger.info("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper) + logger.debug("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper) content = self._get_scroll_helper_content(plugin, plugin_id, offscreen_only) if content: total_width = sum(img.width for img in content) - logger.info( + logger.debug( "[%s] ScrollHelper content SUCCESS: %d images, %dpx total", plugin_id, len(content), total_width ) return self._finalize(content, plugin_id, 'scroll_helper', plugin) if has_scroll_helper: - logger.info("[%s] ScrollHelper content returned None", plugin_id) + logger.debug("[%s] ScrollHelper content returned None", plugin_id) if offscreen_only: # Display capture needs the shared canvas; leave it to the caller. - logger.info( + logger.debug( "[%s] Needs display capture, deferring to the render thread", plugin_id ) return None # Fall back to display capture - logger.info("[%s] Trying fallback display capture...", plugin_id) + logger.debug("[%s] Trying fallback display capture...", plugin_id) content = self._capture_display_content(plugin, plugin_id) if content: total_width = sum(img.width for img in content) - logger.info( + logger.debug( "[%s] Fallback capture SUCCESS: %d images, %dpx total", plugin_id, len(content), total_width ) @@ -226,7 +226,7 @@ class PluginAdapter: kept.append(result.image) if not kept: - logger.info( + logger.debug( "[%s] All %d image(s) from %s were blank — contributing nothing", plugin_id, len(images), source ) @@ -235,14 +235,14 @@ class PluginAdapter: trimmed_width = sum(img.width for img in kept) if trimmed_width < self.config.min_plugin_width: - logger.info( + logger.debug( "[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping", plugin_id, trimmed_width, self.config.min_plugin_width ) return None if trimmed_width != original_width or dropped_blank: - logger.info( + logger.debug( "[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), " "%d image(s) kept, %d blank dropped", plugin_id, source, original_width, trimmed_width, @@ -431,7 +431,7 @@ class PluginAdapter: """ if self._offset_shapes.get(plugin_id) != shape: if plugin_id in self._item_offsets: - logger.info( + logger.debug( "[%s] Content is %s now, was %s — restarting the rotation " "rather than resuming at a position that no longer means " "anything", plugin_id, shape, @@ -579,7 +579,7 @@ class PluginAdapter: consumed += 1 if mode == 'truncate': - logger.info( + logger.debug( "[%s] Width budget %dpx: showing the first %d of %d row(s) " "(%dpx incl. gaps); the rest are not shown (overflow=truncate)", plugin_id, budget, len(selected), len(images), used @@ -587,7 +587,7 @@ class PluginAdapter: else: self._record_offset( plugin_id, (start + consumed) % len(images), shape) - logger.info( + logger.debug( "[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) " "from offset %d; remainder deferred to a later cycle", plugin_id, budget, len(selected), len(images), used, start @@ -636,7 +636,7 @@ class PluginAdapter: if mode != 'truncate': self._record_offset( plugin_id, 0 if end >= img.width else end, shape) - logger.info( + logger.debug( "[%s] Width budget %dpx: cropped continuous %dpx image to " "[%d:%d] (no item gaps of %dpx+ to align to)%s", plugin_id, budget, img.width, offset, end, min_run, @@ -674,7 +674,7 @@ class PluginAdapter: self._record_offset( plugin_id, 0 if end >= img.width else end_index, shape) - logger.info( + logger.debug( "[%s] Width budget %dpx: cropped single %dpx image to [%d:%d] " "(%dpx) at item boundaries %d-%d of %d, %s", plugin_id, budget, img.width, start, end, end - start, @@ -698,7 +698,7 @@ class PluginAdapter: List of images or None """ try: - logger.info("[%s] Native: calling get_vegas_content()", plugin_id) + logger.debug("[%s] Native: calling get_vegas_content()", plugin_id) # Tell the plugin how much width the ticker wants it to use, and # narrow the canvas for the duration of the call. A plugin that @@ -707,7 +707,7 @@ class PluginAdapter: # be explicit can read get_vegas_render_width(). render_width = self.resolve_render_width(plugin, plugin_id) if render_width != self.display_width: - logger.info( + logger.debug( "[%s] Native: requesting %dpx instead of %dpx", plugin_id, render_width, self.display_width ) @@ -735,19 +735,19 @@ class PluginAdapter: plugin._vegas_render_width = None if result is None: - logger.info("[%s] Native: get_vegas_content() returned None", plugin_id) + logger.debug("[%s] Native: get_vegas_content() returned None", plugin_id) return None # Normalize to list if isinstance(result, Image.Image): images = [result] - logger.info( + logger.debug( "[%s] Native: got single Image %dx%d", plugin_id, result.width, result.height ) elif isinstance(result, (list, tuple)): images = list(result) - logger.info( + logger.debug( "[%s] Native: got %d items in list/tuple", plugin_id, len(images) ) @@ -768,14 +768,14 @@ class PluginAdapter: ) continue - logger.info( + logger.debug( "[%s] Native: item[%d] is %dx%d, mode=%s", plugin_id, i, img.width, img.height, img.mode ) # Ensure correct height if img.height != self.display_height: - logger.info( + logger.debug( "[%s] Native: resizing item[%d]: %dx%d -> %dx%d", plugin_id, i, img.width, img.height, img.width, self.display_height @@ -793,13 +793,13 @@ class PluginAdapter: if valid_images: total_width = sum(img.width for img in valid_images) - logger.info( + logger.debug( "[%s] Native: SUCCESS - %d images, %dpx total width", plugin_id, len(valid_images), total_width ) return valid_images - logger.info("[%s] Native: no valid images after validation", plugin_id) + logger.debug("[%s] Native: no valid images after validation", plugin_id) return None except (AttributeError, TypeError, ValueError, OSError) as e: @@ -833,20 +833,20 @@ class PluginAdapter: logger.debug("[%s] No scroll_helper attribute", plugin_id) return None - logger.info( + logger.debug( "[%s] Found scroll_helper: %s", plugin_id, type(scroll_helper).__name__ ) cached_image = getattr(scroll_helper, 'cached_image', None) if cached_image is None: - logger.info( + logger.debug( "[%s] scroll_helper.cached_image is None, triggering content generation", plugin_id ) if offscreen_only: # Generating it calls display(), which needs the canvas. - logger.info( + logger.debug( "[%s] scroll_helper cache empty; deferring generation " "to the render thread", plugin_id ) @@ -859,13 +859,13 @@ class PluginAdapter: return None if not isinstance(cached_image, Image.Image): - logger.info( + logger.debug( "[%s] scroll_helper.cached_image is not an Image: %s", plugin_id, type(cached_image).__name__ ) return None - logger.info( + logger.debug( "[%s] scroll_helper.cached_image found: %dx%d, mode=%s", plugin_id, cached_image.width, cached_image.height, cached_image.mode ) @@ -888,7 +888,7 @@ class PluginAdapter: # Ensure correct height if img.height != self.display_height: - logger.info( + logger.debug( "[%s] Resizing scroll_helper content: %dx%d -> %dx%d", plugin_id, img.width, img.height, img.width, self.display_height @@ -902,7 +902,7 @@ class PluginAdapter: if img.mode != 'RGB': img = img.convert('RGB') - logger.info( + logger.debug( "[%s] ScrollHelper content ready: %dx%d", plugin_id, img.width, img.height ) @@ -1002,7 +1002,7 @@ class PluginAdapter: with self._capture(): # Method 1: Try _create_scrolling_display (stocks pattern) if hasattr(plugin, '_create_scrolling_display'): - logger.info( + logger.debug( "[%s] Triggering via _create_scrolling_display()", plugin_id ) @@ -1010,7 +1010,7 @@ class PluginAdapter: plugin._create_scrolling_display() cached_image = getattr(scroll_helper, 'cached_image', None) if cached_image is not None and isinstance(cached_image, Image.Image): - logger.info( + logger.debug( "[%s] _create_scrolling_display() SUCCESS: %dx%d", plugin_id, cached_image.width, cached_image.height ) @@ -1022,7 +1022,7 @@ class PluginAdapter: # Method 2: Try display(force_clear=True) which typically builds scroll content if hasattr(plugin, 'display'): - logger.info( + logger.debug( "[%s] Triggering via display(force_clear=True)", plugin_id ) @@ -1031,12 +1031,12 @@ class PluginAdapter: plugin.display(force_clear=True) cached_image = getattr(scroll_helper, 'cached_image', None) if cached_image is not None and isinstance(cached_image, Image.Image): - logger.info( + logger.debug( "[%s] display(force_clear=True) SUCCESS: %dx%d", plugin_id, cached_image.width, cached_image.height ) return cached_image - logger.info( + logger.debug( "[%s] display(force_clear=True) did not populate cached_image", plugin_id ) @@ -1045,7 +1045,7 @@ class PluginAdapter: "[%s] display(force_clear=True) failed", plugin_id ) - logger.info( + logger.debug( "[%s] Could not trigger scroll content generation", plugin_id ) @@ -1077,15 +1077,15 @@ class PluginAdapter: try: # Save current display state original_image = self.display_manager.image.copy() - logger.info("[%s] Fallback: saved original display state", plugin_id) + logger.debug("[%s] Fallback: saved original display state", plugin_id) # Ensure plugin has fresh data before capturing has_update_data = hasattr(plugin, 'update_data') - logger.info("[%s] Fallback: has update_data=%s", plugin_id, has_update_data) + logger.debug("[%s] Fallback: has update_data=%s", plugin_id, has_update_data) if has_update_data: try: plugin.update_data() - logger.info("[%s] Fallback: update_data() called", plugin_id) + logger.debug("[%s] Fallback: update_data() called", plugin_id) except (AttributeError, RuntimeError, OSError): logger.exception("[%s] Fallback: update_data() failed", plugin_id) @@ -1097,41 +1097,41 @@ class PluginAdapter: # arrangement rather than one that has to be cropped afterwards. render_width = self.resolve_render_width(plugin, plugin_id) if render_width != self.display_width: - logger.info( + logger.debug( "[%s] Fallback: rendering at %dpx instead of %dpx", plugin_id, render_width, self.display_width ) with self._capture(), self._render_at(render_width): self.display_manager.clear() - logger.info("[%s] Fallback: display cleared, calling display()", plugin_id) + logger.debug("[%s] Fallback: display cleared, calling display()", plugin_id) # First try without force_clear (some plugins behave better this way) try: plugin.display() - logger.info("[%s] Fallback: display() called successfully", plugin_id) + logger.debug("[%s] Fallback: display() called successfully", plugin_id) except TypeError: # Plugin may require force_clear argument - logger.info("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id) + logger.debug("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id) plugin.display(force_clear=True) # Capture the result captured = self.display_manager.image.copy() - logger.info( + logger.debug( "[%s] Fallback: captured frame %dx%d, mode=%s", plugin_id, captured.width, captured.height, captured.mode ) # Check if captured image has content (not all black) is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True) - logger.info( + logger.debug( "[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)", plugin_id, bright_ratio * 100 ) if is_blank: - logger.info( + logger.debug( "[%s] Fallback: first capture blank, retrying with force_clear", plugin_id ) @@ -1142,7 +1142,7 @@ class PluginAdapter: captured = self.display_manager.image.copy() is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True) - logger.info( + logger.debug( "[%s] Fallback: retry brightness - %.3f%% bright pixels", plugin_id, bright_ratio * 100 ) @@ -1159,7 +1159,7 @@ class PluginAdapter: if captured.mode != 'RGB': captured = captured.convert('RGB') - logger.info( + logger.debug( "[%s] Fallback: SUCCESS - captured %dx%d", plugin_id, captured.width, captured.height ) diff --git a/test/test_vegas_log_volume.py b/test/test_vegas_log_volume.py new file mode 100644 index 00000000..0327d717 --- /dev/null +++ b/test/test_vegas_log_volume.py @@ -0,0 +1,63 @@ +"""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 From 3b4afa2f8512e65f7e9d638f36b10b3cc62fa5bc Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Thu, 20 Aug 2026 02:54:18 -0400 Subject: [PATCH 3/4] fix(logging): give the journal the real severity of each line Everything this process writes to stdout reaches the journal as PRIORITY=6, whatever the Python level was, because journald has nothing else to go on. Measured on a live rig over 24 hours: lines containing " - ERROR - " 55 lines containing " - WARNING - " 13 journald PRIORITY recorded 6, for every one of them So `journalctl -p err -u ledmatrix` returns nothing while errors are being logged, and `-p warning` likewise. Triage falls back to grepping message text, which is slower and unreliable: during this audit a search for "oom" matched the radar logging "zoom=9" twenty-four times and briefly looked like the OOM killer had been firing. systemd reads a leading "" on each stdout line and takes it as the priority (sd-daemon(3)), so a formatter that prefixes one costs no dependency. Every line of a multi-line record is tagged, not just the first -- the journal splits them, and an untagged continuation reverts to the default, which would leave the body of a traceback filed as informational while its first line was an error. Applied only when JOURNAL_STREAM is set, which systemd sets for services whose output it captures. Run from a terminal, in the emulator or under pytest the prefixes would be literal noise, and the file handler keeps the plain formatter for the same reason. Mutation-checked three ways: prefixing unconditionally fails the outside-systemd test, prefixing only the first line fails the multi-line test, and mapping ERROR to 6 fails the level mapping. 39 tests pass across the logging suites. (cherry picked from commit 780fca6365052a7767fbcd458da6baacb0456229) --- src/logging_config.py | 55 +++++++++++++++- test/test_journald_log_priority.py | 101 +++++++++++++++++++++++++++++ 2 files changed, 155 insertions(+), 1 deletion(-) create mode 100644 test/test_journald_log_priority.py diff --git a/src/logging_config.py b/src/logging_config.py index 17d831bb..a4431016 100644 --- a/src/logging_config.py +++ b/src/logging_config.py @@ -130,7 +130,12 @@ def setup_logging( # Console handler (always add) console_handler = logging.StreamHandler(sys.stdout) console_handler.setLevel(level) - console_handler.setFormatter(formatter) + # Under systemd, tag each line so the journal records the real severity + # rather than filing everything as informational. The file handler below + # keeps the plain formatter: the prefix is meaningful to journald and noise + # anywhere else. + console_handler.setFormatter( + JournalPriorityFormatter(formatter) if _under_systemd() else formatter) root_logger.addHandler(console_handler) # File handler (if specified) @@ -145,6 +150,54 @@ 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 "" 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 "" 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 + + 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 "" 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. diff --git a/test/test_journald_log_priority.py b/test/test_journald_log_priority.py new file mode 100644 index 00000000..b60855e0 --- /dev/null +++ b/test/test_journald_log_priority.py @@ -0,0 +1,101 @@ +"""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 "" 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() From 073435a2accd47ed96331645157972ed5afaf0ed Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Thu, 20 Aug 2026 04:04:46 -0400 Subject: [PATCH 4/4] fix(logging): let callers see through the journald formatter wrapper CI caught what local testing could not: two existing tests in test_logging_config.py assert that setup_logging() selected a StructuredFormatter or a ContextualFormatter, by checking the console handler's formatter directly. Wrapping that formatter to tag each line with its syslog priority makes those assertions false. They passed locally and failed on the runner because the wrapper is applied only when JOURNAL_STREAM is set -- absent in a terminal, present in CI. An environment-dependent break, which is the kind that gets shipped. The wrapper now exposes the formatter it delegates to, and those two tests look through it. They are about which formatter format_type selects, and that behaviour is unchanged; only the object they have to reach for moved. Verified both ways this time: 39 tests pass with JOURNAL_STREAM set and with it unset. --- src/logging_config.py | 12 ++++++++++++ test/test_logging_config.py | 20 ++++++++++++++++---- 2 files changed, 28 insertions(+), 4 deletions(-) diff --git a/src/logging_config.py b/src/logging_config.py index a4431016..3d3fa192 100644 --- a/src/logging_config.py +++ b/src/logging_config.py @@ -182,6 +182,18 @@ class JournalPriorityFormatter(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)}>" diff --git a/test/test_logging_config.py b/test/test_logging_config.py index e0fe7fff..d0cf0fe8 100644 --- a/test/test_logging_config.py +++ b/test/test_logging_config.py @@ -183,15 +183,27 @@ class TestSetupLogging: setup_logging() assert len(logging.getLogger().handlers) == 1 + @staticmethod + def _selected_formatter(): + """The formatter setup_logging() chose, past any journald wrapper. + + Under systemd the console handler's formatter is wrapped so each line + carries its syslog priority. That wrapper is applied only when + JOURNAL_STREAM is set, which is true in CI and false in a terminal, so + asserting on the handler's formatter directly passes locally and fails + on the runner. These tests are about which formatter format_type + selects, so they look through the wrapper. + """ + formatter = logging.getLogger().handlers[0].formatter + return getattr(formatter, "inner", formatter) + def test_json_format_selects_structured_formatter(self): setup_logging(format_type="json") - assert isinstance( - logging.getLogger().handlers[0].formatter, StructuredFormatter) + assert isinstance(self._selected_formatter(), StructuredFormatter) def test_readable_format_selects_contextual_formatter(self): setup_logging(format_type="readable") - assert isinstance( - logging.getLogger().handlers[0].formatter, ContextualFormatter) + assert isinstance(self._selected_formatter(), ContextualFormatter) def test_log_file_adds_file_handler(self, tmp_path): log_file = tmp_path / "test.log"