Compare commits

..
Author SHA1 Message Date
ChuckBuilds e496d95dfe 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.
2026-08-19 19:56:03 -04:00
5 changed files with 119 additions and 193 deletions
+1 -63
View File
@@ -111,12 +111,6 @@ class RestoreOptions:
"""Which sections of a backup should be restored.""" """Which sections of a backup should be restored."""
restore_config: bool = True restore_config: bool = True
#: Whether to take the backup's display.hardware block as well.
#: Off by default: that block describes the panel physically wired to
#: *this* device -- its size, chain length, mapping, multiplexing and
#: refresh cap. A backup carries the panel of the machine it was taken
#: on, and restoring one onto a different rig drives the wrong geometry.
restore_hardware: bool = False
restore_secrets: bool = True restore_secrets: bool = True
restore_wifi: bool = True restore_wifi: bool = True
restore_fonts: bool = True restore_fonts: bool = True
@@ -555,60 +549,6 @@ def _copy_file(src: Path, dst: Path) -> None:
raise raise
_HARDWARE_PATH = ("display", "hardware")
def _restore_config_preserving_hardware(src: Path, dst: Path, keep_hardware: bool) -> None:
"""Copy a backed-up config.json, optionally keeping the local panel block.
display.hardware describes the panel physically attached to this device:
cols, rows, chain_length, hardware_mapping, panel_type, multiplexing and
the refresh-rate cap. None of that travels with a configuration -- it is a
property of the machine. Restoring a backup taken on a 512x64 rig onto a
128x32 one used to overwrite the smaller panel's geometry with the larger
one's, which is not a setting the user can see going wrong; the display
simply stops being right.
Falls back to a plain copy when either file cannot be parsed, so a restore
never fails because of this.
"""
if not keep_hardware:
_copy_file(src, dst)
return
try:
incoming = json.loads(src.read_text(encoding="utf-8"))
local = json.loads(dst.read_text(encoding="utf-8")) if dst.exists() else {}
except (OSError, ValueError) as exc:
logger.warning(
"[Backup] Could not merge local panel config (%s); restoring the "
"backup's config.json as-is", exc)
_copy_file(src, dst)
return
section, key = _HARDWARE_PATH
local_hw = (local.get(section) or {}).get(key)
if not isinstance(local_hw, dict) or not local_hw:
_copy_file(src, dst)
return
if not isinstance(incoming.get(section), dict):
incoming[section] = {}
incoming_hw = incoming[section].get(key)
incoming[section][key] = local_hw
if isinstance(incoming_hw, dict) and incoming_hw != local_hw:
logger.info(
"[Backup] Kept this device's display.hardware; the backup's panel "
"was %sx%s chain %s, this one is %sx%s chain %s",
incoming_hw.get("cols"), incoming_hw.get("rows"),
incoming_hw.get("chain_length"),
local_hw.get("cols"), local_hw.get("rows"),
local_hw.get("chain_length"))
tmp_path = dst.with_suffix(dst.suffix + ".restore-tmp")
tmp_path.write_text(json.dumps(incoming, indent=2) + "\n", encoding="utf-8")
os.replace(tmp_path, dst)
def restore_backup( def restore_backup(
zip_path: Path, zip_path: Path,
project_root: Path, project_root: Path,
@@ -644,9 +584,7 @@ def restore_backup(
# Main config. # Main config.
if options.restore_config and (tmp_dir / _CONFIG_REL).exists(): if options.restore_config and (tmp_dir / _CONFIG_REL).exists():
try: try:
_restore_config_preserving_hardware( _copy_file(tmp_dir / _CONFIG_REL, project_root / _CONFIG_REL)
tmp_dir / _CONFIG_REL, project_root / _CONFIG_REL,
keep_hardware=not options.restore_hardware)
result.restored.append("config") result.restored.append("config")
except OSError as e: except OSError as e:
logger.error("[Backup] Failed to restore config.json: %s", e, exc_info=True) logger.error("[Backup] Failed to restore config.json: %s", e, exc_info=True)
+1 -1
View File
@@ -328,7 +328,7 @@ class ScrollHelper:
elapsed_time = current_time - (self.scroll_start_time or current_time) 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 # The image already includes display_width padding, so we only need total_scroll_width
required_total_distance = self.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%%)", "Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
elapsed_time, elapsed_time,
self.calculated_duration, self.calculated_duration,
+54 -54
View File
@@ -83,7 +83,7 @@ class PluginAdapter:
# into unrelated headlines once the strip refreshed to 9,505px. # into unrelated headlines once the strip refreshed to 9,505px.
self._offset_shapes: dict = {} self._offset_shapes: dict = {}
logger.info( logger.debug(
"PluginAdapter initialized: display=%dx%d", "PluginAdapter initialized: display=%dx%d",
self.display_width, self.display_height self.display_width, self.display_height
) )
@@ -109,7 +109,7 @@ class PluginAdapter:
Returns: Returns:
List of PIL Images representing plugin content, or None if no content List of PIL Images representing plugin content, or None if no content
""" """
logger.info( logger.debug(
"[%s] Getting content (class=%s)", "[%s] Getting content (class=%s)",
plugin_id, plugin.__class__.__name__ plugin_id, plugin.__class__.__name__
) )
@@ -118,7 +118,7 @@ class PluginAdapter:
cached = self._get_cached(plugin_id) cached = self._get_cached(plugin_id)
if cached is not None: if cached is not None:
total_width = sum(img.width for img in cached) total_width = sum(img.width for img in cached)
logger.info( logger.debug(
"[%s] Using cached content: %d images, %dpx total", "[%s] Using cached content: %d images, %dpx total",
plugin_id, len(cached), total_width plugin_id, len(cached), total_width
) )
@@ -126,46 +126,46 @@ class PluginAdapter:
# Try native Vegas content method first # Try native Vegas content method first
has_native = hasattr(plugin, 'get_vegas_content') 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: if has_native:
content = self._get_native_content(plugin, plugin_id, offscreen_only) content = self._get_native_content(plugin, plugin_id, offscreen_only)
if content: if content:
total_width = sum(img.width for img in content) total_width = sum(img.width for img in content)
logger.info( logger.debug(
"[%s] Native content SUCCESS: %d images, %dpx total", "[%s] Native content SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width plugin_id, len(content), total_width
) )
return self._finalize(content, plugin_id, 'native', plugin) 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) # Try to get scroll_helper's cached image (for scrolling plugins like stocks/odds)
has_scroll_helper = hasattr(plugin, 'scroll_helper') 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) content = self._get_scroll_helper_content(plugin, plugin_id, offscreen_only)
if content: if content:
total_width = sum(img.width for img in content) total_width = sum(img.width for img in content)
logger.info( logger.debug(
"[%s] ScrollHelper content SUCCESS: %d images, %dpx total", "[%s] ScrollHelper content SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width plugin_id, len(content), total_width
) )
return self._finalize(content, plugin_id, 'scroll_helper', plugin) return self._finalize(content, plugin_id, 'scroll_helper', plugin)
if has_scroll_helper: 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: if offscreen_only:
# Display capture needs the shared canvas; leave it to the caller. # Display capture needs the shared canvas; leave it to the caller.
logger.info( logger.debug(
"[%s] Needs display capture, deferring to the render thread", "[%s] Needs display capture, deferring to the render thread",
plugin_id plugin_id
) )
return None return None
# Fall back to display capture # 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) content = self._capture_display_content(plugin, plugin_id)
if content: if content:
total_width = sum(img.width for img in content) total_width = sum(img.width for img in content)
logger.info( logger.debug(
"[%s] Fallback capture SUCCESS: %d images, %dpx total", "[%s] Fallback capture SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width plugin_id, len(content), total_width
) )
@@ -226,7 +226,7 @@ class PluginAdapter:
kept.append(result.image) kept.append(result.image)
if not kept: if not kept:
logger.info( logger.debug(
"[%s] All %d image(s) from %s were blank — contributing nothing", "[%s] All %d image(s) from %s were blank — contributing nothing",
plugin_id, len(images), source plugin_id, len(images), source
) )
@@ -235,14 +235,14 @@ class PluginAdapter:
trimmed_width = sum(img.width for img in kept) trimmed_width = sum(img.width for img in kept)
if trimmed_width < self.config.min_plugin_width: if trimmed_width < self.config.min_plugin_width:
logger.info( logger.debug(
"[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping", "[%s] Trimmed content %dpx is below min_plugin_width %dpx — skipping",
plugin_id, trimmed_width, self.config.min_plugin_width plugin_id, trimmed_width, self.config.min_plugin_width
) )
return None return None
if trimmed_width != original_width or dropped_blank: if trimmed_width != original_width or dropped_blank:
logger.info( logger.debug(
"[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), " "[%s] Trimmed %s content: %dpx -> %dpx (%.0f%% reclaimed), "
"%d image(s) kept, %d blank dropped", "%d image(s) kept, %d blank dropped",
plugin_id, source, original_width, trimmed_width, plugin_id, source, original_width, trimmed_width,
@@ -431,7 +431,7 @@ class PluginAdapter:
""" """
if self._offset_shapes.get(plugin_id) != shape: if self._offset_shapes.get(plugin_id) != shape:
if plugin_id in self._item_offsets: if plugin_id in self._item_offsets:
logger.info( logger.debug(
"[%s] Content is %s now, was %s — restarting the rotation " "[%s] Content is %s now, was %s — restarting the rotation "
"rather than resuming at a position that no longer means " "rather than resuming at a position that no longer means "
"anything", plugin_id, shape, "anything", plugin_id, shape,
@@ -579,7 +579,7 @@ class PluginAdapter:
consumed += 1 consumed += 1
if mode == 'truncate': if mode == 'truncate':
logger.info( logger.debug(
"[%s] Width budget %dpx: showing the first %d of %d row(s) " "[%s] Width budget %dpx: showing the first %d of %d row(s) "
"(%dpx incl. gaps); the rest are not shown (overflow=truncate)", "(%dpx incl. gaps); the rest are not shown (overflow=truncate)",
plugin_id, budget, len(selected), len(images), used plugin_id, budget, len(selected), len(images), used
@@ -587,7 +587,7 @@ class PluginAdapter:
else: else:
self._record_offset( self._record_offset(
plugin_id, (start + consumed) % len(images), shape) plugin_id, (start + consumed) % len(images), shape)
logger.info( logger.debug(
"[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) " "[%s] Width budget %dpx: showing %d of %d row(s) (%dpx incl. gaps) "
"from offset %d; remainder deferred to a later cycle", "from offset %d; remainder deferred to a later cycle",
plugin_id, budget, len(selected), len(images), used, start plugin_id, budget, len(selected), len(images), used, start
@@ -636,7 +636,7 @@ class PluginAdapter:
if mode != 'truncate': if mode != 'truncate':
self._record_offset( self._record_offset(
plugin_id, 0 if end >= img.width else end, shape) plugin_id, 0 if end >= img.width else end, shape)
logger.info( logger.debug(
"[%s] Width budget %dpx: cropped continuous %dpx image to " "[%s] Width budget %dpx: cropped continuous %dpx image to "
"[%d:%d] (no item gaps of %dpx+ to align to)%s", "[%d:%d] (no item gaps of %dpx+ to align to)%s",
plugin_id, budget, img.width, offset, end, min_run, plugin_id, budget, img.width, offset, end, min_run,
@@ -674,7 +674,7 @@ class PluginAdapter:
self._record_offset( self._record_offset(
plugin_id, 0 if end >= img.width else end_index, shape) 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] " "[%s] Width budget %dpx: cropped single %dpx image to [%d:%d] "
"(%dpx) at item boundaries %d-%d of %d, %s", "(%dpx) at item boundaries %d-%d of %d, %s",
plugin_id, budget, img.width, start, end, end - start, plugin_id, budget, img.width, start, end, end - start,
@@ -698,7 +698,7 @@ class PluginAdapter:
List of images or None List of images or None
""" """
try: 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 # 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 # 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(). # be explicit can read get_vegas_render_width().
render_width = self.resolve_render_width(plugin, plugin_id) render_width = self.resolve_render_width(plugin, plugin_id)
if render_width != self.display_width: if render_width != self.display_width:
logger.info( logger.debug(
"[%s] Native: requesting %dpx instead of %dpx", "[%s] Native: requesting %dpx instead of %dpx",
plugin_id, render_width, self.display_width plugin_id, render_width, self.display_width
) )
@@ -735,19 +735,19 @@ class PluginAdapter:
plugin._vegas_render_width = None plugin._vegas_render_width = None
if result is 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 return None
# Normalize to list # Normalize to list
if isinstance(result, Image.Image): if isinstance(result, Image.Image):
images = [result] images = [result]
logger.info( logger.debug(
"[%s] Native: got single Image %dx%d", "[%s] Native: got single Image %dx%d",
plugin_id, result.width, result.height plugin_id, result.width, result.height
) )
elif isinstance(result, (list, tuple)): elif isinstance(result, (list, tuple)):
images = list(result) images = list(result)
logger.info( logger.debug(
"[%s] Native: got %d items in list/tuple", "[%s] Native: got %d items in list/tuple",
plugin_id, len(images) plugin_id, len(images)
) )
@@ -768,14 +768,14 @@ class PluginAdapter:
) )
continue continue
logger.info( logger.debug(
"[%s] Native: item[%d] is %dx%d, mode=%s", "[%s] Native: item[%d] is %dx%d, mode=%s",
plugin_id, i, img.width, img.height, img.mode plugin_id, i, img.width, img.height, img.mode
) )
# Ensure correct height # Ensure correct height
if img.height != self.display_height: if img.height != self.display_height:
logger.info( logger.debug(
"[%s] Native: resizing item[%d]: %dx%d -> %dx%d", "[%s] Native: resizing item[%d]: %dx%d -> %dx%d",
plugin_id, i, img.width, img.height, plugin_id, i, img.width, img.height,
img.width, self.display_height img.width, self.display_height
@@ -793,13 +793,13 @@ class PluginAdapter:
if valid_images: if valid_images:
total_width = sum(img.width for img in valid_images) total_width = sum(img.width for img in valid_images)
logger.info( logger.debug(
"[%s] Native: SUCCESS - %d images, %dpx total width", "[%s] Native: SUCCESS - %d images, %dpx total width",
plugin_id, len(valid_images), total_width plugin_id, len(valid_images), total_width
) )
return valid_images 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 return None
except (AttributeError, TypeError, ValueError, OSError) as e: except (AttributeError, TypeError, ValueError, OSError) as e:
@@ -833,20 +833,20 @@ class PluginAdapter:
logger.debug("[%s] No scroll_helper attribute", plugin_id) logger.debug("[%s] No scroll_helper attribute", plugin_id)
return None return None
logger.info( logger.debug(
"[%s] Found scroll_helper: %s", "[%s] Found scroll_helper: %s",
plugin_id, type(scroll_helper).__name__ plugin_id, type(scroll_helper).__name__
) )
cached_image = getattr(scroll_helper, 'cached_image', None) cached_image = getattr(scroll_helper, 'cached_image', None)
if cached_image is None: if cached_image is None:
logger.info( logger.debug(
"[%s] scroll_helper.cached_image is None, triggering content generation", "[%s] scroll_helper.cached_image is None, triggering content generation",
plugin_id plugin_id
) )
if offscreen_only: if offscreen_only:
# Generating it calls display(), which needs the canvas. # Generating it calls display(), which needs the canvas.
logger.info( logger.debug(
"[%s] scroll_helper cache empty; deferring generation " "[%s] scroll_helper cache empty; deferring generation "
"to the render thread", plugin_id "to the render thread", plugin_id
) )
@@ -859,13 +859,13 @@ class PluginAdapter:
return None return None
if not isinstance(cached_image, Image.Image): if not isinstance(cached_image, Image.Image):
logger.info( logger.debug(
"[%s] scroll_helper.cached_image is not an Image: %s", "[%s] scroll_helper.cached_image is not an Image: %s",
plugin_id, type(cached_image).__name__ plugin_id, type(cached_image).__name__
) )
return None return None
logger.info( logger.debug(
"[%s] scroll_helper.cached_image found: %dx%d, mode=%s", "[%s] scroll_helper.cached_image found: %dx%d, mode=%s",
plugin_id, cached_image.width, cached_image.height, cached_image.mode plugin_id, cached_image.width, cached_image.height, cached_image.mode
) )
@@ -888,7 +888,7 @@ class PluginAdapter:
# Ensure correct height # Ensure correct height
if img.height != self.display_height: if img.height != self.display_height:
logger.info( logger.debug(
"[%s] Resizing scroll_helper content: %dx%d -> %dx%d", "[%s] Resizing scroll_helper content: %dx%d -> %dx%d",
plugin_id, img.width, img.height, plugin_id, img.width, img.height,
img.width, self.display_height img.width, self.display_height
@@ -902,7 +902,7 @@ class PluginAdapter:
if img.mode != 'RGB': if img.mode != 'RGB':
img = img.convert('RGB') img = img.convert('RGB')
logger.info( logger.debug(
"[%s] ScrollHelper content ready: %dx%d", "[%s] ScrollHelper content ready: %dx%d",
plugin_id, img.width, img.height plugin_id, img.width, img.height
) )
@@ -1002,7 +1002,7 @@ class PluginAdapter:
with self._capture(): with self._capture():
# Method 1: Try _create_scrolling_display (stocks pattern) # Method 1: Try _create_scrolling_display (stocks pattern)
if hasattr(plugin, '_create_scrolling_display'): if hasattr(plugin, '_create_scrolling_display'):
logger.info( logger.debug(
"[%s] Triggering via _create_scrolling_display()", "[%s] Triggering via _create_scrolling_display()",
plugin_id plugin_id
) )
@@ -1010,7 +1010,7 @@ class PluginAdapter:
plugin._create_scrolling_display() plugin._create_scrolling_display()
cached_image = getattr(scroll_helper, 'cached_image', None) cached_image = getattr(scroll_helper, 'cached_image', None)
if cached_image is not None and isinstance(cached_image, Image.Image): if cached_image is not None and isinstance(cached_image, Image.Image):
logger.info( logger.debug(
"[%s] _create_scrolling_display() SUCCESS: %dx%d", "[%s] _create_scrolling_display() SUCCESS: %dx%d",
plugin_id, cached_image.width, cached_image.height 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 # Method 2: Try display(force_clear=True) which typically builds scroll content
if hasattr(plugin, 'display'): if hasattr(plugin, 'display'):
logger.info( logger.debug(
"[%s] Triggering via display(force_clear=True)", "[%s] Triggering via display(force_clear=True)",
plugin_id plugin_id
) )
@@ -1031,12 +1031,12 @@ class PluginAdapter:
plugin.display(force_clear=True) plugin.display(force_clear=True)
cached_image = getattr(scroll_helper, 'cached_image', None) cached_image = getattr(scroll_helper, 'cached_image', None)
if cached_image is not None and isinstance(cached_image, Image.Image): if cached_image is not None and isinstance(cached_image, Image.Image):
logger.info( logger.debug(
"[%s] display(force_clear=True) SUCCESS: %dx%d", "[%s] display(force_clear=True) SUCCESS: %dx%d",
plugin_id, cached_image.width, cached_image.height plugin_id, cached_image.width, cached_image.height
) )
return cached_image return cached_image
logger.info( logger.debug(
"[%s] display(force_clear=True) did not populate cached_image", "[%s] display(force_clear=True) did not populate cached_image",
plugin_id plugin_id
) )
@@ -1045,7 +1045,7 @@ class PluginAdapter:
"[%s] display(force_clear=True) failed", plugin_id "[%s] display(force_clear=True) failed", plugin_id
) )
logger.info( logger.debug(
"[%s] Could not trigger scroll content generation", "[%s] Could not trigger scroll content generation",
plugin_id plugin_id
) )
@@ -1077,15 +1077,15 @@ class PluginAdapter:
try: try:
# Save current display state # Save current display state
original_image = self.display_manager.image.copy() 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 # Ensure plugin has fresh data before capturing
has_update_data = hasattr(plugin, 'update_data') 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: if has_update_data:
try: try:
plugin.update_data() 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): except (AttributeError, RuntimeError, OSError):
logger.exception("[%s] Fallback: update_data() failed", plugin_id) 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. # arrangement rather than one that has to be cropped afterwards.
render_width = self.resolve_render_width(plugin, plugin_id) render_width = self.resolve_render_width(plugin, plugin_id)
if render_width != self.display_width: if render_width != self.display_width:
logger.info( logger.debug(
"[%s] Fallback: rendering at %dpx instead of %dpx", "[%s] Fallback: rendering at %dpx instead of %dpx",
plugin_id, render_width, self.display_width plugin_id, render_width, self.display_width
) )
with self._capture(), self._render_at(render_width): with self._capture(), self._render_at(render_width):
self.display_manager.clear() 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) # First try without force_clear (some plugins behave better this way)
try: try:
plugin.display() plugin.display()
logger.info("[%s] Fallback: display() called successfully", plugin_id) logger.debug("[%s] Fallback: display() called successfully", plugin_id)
except TypeError: except TypeError:
# Plugin may require force_clear argument # 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) plugin.display(force_clear=True)
# Capture the result # Capture the result
captured = self.display_manager.image.copy() captured = self.display_manager.image.copy()
logger.info( logger.debug(
"[%s] Fallback: captured frame %dx%d, mode=%s", "[%s] Fallback: captured frame %dx%d, mode=%s",
plugin_id, captured.width, captured.height, captured.mode plugin_id, captured.width, captured.height, captured.mode
) )
# Check if captured image has content (not all black) # Check if captured image has content (not all black)
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True) 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%%)", "[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)",
plugin_id, bright_ratio * 100 plugin_id, bright_ratio * 100
) )
if is_blank: if is_blank:
logger.info( logger.debug(
"[%s] Fallback: first capture blank, retrying with force_clear", "[%s] Fallback: first capture blank, retrying with force_clear",
plugin_id plugin_id
) )
@@ -1142,7 +1142,7 @@ class PluginAdapter:
captured = self.display_manager.image.copy() captured = self.display_manager.image.copy()
is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True) is_blank, bright_ratio = self._is_blank_image(captured, return_ratio=True)
logger.info( logger.debug(
"[%s] Fallback: retry brightness - %.3f%% bright pixels", "[%s] Fallback: retry brightness - %.3f%% bright pixels",
plugin_id, bright_ratio * 100 plugin_id, bright_ratio * 100
) )
@@ -1159,7 +1159,7 @@ class PluginAdapter:
if captured.mode != 'RGB': if captured.mode != 'RGB':
captured = captured.convert('RGB') captured = captured.convert('RGB')
logger.info( logger.debug(
"[%s] Fallback: SUCCESS - captured %dx%d", "[%s] Fallback: SUCCESS - captured %dx%d",
plugin_id, captured.width, captured.height plugin_id, captured.width, captured.height
) )
-75
View File
@@ -1,75 +0,0 @@
#!/usr/bin/env python3
"""A restore must not repoint this device at another machine's panel.
display.hardware describes the panel physically wired to this device -- cols,
rows, chain_length, hardware_mapping, panel_type, multiplexing, the refresh
cap. A backup carries the panel of the machine it was taken on. Restoring a
512x64 rig's backup onto a 128x32 one used to overwrite the smaller panel's
geometry with the larger one's, and nothing on screen explains why: the
display just stops being right.
That is not hypothetical. It happened, and the rig it happened to had to be
reflashed.
"""
import json
import sys
from pathlib import Path
sys.path.insert(0, str(Path(__file__).resolve().parent.parent))
from src.backup_manager import _restore_config_preserving_hardware # noqa: E402
BIG = {"display": {"hardware": {"cols": 128, "rows": 64, "chain_length": 4,
"hardware_mapping": "adafruit-hat-pwm"},
"runtime": {"gpio_slowdown": 4}},
"timezone": "America/New_York", "some-plugin": {"enabled": True}}
SMALL = {"display": {"hardware": {"cols": 64, "rows": 32, "chain_length": 2,
"hardware_mapping": "regular"},
"runtime": {"gpio_slowdown": 2}},
"timezone": "UTC"}
def _run(tmp, keep):
src = tmp / "backup_config.json"; src.write_text(json.dumps(BIG))
dst = tmp / "config.json"; dst.write_text(json.dumps(SMALL))
_restore_config_preserving_hardware(src, dst, keep_hardware=keep)
return json.loads(dst.read_text())
def test_local_panel_survives(tmp_path):
out = _run(tmp_path, keep=True)
hw = out["display"]["hardware"]
assert (hw["cols"], hw["rows"], hw["chain_length"]) == (64, 32, 2), (
"the restore repointed this device at the backup's panel")
assert hw["hardware_mapping"] == "regular", "panel wiring came from the backup"
def test_everything_else_is_restored(tmp_path):
out = _run(tmp_path, keep=True)
assert out["timezone"] == "America/New_York", "config was not restored"
assert out["some-plugin"] == {"enabled": True}, "plugin config was not restored"
assert out["display"]["runtime"] == {"gpio_slowdown": 4}, (
"only display.hardware should be held back")
def test_opting_in_takes_the_backups_panel(tmp_path):
out = _run(tmp_path, keep=False)
hw = out["display"]["hardware"]
assert (hw["cols"], hw["rows"], hw["chain_length"]) == (128, 64, 4)
def test_a_device_with_no_local_hardware_takes_the_backups(tmp_path):
src = tmp_path / "b.json"; src.write_text(json.dumps(BIG))
dst = tmp_path / "c.json"; dst.write_text(json.dumps({"timezone": "UTC"}))
_restore_config_preserving_hardware(src, dst, keep_hardware=True)
out = json.loads(dst.read_text())
assert out["display"]["hardware"]["cols"] == 128, (
"nothing local to preserve, so the backup's panel should be used")
def test_unparseable_local_config_still_restores(tmp_path):
src = tmp_path / "b.json"; src.write_text(json.dumps(BIG))
dst = tmp_path / "c.json"; dst.write_text("{ not json")
_restore_config_preserving_hardware(src, dst, keep_hardware=True)
assert json.loads(dst.read_text())["timezone"] == "America/New_York", (
"a restore must never fail because of this merge")
+63
View File
@@ -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