Compare commits

..
Author SHA1 Message Date
ChuckBuilds 8d1e43c15a perf(vegas): trace the content path at DEBUG instead of INFO
plugin_adapter narrates every step of acquiring content from every plugin --
"Has get_vegas_content", "Native: calling get_vegas_content()", "Native
content returned None", "Has scroll_helper", per-item sizes -- once per plugin
per cycle, all at INFO.

Measured on a live rig: 13,408 log lines an hour, of which 13,366 were INFO
and 35 were WARNING. Roughly 223 lines a minute of string formatting on a Pi
that is also driving the panel, written through journald to the SD card, with
the 35 lines that actually indicate a problem buried among them.

Top repeated messages in that hour:

    717  Scroll progress: elapsed=... total_scrolled=.../... px
    399  [plugin] --> INCLUDED in Vegas scroll
    323  [plugin] content_type=static, display_mode=fixed
    195  [plugin] Has get_vegas_content: True
    195  [plugin] Native: calling get_vegas_content()
    168  [plugin] Native: get_vegas_content() returned None
    168  [plugin] Native content returned None        <- the same fact, twice

54 logger.info calls in plugin_adapter become logger.debug, along with the
per-frame scroll-progress line in scroll_helper. Together those are 3,174 of
the 13,408 lines an hour, a 23% cut, and the ~3,600 odds-manager lines are
addressed separately by ledmatrix-plugins#300.

Nothing is lost: the 19 warning/error/exception calls in the module are
untouched, so real failures still surface at their own level. This is a
logging-level change only -- no control flow, no behaviour.

One INFO call is deliberate and stays. The padding-strip message picks its
level at runtime (`logger.warning if (left and right) else logger.info`) and
test_vegas_plugin_adapter.py pins that choice; it survives because it is not a
direct logger.info call site. That test still passes.

Mutation-checked both ways: reintroducing a single INFO trace fails the guard,
and demoting the warning/error calls along with the trace fails a second guard
written for exactly that mistake. 537 vegas and scroll tests pass.

(cherry picked from commit e496d95dfe)
2026-08-19 20:49:31 -04:00
ChuckBuilds 0f77bd2345 perf(health): stop rewriting a health record on every healthy cycle
Every successful plugin update called record_success(), which persisted the
record unconditionally. In steady state the only fields that had changed were
total_successes and last_success_time -- a counter and a timestamp that
health_monitor surfaces for display and that nothing reads back after a
restart. Nothing alerts on the age of last_successful_update; it is carried in
the metrics dataclass and shown.

Measured on a rig running 24 plugins, all steady-state (0 consecutive
failures, circuit closed): a five-minute sample caught 22 health-file
rewrites, about 4.4 a minute or 6,300 a day. Each write is ~400 bytes through
cache_manager.set(), which writes a file per call, so each one costs a
filesystem block plus an ext4 journal write.

That lands on an SD card, where the unit of cost is an erase-block cycle
rather than the bytes involved, and where wear is what eventually kills the
card. Two cards have already failed on the other rig with the same
signature -- unreadable block device, EIO on exec, sshd unable to read its
host keys.

The circuit breaker still has to survive a restart, so the write is kept for
exactly the fields it is rebuilt from: consecutive_failures, circuit_state,
circuit_opened_time, half_open_start_time. A failure, a circuit opening and a
recovery are all still written the moment they happen. In-memory state is
updated every time either way, so the health API and web UI show what they
always did.

Tested: 100 healthy cycles now perform zero writes after the first, the
counters remain accurate in memory, and a failure, a recovery and a
half-open-to-closed transition each still reach disk. One test kills and
rebuilds the tracker from the cache to prove the breaker's state genuinely
survives what is no longer written.

Mutation-checked both ways: persisting unconditionally again fails the
steady-state test, and widening _DURABLE_FIELDS to include last_success_time
fails it too. The 46 existing health tests pass.

