Compare commits

..
Author SHA1 Message Date
ChuckBuildsandClaude Opus 5 95bd8a1a67 fix(web): stop an unrelated config edit from erasing a plugin's secret
Saving any field on a plugin's config form destroyed that plugin's stored
credential. On a rig with a weather API key, changing the city silently
emptied the key, and the plugin stopped working at the next fetch with no
indication why.

The path had no guard at any step. The config partial masks secrets before
rendering (pages_v3.py:740), so the browser posts them back blank; _parse_value
deliberately preserves "" for optional string fields; separate_secrets routes
that "" into secrets_config, which is a truthy dict; deep_merge writes it over
the stored value; save_raw_file_content persists it.

The blank does not even need the round-trip. merge_with_defaults injects the
schema's api_key default ("") into every save, so a client that never sends
the field at all still erases it. test_secret_count_message_counts_top_level_keys
was counting exactly that injected blank as a saved secret field -- the visible
edge of the bug, pinned as expected behaviour.

remove_empty_secrets() already existed for this, with seven unit tests and a
docstring describing this precise scenario ("clients will send those empty
strings back ... so that existing stored secrets are not overwritten with
blanks"). It was never wired into a call site. This wires it into both save
paths that merge into the secrets file.

A blank now means "unchanged" rather than "delete", which is the same contract
the helper's tests already describe. The cost is that a secret can no longer be
cleared by emptying the field; clearing needs its own affordance, since a
control that erases credentials as a side effect of ordinary edits is not one.

Verified by reverting the guard: the new round-trip test then fails with the
stored key read back as ''. 262 web tests pass with it.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW
2026-08-20 05:53:51 -04:00
10 changed files with 112 additions and 442 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.debug(
self.logger.info(
"Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
elapsed_time,
self.calculated_duration,
+1 -66
View File
@@ -130,12 +130,7 @@ def setup_logging(
# Console handler (always add)
console_handler = logging.StreamHandler(sys.stdout)
console_handler.setLevel(level)
# Under systemd, tag each line so the journal records the real severity
# rather than filing everything as informational. The file handler below
# keeps the plain formatter: the prefix is meaningful to journald and noise
# anywhere else.
console_handler.setFormatter(
JournalPriorityFormatter(formatter) if _under_systemd() else formatter)
console_handler.setFormatter(formatter)
root_logger.addHandler(console_handler)
# File handler (if specified)
@@ -150,66 +145,6 @@ def setup_logging(
sys.stderr.write(f"Warning: Could not set up file logging to {log_file}: {e}\n")
#: syslog priorities, which is what systemd parses from a "<N>" prefix on
#: stdout. Mapped from Python's levels.
_SYSLOG_PRIORITY = {
logging.CRITICAL: 2, # LOG_CRIT
logging.ERROR: 3, # LOG_ERR
logging.WARNING: 4, # LOG_WARNING
logging.INFO: 6, # LOG_INFO
logging.DEBUG: 7, # LOG_DEBUG
}
class JournalPriorityFormatter(logging.Formatter):
"""Wraps a formatter, prefixing each line with its syslog priority.
Under systemd everything this process writes to stdout lands in the journal
as PRIORITY=6, whatever the Python level was. Measured on a live rig: 55
ERROR lines and 13 WARNING lines in a day, every one of them recorded as
informational, so `journalctl -p err -u ledmatrix` returned nothing at all
while errors were being logged. Anyone triaging has to grep the message
text instead, which is both slower and wrong -- a search for "oom" matches
the radar logging "zoom=9".
systemd reads a leading "<N>" on each line and uses it as the priority
(sd-daemon(3)), so this needs no extra dependency. Multi-line records get
the prefix on every line, since the journal splits them and an unprefixed
continuation would fall back to the default.
"""
def __init__(self, inner: logging.Formatter):
super().__init__()
self._inner = inner
@property
def inner(self) -> logging.Formatter:
"""The formatter doing the actual work.
Whether journald tagging is applied depends on JOURNAL_STREAM, so it is
on under systemd and off in a terminal -- and anything asserting which
formatter setup_logging() selected would otherwise get a different
answer in CI than on a developer's machine. Exposing the inner one lets
those checks stay about format_type, which is what they mean.
"""
return self._inner
def format(self, record: logging.LogRecord) -> str:
text = self._inner.format(record)
prefix = f"<{_SYSLOG_PRIORITY.get(record.levelno, 6)}>"
return "\n".join(prefix + line for line in text.split("\n"))
def _under_systemd() -> bool:
"""True when stdout is the journal.
systemd sets JOURNAL_STREAM for services whose output it captures. Without
this check the "<N>" prefixes would show up as literal noise when the
program is run from a terminal, in the emulator, or in tests.
"""
return bool(os.environ.get("JOURNAL_STREAM"))
class PluginLoggerAdapter(logging.LoggerAdapter):
"""LoggerAdapter that stamps every record with its plugin_id.
+4 -25
View File
@@ -178,21 +178,11 @@ 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
@@ -208,20 +198,9 @@ class PluginHealthTracker:
# Shouldn't happen, but handle it
state['circuit_state'] = CircuitState.CLOSED.value
state['circuit_opened_time'] = None
# 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)
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.debug(
logger.info(
"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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug("[%s] Has get_vegas_content: %s", plugin_id, has_native)
logger.info("[%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.debug(
logger.info(
"[%s] Native content SUCCESS: %d images, %dpx total",
plugin_id, len(content), total_width
)
return self._finalize(content, plugin_id, 'native', plugin)
logger.debug("[%s] Native content returned None", plugin_id)
logger.info("[%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.debug("[%s] Has scroll_helper: %s", plugin_id, has_scroll_helper)
logger.info("[%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.debug(
logger.info(
"[%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.debug("[%s] ScrollHelper content returned None", plugin_id)
logger.info("[%s] ScrollHelper content returned None", plugin_id)
if offscreen_only:
# Display capture needs the shared canvas; leave it to the caller.
logger.debug(
logger.info(
"[%s] Needs display capture, deferring to the render thread",
plugin_id
)
return None
# Fall back to display capture
logger.debug("[%s] Trying fallback display capture...", plugin_id)
logger.info("[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug("[%s] Native: calling get_vegas_content()", plugin_id)
logger.info("[%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.debug(
logger.info(
"[%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.debug("[%s] Native: get_vegas_content() returned None", plugin_id)
logger.info("[%s] Native: get_vegas_content() returned None", plugin_id)
return None
# Normalize to list
if isinstance(result, Image.Image):
images = [result]
logger.debug(
logger.info(
"[%s] Native: got single Image %dx%d",
plugin_id, result.width, result.height
)
elif isinstance(result, (list, tuple)):
images = list(result)
logger.debug(
logger.info(
"[%s] Native: got %d items in list/tuple",
plugin_id, len(images)
)
@@ -768,14 +768,14 @@ class PluginAdapter:
)
continue
logger.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%s] Native: SUCCESS - %d images, %dpx total width",
plugin_id, len(valid_images), total_width
)
return valid_images
logger.debug("[%s] Native: no valid images after validation", plugin_id)
logger.info("[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%s] scroll_helper.cached_image is None, triggering content generation",
plugin_id
)
if offscreen_only:
# Generating it calls display(), which needs the canvas.
logger.debug(
logger.info(
"[%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.debug(
logger.info(
"[%s] scroll_helper.cached_image is not an Image: %s",
plugin_id, type(cached_image).__name__
)
return None
logger.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%s] display(force_clear=True) SUCCESS: %dx%d",
plugin_id, cached_image.width, cached_image.height
)
return cached_image
logger.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug("[%s] Fallback: saved original display state", plugin_id)
logger.info("[%s] Fallback: saved original display state", plugin_id)
# Ensure plugin has fresh data before capturing
has_update_data = hasattr(plugin, 'update_data')
logger.debug("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
logger.info("[%s] Fallback: has update_data=%s", plugin_id, has_update_data)
if has_update_data:
try:
plugin.update_data()
logger.debug("[%s] Fallback: update_data() called", plugin_id)
logger.info("[%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.debug(
logger.info(
"[%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.debug("[%s] Fallback: display cleared, calling display()", plugin_id)
logger.info("[%s] Fallback: display cleared, calling display()", plugin_id)
# First try without force_clear (some plugins behave better this way)
try:
plugin.display()
logger.debug("[%s] Fallback: display() called successfully", plugin_id)
logger.info("[%s] Fallback: display() called successfully", plugin_id)
except TypeError:
# Plugin may require force_clear argument
logger.debug("[%s] Fallback: display() failed, trying with force_clear=True", plugin_id)
logger.info("[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%s] Fallback: brightness check - %.3f%% bright pixels (threshold=0.5%%)",
plugin_id, bright_ratio * 100
)
if is_blank:
logger.debug(
logger.info(
"[%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.debug(
logger.info(
"[%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.debug(
logger.info(
"[%s] Fallback: SUCCESS - captured %dx%d",
plugin_id, captured.width, captured.height
)
-110
View File
@@ -1,110 +0,0 @@
"""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
-101
View File
@@ -1,101 +0,0 @@
"""Log lines must reach the journal with their real severity.
Everything this process writes to stdout lands in the journal as PRIORITY=6,
whatever the Python level was, because journald has no other signal. Measured
on a live rig over 24 hours: 55 lines containing " - ERROR - " and 13
containing " - WARNING - ", every one of them recorded as informational. So
journalctl -p err -u ledmatrix
returned nothing while errors were being logged, and anyone triaging has to
grep the message text instead. That is slower and it is wrong: a search for
"oom" also matches the radar logging "zoom=9", which is exactly the false
positive it produced during this audit.
systemd reads a leading "<N>" on each stdout line and uses it as the priority
(sd-daemon(3)), so this needs no extra dependency -- and it must only be
applied when systemd is actually reading, or the prefixes become literal noise
in a terminal, the emulator, and test output.
"""
import logging
import os
from unittest.mock import patch
import pytest
from src.logging_config import JournalPriorityFormatter, _SYSLOG_PRIORITY, _under_systemd
class _Plain(logging.Formatter):
def format(self, record):
return record.getMessage()
def _record(level, msg="hello"):
return logging.LogRecord("t", level, "f.py", 1, msg, None, None)
@pytest.mark.parametrize("level,expected", [
(logging.CRITICAL, 2),
(logging.ERROR, 3),
(logging.WARNING, 4),
(logging.INFO, 6),
(logging.DEBUG, 7),
])
def test_each_level_maps_to_its_syslog_priority(level, expected):
out = JournalPriorityFormatter(_Plain()).format(_record(level))
assert out.startswith(f"<{expected}>"), out
assert _SYSLOG_PRIORITY[level] == expected
def test_error_and_info_are_distinguishable():
"""The whole point: journalctl -p err must be able to tell them apart."""
fmt = JournalPriorityFormatter(_Plain())
assert fmt.format(_record(logging.ERROR))[:3] != fmt.format(_record(logging.INFO))[:3]
def test_every_line_of_a_multiline_record_is_tagged():
"""The journal splits them, and an untagged continuation loses its level.
A traceback is the case that matters -- it is the most important thing in
the log and the longest.
"""
out = JournalPriorityFormatter(_Plain()).format(
_record(logging.ERROR, "Traceback:\nline one\nline two"))
lines = out.split("\n")
assert len(lines) == 3
assert all(line.startswith("<3>") for line in lines), lines
def test_the_message_survives_intact():
out = JournalPriorityFormatter(_Plain()).format(_record(logging.WARNING, "disk full"))
assert out == "<4>disk full"
def test_an_unknown_level_falls_back_to_info():
out = JournalPriorityFormatter(_Plain()).format(_record(25))
assert out.startswith("<6>")
def test_prefixing_is_off_outside_systemd():
"""Otherwise a terminal run, the emulator and pytest all show `<6>`."""
with patch.dict(os.environ, {}, clear=True):
assert not _under_systemd()
with patch.dict(os.environ, {"JOURNAL_STREAM": "8:12345"}):
assert _under_systemd()
def test_setup_uses_the_wrapper_only_under_systemd():
from src.logging_config import setup_logging
for env, expect_wrapped in (({}, False), ({"JOURNAL_STREAM": "8:1"}, True)):
with patch.dict(os.environ, env, clear=True):
setup_logging()
handlers = [h for h in logging.getLogger().handlers
if isinstance(h, logging.StreamHandler)]
assert handlers, "no stream handler installed"
wrapped = any(isinstance(h.formatter, JournalPriorityFormatter)
for h in handlers)
assert wrapped is expect_wrapped, (
f"JOURNAL_STREAM={env}: wrapped={wrapped}, expected {expect_wrapped}")
logging.getLogger().handlers.clear()
+4 -16
View File
@@ -183,27 +183,15 @@ class TestSetupLogging:
setup_logging()
assert len(logging.getLogger().handlers) == 1
@staticmethod
def _selected_formatter():
"""The formatter setup_logging() chose, past any journald wrapper.
Under systemd the console handler's formatter is wrapped so each line
carries its syslog priority. That wrapper is applied only when
JOURNAL_STREAM is set, which is true in CI and false in a terminal, so
asserting on the handler's formatter directly passes locally and fails
on the runner. These tests are about which formatter format_type
selects, so they look through the wrapper.
"""
formatter = logging.getLogger().handlers[0].formatter
return getattr(formatter, "inner", formatter)
def test_json_format_selects_structured_formatter(self):
setup_logging(format_type="json")
assert isinstance(self._selected_formatter(), StructuredFormatter)
assert isinstance(
logging.getLogger().handlers[0].formatter, StructuredFormatter)
def test_readable_format_selects_contextual_formatter(self):
setup_logging(format_type="readable")
assert isinstance(self._selected_formatter(), ContextualFormatter)
assert isinstance(
logging.getLogger().handlers[0].formatter, ContextualFormatter)
def test_log_file_adds_file_handler(self, tmp_path):
log_file = tmp_path / "test.log"
-63
View File
@@ -1,63 +0,0 @@
"""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
@@ -194,15 +194,46 @@ class TestSavePluginConfig:
def test_secret_count_message_counts_top_level_keys(self, env):
# Pinned: the "(N secret field(s))" message counts TOP-LEVEL keys of
# the separated secrets dict. Here that is 2: the posted accounts
# array (all its item tokens count as ONE key) plus the schema's
# api_key default ("") that merge_with_defaults adds before
# separation.
# the separated secrets dict. Here that is 1: the posted accounts
# array, whose item tokens all count as ONE key.
#
# It was 2 before blank secrets were dropped, the second being the
# schema's api_key default (""), which merge_with_defaults adds to
# every save. Counting it was the visible edge of a real bug: that
# injected blank was merged over the stored api_key, so saving any
# unrelated field destroyed the credential. See
# test_an_unrelated_edit_does_not_erase_a_stored_secret.
resp = self._save(env, {
"accounts": [{"name": "a", "token": "t"}],
})
message = resp.get_json()["message"]
assert "(2 secret field(s) saved to config_secrets.json)" in message
assert "(1 secret field(s) saved to config_secrets.json)" in message
def test_an_unrelated_edit_does_not_erase_a_stored_secret(self, env):
"""Editing one field must not wipe the plugin's API key.
The config form renders secrets masked, so the browser posts them
back blank; merge_with_defaults injects a blank api_key even when
the client omits it entirely. Either way a "" reached the secrets
file and deep_merge wrote it over the stored credential.
"""
assert self._save(env, {"api_key": "REAL-KEY-0123456789",
"city": "Austin"}).status_code == 200
assert _on_disk(env.secrets_file)[PLUGIN_ID]["api_key"] == \
"REAL-KEY-0123456789"
# the user changes the city; the masked api_key rides along blank
assert self._save(env, {"api_key": "", "city": "Dallas"}).status_code == 200
assert _on_disk(env.secrets_file)[PLUGIN_ID]["api_key"] == \
"REAL-KEY-0123456789", "an unrelated edit destroyed the API key"
assert env.fresh_load()[PLUGIN_ID]["city"] == "Dallas"
def test_a_secret_can_still_be_changed(self, env):
"""Dropping blanks must not stop a real new value from being saved."""
self._save(env, {"api_key": "first-key"})
self._save(env, {"api_key": "second-key"})
assert _on_disk(env.secrets_file)[PLUGIN_ID]["api_key"] == "second-key"
def test_resave_replaces_stored_secrets_list_wholesale(self, env):
# Characterized: api_v3's deep_merge intentionally replaces lists,
+12 -1
View File
@@ -21,7 +21,8 @@ logger = logging.getLogger(__name__)
# Import new infrastructure
from src.web_interface.api_helpers import success_response, error_response, validate_request_json
from src.web_interface.errors import ErrorCode
from src.web_interface.secret_helpers import find_secret_fields, separate_secrets
from src.web_interface.secret_helpers import (find_secret_fields, remove_empty_secrets,
separate_secrets)
from src.web_interface.error_handler import describe_exception, redact_text
from src.plugin_system.operation_types import OperationType
from src.web_interface.validators import (
@@ -1216,6 +1217,11 @@ def save_main_config():
# Separate secrets from regular config (same logic as save_plugin_config)
regular_config, secrets_config = separate_secrets(plugin_config, secret_fields)
# The config form renders secrets masked, so every save posts
# them back blank. Without this the blank is merged over the
# stored value and the credential is destroyed by the act of
# changing an unrelated setting. A blank means "unchanged".
secrets_config = remove_empty_secrets(secrets_config)
# PRE-PROCESSING: Preserve 'enabled' state if not in regular_config
# This prevents overwriting the enabled state when saving config from a form that doesn't include the toggle
@@ -5599,6 +5605,11 @@ def save_plugin_config():
# Separate secrets from regular config (handles nested configs and
# array-item secrets — see src/web_interface/secret_helpers.py)
regular_config, secrets_config = separate_secrets(plugin_config, secret_fields)
# The config form renders secrets masked, so every save posts
# them back blank. Without this the blank is merged over the
# stored value and the credential is destroyed by the act of
# changing an unrelated setting. A blank means "unchanged".
secrets_config = remove_empty_secrets(secrets_config)
# Get current configs
current_config = api_v3.config_manager.load_config()