From 0f77bd2345427a994a5e2d736304b2dd44c9e264 Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Wed, 19 Aug 2026 18:47:21 -0400 Subject: [PATCH 1/2] 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) --- 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 @@ def get_health_state(self, plugin_id: str, force_reload: bool = False) -> Dict[s ) 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 @@ def record_success(self, plugin_id: str) -> None: # 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 8d1e43c15aaf68ae6de32f2be7a9ff30e39871d9 Mon Sep 17 00:00:00 2001 From: ChuckBuilds Date: Wed, 19 Aug 2026 19:56:03 -0400 Subject: [PATCH 2/2] 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) --- 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 @@ def update_scroll_position(self) -> None: 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 @@ def __init__(self, display_manager: Any, config: Optional[Any] = None): # 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 @@ def get_content(self, plugin: 'BasePlugin', plugin_id: str, 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 @@ def get_content(self, plugin: 'BasePlugin', plugin_id: str, 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 @@ def get_content(self, plugin: 'BasePlugin', plugin_id: str, # 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 @@ def _finalize( 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 @@ def _finalize( 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 @@ def _resume_offset(self, plugin_id: str, shape: Tuple[str, int]) -> int: """ 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 @@ def _apply_width_budget( 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 @@ def _apply_width_budget( 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 @@ def _crop_to_budget( 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 @@ def _crop_to_budget( 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 @@ def _get_native_content( 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 @@ def _get_native_content( # 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 @@ def _get_native_content( 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 @@ def _get_native_content( ) 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 @@ def _get_native_content( 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 @@ def _get_scroll_helper_content( 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 @@ def _get_scroll_helper_content( 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 @@ def _get_scroll_helper_content( # 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 @@ def _get_scroll_helper_content( 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 @@ def _trigger_scroll_content_generation( 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 @@ def _trigger_scroll_content_generation( 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 @@ def _trigger_scroll_content_generation( # 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 @@ def _trigger_scroll_content_generation( 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 @@ def _trigger_scroll_content_generation( "[%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 @@ def _capture_display_content( 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 @@ def _capture_display_content( # 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 @@ def _capture_display_content( 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 @@ def _capture_display_content( 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