(cherry picked from commit 14abea2d24)
2026-08-19 20:49:31 -04:00
9 changed files with 257 additions and 180 deletions
+1 -1
View File
@@ -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,
+25 -4
View File
@@ -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)
+54 -54
View File
@@ -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
)
+110
View File
@@ -0,0 +1,110 @@
"""A healthy plugin must not rewrite its health record every cycle.
Every successful plugin update called record_success(), which persisted the
record unconditionally. In steady state the only fields that had changed were
total_successes and last_success_time -- a counter and a timestamp that
health_monitor reads for display and that nothing reads back after a restart.
Measured on a rig running 24 plugins: about 17 health-file rewrites a minute,
roughly 25,000 a day. Each is ~400 bytes, but they land on an SD card where
the unit of cost is an erase-block cycle, not the byte count, and where wear is
what eventually kills the card.
The circuit breaker still needs its own state to survive a restart, so the
write is kept for exactly the fields it is rebuilt from -- and a failure, a
circuit opening, or a recovery must still be written the moment it happens.
"""
import time
import pytest
from src.plugin_system.plugin_health import PluginHealthTracker, CircuitState
class _Cache:
"""Counts writes; serves back whatever was last written."""
def __init__(self):
self.store = {}
self.writes = 0
def set(self, key, data, ttl=None, **kwargs):
self.writes += 1
self.store[key] = data
def get(self, key, max_age=None, memory_ttl=None, **kwargs):
return self.store.get(key)
@pytest.fixture
def tracker():
cache = _Cache()
t = PluginHealthTracker(cache_manager=cache)
return t, cache
def test_steady_state_success_stops_writing(tracker):
"""The regression: 100 healthy cycles used to be 100 SD writes."""
t, cache = tracker
t.record_success("weather")
first = cache.writes
for _ in range(100):
t.record_success("weather")
assert cache.writes == first, (
f"{cache.writes - first} redundant writes across 100 healthy cycles"
)
def test_the_counters_are_still_accurate_in_memory(tracker):
"""Skipping the write must not skip the bookkeeping."""
t, _ = tracker
for _ in range(10):
t.record_success("weather")
state = t.get_health_state("weather")
assert state["total_successes"] == 10
assert state["last_success_time"] is not None
assert state["last_success_time"] <= time.time()
def test_a_failure_is_written_immediately(tracker):
t, cache = tracker
t.record_success("weather")
before = cache.writes
t.record_failure("weather", RuntimeError("boom"))
assert cache.writes > before, "a failure must reach disk"
def test_recovery_after_failure_is_written(tracker):
"""consecutive_failures returning to 0 is durable state changing."""
t, cache = tracker
t.record_failure("weather", RuntimeError("boom"))
before = cache.writes
t.record_success("weather")
assert cache.writes > before, "recovery must reach disk"
assert t.get_health_state("weather")["consecutive_failures"] == 0
def test_a_closing_circuit_is_written(tracker):
"""Success in half-open closes the circuit -- that must survive a restart."""
t, cache = tracker
state = t.get_health_state("weather")
state["circuit_state"] = CircuitState.HALF_OPEN.value
state["half_open_start_time"] = time.time()
before = cache.writes
t.record_success("weather")
assert cache.writes > before, "a circuit transition must reach disk"
assert t.get_health_state("weather")["circuit_state"] == CircuitState.CLOSED.value
def test_durable_state_survives_a_restart(tracker):
"""What is skipped must genuinely not matter to the breaker."""
t, cache = tracker
for _ in range(3):
t.record_failure("weather", RuntimeError("boom"))
for _ in range(50):
t.record_success("weather")
revived = PluginHealthTracker(cache_manager=cache)
state = revived.get_health_state("weather")
assert state["consecutive_failures"] == 0
assert state["circuit_state"] == CircuitState.CLOSED.value
-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:
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
# an explicit "origin <branch>" above so the update still works.
result = subprocess.run(
@@ -2044,7 +2039,6 @@ def execute_system_action():
capture_output=True, text=True, timeout=10, cwd=project_dir)
new_head = _post.stdout.strip() if _post.returncode == 0 else None
if old_head and new_head and old_head != new_head:
code_changed = True
diff = subprocess.run(
['git', 'diff', '--name-only', f'{old_head}..{new_head}'],
capture_output=True, text=True, timeout=15, cwd=project_dir)
@@ -2104,14 +2098,9 @@ def execute_system_action():
if ln.strip()), '')
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({
'status': 'success' if result.returncode == 0 else 'error',
'message': pull_message,
'restart_required': bool(result.returncode == 0 and code_changed),
})
elif action == 'checkout_branch':
# 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 =====
// Shown after restart-requiring saves; persists across tab switches (and
// reloads, via sessionStorage) until the display restarts or it's dismissed.
window.showRestartPending = function(message) {
try {
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 */ }
window.showRestartPending = function() {
try { sessionStorage.setItem('ledmatrix-restart-pending', '1'); } catch { /* private browsing */ }
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';
};
window.dismissRestartPending = function() {
try {
sessionStorage.removeItem('ledmatrix-restart-pending');
sessionStorage.removeItem('ledmatrix-restart-pending-text');
} catch { /* no-op */ }
try { sessionStorage.removeItem('ledmatrix-restart-pending'); } catch { /* no-op */ }
const banner = document.getElementById('restart-pending-banner');
if (banner) banner.style.display = 'none';
};
@@ -162,9 +151,6 @@ document.addEventListener('DOMContentLoaded', function() {
try {
if (sessionStorage.getItem('ledmatrix-restart-pending') === '1') {
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';
}
} catch { /* no-op */ }
+1 -9
View File
@@ -413,8 +413,7 @@
<div class="flex items-center justify-between">
<div class="flex items-center space-x-3">
<i class="fas fa-rotate text-lg"></i>
<span class="text-sm font-medium" aria-live="polite"
id="restart-pending-text">
<span class="text-sm font-medium" aria-live="polite">
Configuration saved &mdash; restart the display to apply the changes
</span>
</div>
@@ -1147,13 +1146,6 @@
if (data.status === 'success') {
document.getElementById('update-banner').style.display = 'none';
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') {
showNotification(data.message || 'Update complete', data.status || 'success');