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
7 changed files with 122 additions and 176 deletions
+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
) )
-84
View File
@@ -1,84 +0,0 @@
"""A pull that changed nothing on the running system is not an applied update.
git_pull replaces files on disk and restarts nothing -- there is no systemctl
call anywhere in the handler. The display and web services keep running the
code they loaded at boot, so the user is told "Code updated successfully" and
sees no change until they happen to reboot. The response now says whether a
restart is owed, and the UI raises the existing restart-pending banner.
"""
import subprocess
import sys
from pathlib import Path
from unittest.mock import patch
import pytest
from flask import Flask
sys.path.insert(0, str(Path(__file__).resolve().parent.parent))
from web_interface.blueprints import api_v3 as mod # noqa: E402
from web_interface.blueprints.api_v3 import api_v3 # noqa: E402
@pytest.fixture
def client():
app = Flask(__name__)
app.config['TESTING'] = True
app.register_blueprint(api_v3, url_prefix='/api/v3')
# The handler consults these after a successful pull; None is the
# "not wired up" case it already guards for.
api_v3.plugin_store_manager = None
api_v3.config_manager = None
return app.test_client()
def _git(heads, pull_rc=0, pull_out='Updating a1b2c3..d4e5f6\n'):
"""Fake git. `heads` are the successive answers to rev-parse HEAD."""
seq = list(heads)
def run(args, **kwargs):
def ok(stdout='', rc=0, b=False):
return subprocess.CompletedProcess(
args, rc, stdout=(stdout.encode() if b else stdout),
stderr=(b'' if b else ''))
if args[:2] == ['git', 'rev-parse'] and args[-1] == 'HEAD':
return ok(seq.pop(0) + '\n' if seq else 'deadbeef\n')
if 'symbolic-full-name' in args or '@{u}' in args:
return ok('origin/main\n')
if args[:2] == ['git', 'status']:
return ok('')
if args[:2] == ['git', 'diff']:
return ok('')
if args[:2] == ['git', 'pull']:
return ok(pull_out, pull_rc)
return ok('')
return run
def _pull(client):
return client.post('/api/v3/system/action',
json={'action': 'git_pull'}).get_json()
class TestRestartIsRequestedWhenCodeChanged:
def test_a_pull_that_moved_head_asks_for_a_restart(self, client):
with patch.object(mod.subprocess, 'run', _git(['aaa111', 'bbb222'])):
data = _pull(client)
assert data['status'] == 'success'
assert data['restart_required'] is True, (
"new code on disk, services still running the old code, and "
"nothing told the user to restart")
def test_already_up_to_date_does_not(self, client):
with patch.object(mod.subprocess, 'run',
_git(['aaa111', 'aaa111'], pull_out='Already up to date.\n')):
data = _pull(client)
assert data['status'] == 'success'
assert data['restart_required'] is False, (
"prompting after a no-op update trains users to ignore the prompt")
def test_a_failed_pull_does_not(self, client):
with patch.object(mod.subprocess, 'run', _git(['aaa111'], pull_rc=1)):
data = _pull(client)
assert data['status'] == 'error'
assert data['restart_required'] is False
+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
-11
View File
@@ -1996,11 +1996,6 @@ def execute_system_action():
except subprocess.TimeoutExpired: except subprocess.TimeoutExpired:
logger.warning("git rev-parse timed out before pull") logger.warning("git rev-parse timed out before pull")
# Whether the pull actually brought new code in. "Already up to
# date" is a success too, and prompting for a restart then would
# train users to ignore the prompt.
code_changed = False
# Perform the git pull. Branches without an upstream were given # Perform the git pull. Branches without an upstream were given
# an explicit "origin <branch>" above so the update still works. # an explicit "origin <branch>" above so the update still works.
result = subprocess.run( result = subprocess.run(
@@ -2044,7 +2039,6 @@ def execute_system_action():
capture_output=True, text=True, timeout=10, cwd=project_dir) capture_output=True, text=True, timeout=10, cwd=project_dir)
new_head = _post.stdout.strip() if _post.returncode == 0 else None new_head = _post.stdout.strip() if _post.returncode == 0 else None
if old_head and new_head and old_head != new_head: if old_head and new_head and old_head != new_head:
code_changed = True
diff = subprocess.run( diff = subprocess.run(
['git', 'diff', '--name-only', f'{old_head}..{new_head}'], ['git', 'diff', '--name-only', f'{old_head}..{new_head}'],
capture_output=True, text=True, timeout=15, cwd=project_dir) capture_output=True, text=True, timeout=15, cwd=project_dir)
@@ -2104,14 +2098,9 @@ def execute_system_action():
if ln.strip()), '') if ln.strip()), '')
pull_message = f"Update failed: {detail}" if detail else "Update failed; check logs for details" pull_message = f"Update failed: {detail}" if detail else "Update failed; check logs for details"
# Nothing here restarts anything: the pull replaces files on
# disk while the display and web services keep running the code
# they loaded at boot. Without this the user is told the update
# succeeded and sees no change until they happen to reboot.
return jsonify({ return jsonify({
'status': 'success' if result.returncode == 0 else 'error', 'status': 'success' if result.returncode == 0 else 'error',
'message': pull_message, 'message': pull_message,
'restart_required': bool(result.returncode == 0 and code_changed),
}) })
elif action == 'checkout_branch': elif action == 'checkout_branch':
# Switch branches from the Tools tab. Needed because a checkout # Switch branches from the Tools tab. Needed because a checkout
+3 -17
View File
@@ -116,25 +116,14 @@ document.body.addEventListener('htmx:afterRequest', function(event) {
// ===== Restart-pending banner ===== // ===== Restart-pending banner =====
// Shown after restart-requiring saves; persists across tab switches (and // Shown after restart-requiring saves; persists across tab switches (and
// reloads, via sessionStorage) until the display restarts or it's dismissed. // reloads, via sessionStorage) until the display restarts or it's dismissed.
window.showRestartPending = function(message) { window.showRestartPending = function() {
try { try { sessionStorage.setItem('ledmatrix-restart-pending', '1'); } catch { /* private browsing */ }
sessionStorage.setItem('ledmatrix-restart-pending', '1');
// Persisted alongside the flag: a code update and a config save want
// different wording, and the banner outlives the page that raised it.
if (message) sessionStorage.setItem('ledmatrix-restart-pending-text', message);
else sessionStorage.removeItem('ledmatrix-restart-pending-text');
} catch { /* private browsing */ }
const banner = document.getElementById('restart-pending-banner'); const banner = document.getElementById('restart-pending-banner');
const text = document.getElementById('restart-pending-text');
if (text && message) text.textContent = message;
if (banner) banner.style.display = 'block'; if (banner) banner.style.display = 'block';
}; };
window.dismissRestartPending = function() { window.dismissRestartPending = function() {
try { try { sessionStorage.removeItem('ledmatrix-restart-pending'); } catch { /* no-op */ }
sessionStorage.removeItem('ledmatrix-restart-pending');
sessionStorage.removeItem('ledmatrix-restart-pending-text');
} catch { /* no-op */ }
const banner = document.getElementById('restart-pending-banner'); const banner = document.getElementById('restart-pending-banner');
if (banner) banner.style.display = 'none'; if (banner) banner.style.display = 'none';
}; };
@@ -162,9 +151,6 @@ document.addEventListener('DOMContentLoaded', function() {
try { try {
if (sessionStorage.getItem('ledmatrix-restart-pending') === '1') { if (sessionStorage.getItem('ledmatrix-restart-pending') === '1') {
const banner = document.getElementById('restart-pending-banner'); const banner = document.getElementById('restart-pending-banner');
const saved = sessionStorage.getItem('ledmatrix-restart-pending-text');
const text = document.getElementById('restart-pending-text');
if (text && saved) text.textContent = saved;
if (banner) banner.style.display = 'block'; if (banner) banner.style.display = 'block';
} }
} catch { /* no-op */ } } catch { /* no-op */ }
+1 -9
View File
@@ -413,8 +413,7 @@
<div class="flex items-center justify-between"> <div class="flex items-center justify-between">
<div class="flex items-center space-x-3"> <div class="flex items-center space-x-3">
<i class="fas fa-rotate text-lg"></i> <i class="fas fa-rotate text-lg"></i>
<span class="text-sm font-medium" aria-live="polite" <span class="text-sm font-medium" aria-live="polite">
id="restart-pending-text">
Configuration saved &mdash; restart the display to apply the changes Configuration saved &mdash; restart the display to apply the changes
</span> </span>
</div> </div>
@@ -1147,13 +1146,6 @@
if (data.status === 'success') { if (data.status === 'success') {
document.getElementById('update-banner').style.display = 'none'; document.getElementById('update-banner').style.display = 'none';
try { sessionStorage.removeItem('update-sha-dismissed'); } catch(e) {} try { sessionStorage.removeItem('update-sha-dismissed'); } catch(e) {}
// The pull replaced files on disk; the running services still
// hold the code they loaded at boot. Ask for the restart that
// makes the update actually take effect.
if (data.restart_required && typeof window.showRestartPending === 'function') {
window.showRestartPending(
'Update installed \u2014 restart the display to run the new code');
}
} }
if (typeof showNotification === 'function') { if (typeof showNotification === 'function') {
showNotification(data.message || 'Update complete', data.status || 'success'); showNotification(data.message || 'Update complete', data.status || 'success');