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
5 changed files with 103 additions and 124 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,
+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
)
-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()