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/logging_config.py b/src/logging_config.py index 17d831bb..843257eb 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,84 @@ 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 + + @property + def inner(self) -> logging.Formatter: + """The formatter doing the actual work. + + Whether journald tagging is applied depends on JOURNAL_STREAM, so it is + on under systemd and off in a terminal -- and anything asserting which + formatter setup_logging() selected would otherwise get a different + answer in CI than on a developer's machine. Exposing the inner one lets + those checks stay about format_type, which is what they mean. + """ + return self._inner + + def format(self, record: logging.LogRecord) -> str: + text = self._inner.format(record) + prefix = f"<{_SYSLOG_PRIORITY.get(record.levelno, 6)}>" + return "\n".join(prefix + line for line in text.split("\n")) + + +def _under_systemd() -> bool: + """True when stdout really is the journal. + + systemd sets JOURNAL_STREAM to "dev:ino" for services whose output it + captures. Presence alone is not enough to act on: the variable is + inherited by child processes and survives redirection, so a subprocess + whose stdout is a pipe or a file still sees it and would emit the "" + priority prefixes as literal noise into that output. systemd's own + guidance is to fstat the descriptor and compare st_dev/st_ino, which is + what distinguishes "the journal is somewhere in my ancestry" from "my + stdout is the journal". + """ + declared = os.environ.get("JOURNAL_STREAM") + if not declared: + return False + try: + dev_text, ino_text = declared.split(":", 1) + declared_ids = (int(dev_text), int(ino_text)) + except (ValueError, AttributeError): + return False + try: + stat_result = os.fstat(sys.stdout.fileno()) + except (OSError, ValueError, AttributeError): + # No usable stdout: captured by pytest, detached, or already closed. + return False + return (stat_result.st_dev, stat_result.st_ino) == declared_ids + + class PluginLoggerAdapter(logging.LoggerAdapter): """LoggerAdapter that stamps every record with its plugin_id. 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/src/plugin_system/resource_monitor.py b/src/plugin_system/resource_monitor.py index 42ded4ec..1b63d74e 100644 --- a/src/plugin_system/resource_monitor.py +++ b/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 @@ -49,6 +49,20 @@ class ResourceMetrics: self.total_execution_time = self.total_execution_time / self.call_count +#: How often a plugin's metrics are written to the cache, in seconds. +#: +#: Persisting on every call meant a small file rewritten roughly nine times a +#: minute per plugin. On a rig with fourteen active plugins that was ~126 +#: writes a minute for metrics alone, and since each ~350-byte file costs a +#: 4KB block plus an ext4 journal entry, it dominated the device's write +#: volume -- on an SD card, which wears out. +#: +#: The in-memory copy stays authoritative and exact; only the cross-process +#: snapshot the web UI reads is delayed, and telemetry up to half a minute old +#: is still a fair description of a long-running plugin. +_METRICS_PERSIST_INTERVAL = 30.0 + + class PluginResourceMonitor: """ Monitors resource usage for plugins. @@ -75,6 +89,10 @@ class PluginResourceMonitor: # Resource metrics per plugin self._metrics: Dict[str, ResourceMetrics] = {} self._limits: Dict[str, ResourceLimits] = {} + # When each plugin's metrics last reached the cache. Metrics change on + # every call, so they cannot be de-duplicated the way health state can; + # they are rate-limited instead. See _METRICS_PERSIST_INTERVAL. + self._metrics_persisted_at: Dict[str, float] = {} # Thread-local storage for execution tracking self._local = threading.local() @@ -102,6 +120,66 @@ 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 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)) + # A dataclass does not enforce its annotations, so + # ResourceMetrics(call_count="not a number") builds happily and only + # blows up later, deep inside monitor_call ("can only concatenate str + # (not \"int\") to str"). Coerce here, where there is still a cache + # key to name in the warning. + declared = {f.name: f.type for f in fields(ResourceMetrics)} + usable = {} + for key, value in cached.items(): + if key not in known: + continue + try: + usable[key] = int(value) if declared[key] in ('int', int) else float(value) + except (TypeError, ValueError): + self.logger.warning( + "Cached metrics for %s have a bad %s (%r); starting fresh", + plugin_id, key, value) + return ResourceMetrics() + 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 +204,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 @@ -232,18 +310,8 @@ class PluginResourceMonitor: # CPU is harder to measure per-call, so we track it separately metrics.cpu_percent = self._get_process_cpu_percent() - # Persist metrics - cache_key = self._get_metrics_key(plugin_id) - self.cache_manager.set(cache_key, { - 'memory_mb': metrics.memory_mb, - 'cpu_percent': metrics.cpu_percent, - 'execution_time': metrics.execution_time, - 'call_count': metrics.call_count, - 'total_execution_time': metrics.total_execution_time, - 'max_execution_time': metrics.max_execution_time, - 'min_execution_time': metrics.min_execution_time if metrics.min_execution_time != float('inf') else 0.0, - 'last_update_time': metrics.last_update_time - }) + # Persist metrics, at most once per interval per plugin. + self._persist_metrics(plugin_id, metrics) # Check limits if limits: @@ -363,6 +431,44 @@ class PluginResourceMonitor: summaries[plugin_id] = self.get_metrics_summary(plugin_id) return summaries + def _persist_metrics(self, plugin_id: str, metrics: ResourceMetrics, + force: bool = False) -> None: + """Write a plugin's metrics to the cache, at most once per interval. + + Caller must hold ``self._lock``. + """ + # Monotonic, not wall clock: these devices have no RTC, so the clock + # jumps by however far off boot-time was the moment NTP first syncs. + # A forward jump would allow an early write, a backward one would + # stall the snapshot well past the interval. + # + # The sentinel for "never written" is None, not 0.0. monotonic() is + # time since boot on Linux, and systemd starts this service *at* boot, + # so `now - 0.0 < 30` was true for the first half-minute of every + # single run -- the throttle swallowed the very first snapshot, which + # is the one that matters most after a restart. + now = time.monotonic() + last_written = self._metrics_persisted_at.get(plugin_id) + if (not force and last_written is not None + and now - last_written < _METRICS_PERSIST_INTERVAL): + return + cache_key = self._get_metrics_key(plugin_id) + self.cache_manager.set(cache_key, { + 'memory_mb': metrics.memory_mb, + 'cpu_percent': metrics.cpu_percent, + 'execution_time': metrics.execution_time, + 'call_count': metrics.call_count, + 'total_execution_time': metrics.total_execution_time, + 'max_execution_time': metrics.max_execution_time, + 'min_execution_time': (metrics.min_execution_time + if metrics.min_execution_time != float('inf') + else 0.0), + 'last_update_time': metrics.last_update_time, + }) + # Only after the write lands. Marking it first would mean a failed + # set() bought the next interval's silence without leaving a snapshot. + self._metrics_persisted_at[plugin_id] = now + def reset_metrics(self, plugin_id: str) -> None: """Reset metrics for a plugin.""" with self._lock: @@ -370,4 +476,7 @@ class PluginResourceMonitor: self._metrics[plugin_id] = ResourceMetrics() cache_key = self._get_metrics_key(plugin_id) self.cache_manager.delete(cache_key) + # Let the next call persist immediately rather than leaving the + # deleted key absent for the rest of the interval. + self._metrics_persisted_at.pop(plugin_id, None) 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_health_write_churn.py b/test/test_health_write_churn.py new file mode 100644 index 00000000..883ce51a --- /dev/null +++ b/test/test_health_write_churn.py @@ -0,0 +1,119 @@ +"""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 copy + +import pytest + +from src.plugin_system.plugin_health import PluginHealthTracker, CircuitState + + +class _Cache: + """Counts writes; serves back whatever was last written. + + Both directions deep-copy, so this behaves like a real cache that + serialises through a file. Storing by reference let the tracker keep + mutating the object already in the store, so a record could appear to + have been persisted when no write ever happened -- which is precisely + what test_durable_state_survives_a_restart is supposed to detect. + """ + + def __init__(self): + self.store = {} + self.writes = 0 + + def set(self, key, data, ttl=None, **kwargs): + self.writes += 1 + self.store[key] = copy.deepcopy(data) + + def get(self, key, max_age=None, memory_ttl=None, **kwargs): + return copy.deepcopy(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 diff --git a/test/test_journald_log_priority.py b/test/test_journald_log_priority.py new file mode 100644 index 00000000..386b024c --- /dev/null +++ b/test/test_journald_log_priority.py @@ -0,0 +1,137 @@ +"""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 +import sys +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 _stdout_ids(): + """The dev:ino systemd would publish for this process's stdout.""" + st = os.fstat(sys.stdout.fileno()) + return f"{st.st_dev}:{st.st_ino}" + + +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": _stdout_ids()}): + assert _under_systemd() + + +def test_an_inherited_journal_stream_does_not_count(): + """The variable outlives the descriptor it describes. + + systemd sets JOURNAL_STREAM for the service, and every child inherits it + -- including one whose stdout has been redirected to a pipe or a file. + Trusting the variable alone put literal "<6>" prefixes into that captured + output. Only a descriptor whose dev:ino actually matches is the journal. + """ + with patch.dict(os.environ, {"JOURNAL_STREAM": "8:12345"}): + assert not _under_systemd(), \ + "a stale inherited JOURNAL_STREAM was treated as the journal" + + +@pytest.mark.parametrize("value", ["", "not-a-pair", "8", "8:", ":12345", + "eight:12345", "8:12345:9"]) +def test_a_malformed_journal_stream_is_not_the_journal(value): + with patch.dict(os.environ, {"JOURNAL_STREAM": value}): + assert not _under_systemd() + + +def test_a_closed_stdout_is_not_the_journal(): + """os.fstat raises rather than answers; that must not propagate.""" + with patch.dict(os.environ, {"JOURNAL_STREAM": "8:12345"}), \ + patch("src.logging_config.sys.stdout") as fake_stdout: + fake_stdout.fileno.side_effect = ValueError("I/O operation on closed file") + assert not _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": _stdout_ids()}, 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() 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" diff --git a/test/test_metrics_cache_unknown_fields.py b/test/test_metrics_cache_unknown_fields.py new file mode 100644 index 00000000..729893a3 --- /dev/null +++ b/test/test_metrics_cache_unknown_fields.py @@ -0,0 +1,128 @@ +"""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 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) + + +@pytest.mark.parametrize("bad", [ + {"call_count": "not a number"}, + {"memory_mb": None}, + {"execution_time": {"nested": "junk"}}, + {"min_execution_time": ["a", "list"]}, +]) +def test_values_of_the_wrong_type_fall_back_to_usable_defaults(bad): + """isinstance() alone was not enough. + + A dataclass does not enforce its annotations, so the bad value was simply + stored and the old assertion passed -- then monitor_call() raised + "can only concatenate str (not \"int\") to str" on the next call. The + metrics must come back *usable*, not merely constructed. + """ + monitor = _monitor(bad) + metrics = monitor.get_metrics("plugin-f") + assert isinstance(metrics, ResourceMetrics) + + field_name = next(iter(bad)) + assert isinstance(getattr(metrics, field_name), (int, float)), \ + f"{field_name} came back as {getattr(metrics, field_name)!r}" + + # The real proof: arithmetic on the loaded metrics must not explode. + metrics.call_count += 1 + metrics.total_execution_time += 0.5 + metrics.update_average_execution_time() + + +def test_a_numeric_string_is_accepted_rather_than_discarded(): + """JSON round-trips can widen an int to a string; that is recoverable.""" + metrics = _monitor({"call_count": "7"}).get_metrics("plugin-g") + assert metrics.call_count == 7 diff --git a/test/test_resource_monitor.py b/test/test_resource_monitor.py index 6b3dbe48..2f651d1d 100644 --- a/test/test_resource_monitor.py +++ b/test/test_resource_monitor.py @@ -11,7 +11,7 @@ Focus areas: import time import pytest -from unittest.mock import MagicMock +from unittest.mock import MagicMock, patch from src.plugin_system.resource_monitor import ( PluginResourceMonitor, @@ -127,3 +127,87 @@ class TestForceReload: fresh = mon.get_metrics_summary("p", force_reload=True) assert fresh["call_count"] == 7 assert any(c.kwargs.get("memory_ttl") == 0 for c in cache.get.call_args_list) + + +class TestMetricsPersistenceChurn: + """Metrics are telemetry; writing them on every call wore the SD card. + + Each write is a ~350-byte file, which on ext4 costs a 4KB block plus a + journal entry. At roughly nine calls a minute per plugin across fourteen + plugins it dominated the device's write volume. + """ + + def test_the_first_snapshot_is_written_even_seconds_after_boot(self): + """The throttle must key off "have we written?", not process uptime. + + time.monotonic() is time since boot on Linux, and systemd starts this + service at boot. With 0.0 as the missing-timestamp default, + `now - 0.0 < 30` was true for the first half-minute of every run, so + the very first metrics write -- the one that matters most after a + restart -- was silently skipped. + """ + import src.plugin_system.resource_monitor as rm + cache = _cache() + mon = PluginResourceMonitor(cache, enable_monitoring=False) + # 12 seconds after boot: inside the interval, but nothing written yet. + with patch.object(rm.time, "monotonic", return_value=12.0): + mon.monitor_call("p", lambda: None) + writes = [c for c in cache.set.call_args_list + if "plugin_metrics:" in str(c)] + assert writes, \ + "the first snapshot was dropped because the process was young" + + def test_repeated_calls_persist_once_per_interval(self): + cache = _cache() + mon = PluginResourceMonitor(cache, enable_monitoring=False) + for _ in range(50): + mon.monitor_call("p", lambda: None) + writes = [c for c in cache.set.call_args_list + if c.args and str(c.args[0]).startswith("plugin_metrics:")] + assert len(writes) == 1, ( + f"50 calls produced {len(writes)} metric writes; expected 1") + + def test_the_interval_elapsing_allows_the_next_write(self, monkeypatch): + import src.plugin_system.resource_monitor as rm + cache = _cache() + mon = PluginResourceMonitor(cache, enable_monitoring=False) + mon.monitor_call("p", lambda: None) + # pretend the interval has passed + mon._metrics_persisted_at["p"] -= rm._METRICS_PERSIST_INTERVAL + 1 + mon.monitor_call("p", lambda: None) + writes = [c for c in cache.set.call_args_list + if c.args and str(c.args[0]).startswith("plugin_metrics:")] + assert len(writes) == 2 + + def test_in_memory_metrics_stay_exact_while_writes_are_skipped(self): + mon = PluginResourceMonitor(_cache(), enable_monitoring=False) + for _ in range(20): + mon.monitor_call("p", lambda: None) + assert mon.get_metrics("p").call_count == 20 + + def test_reset_lets_the_next_call_persist_immediately(self): + cache = _cache() + mon = PluginResourceMonitor(cache, enable_monitoring=False) + mon.monitor_call("p", lambda: None) + mon.reset_metrics("p") + mon.monitor_call("p", lambda: None) + writes = [c for c in cache.set.call_args_list + if c.args and str(c.args[0]).startswith("plugin_metrics:")] + assert len(writes) == 2, "reset should clear the throttle timestamp" + + def test_a_failed_write_does_not_buy_the_next_interval_of_silence(self): + """A set() that raises must not count as having persisted. + + Marking the timestamp before the write would leave no snapshot in the + cache and still suppress the next 30 seconds of attempts. + """ + cache = _cache() + cache.set.side_effect = [OSError("disk full"), None] + mon = PluginResourceMonitor(cache, enable_monitoring=False) + with pytest.raises(OSError): + mon.monitor_call("p", lambda: None) + # the very next call must try again rather than skip the interval + mon.monitor_call("p", lambda: None) + writes = [c for c in cache.set.call_args_list + if c.args and str(c.args[0]).startswith("plugin_metrics:")] + assert len(writes) == 2, "a failed write should be retried, not skipped" diff --git a/test/test_vegas_log_volume.py b/test/test_vegas_log_volume.py new file mode 100644 index 00000000..5e8d126a --- /dev/null +++ b/test/test_vegas_log_volume.py @@ -0,0 +1,73 @@ +"""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 _logger_calls(path, *levels): + """Direct logger.(...) 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 in levels + and getattr(node.func.value, "id", None) == "logger"): + found.append(node.lineno) + return found + + +def _info_calls(path): + """Direct logger.info(...) call sites in a module.""" + return _logger_calls(path, "info") + + +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. + + Counted from the AST rather than with source.count(): the text form also + matches comments, docstrings and string literals -- including this + module's own docstring, which names these levels -- so a real + logger.error() could be demoted while the tally stayed put. + """ + loud = _logger_calls(ADAPTER, "warning", "error", "exception") + assert len(loud) >= 15, \ + f"only {len(loud)} warning/error/exception calls remain: {loud}" + + +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