Compare commits

..
Author SHA1 Message Date
ChuckBuilds fc6104f229 fix(web): stop /config/main handing out every credential it holds
The endpoint returned the raw config to anyone who could reach the port, and
this web interface has no authentication of any kind. An unauthenticated
request against a live rig returned:

    github.api_token                40 chars
    incoming-packages.ha_token     183 chars
    jellyfin-now-playing.api_key    32 chars
    ledmatrix-weather.api_key       32 chars
    on-air.mqtt_password             8 chars
    youtube.api_key                 20 chars
    youtube-stats.api_key           39 chars

A GitHub token and a Home Assistant long-lived token among them. Anything on
that LAN could read them.

The x-secret masking the plugin config endpoints use does not reach here: this
route never consults a schema, and core keys such as github.api_token have no
schema to carry the marker. Several of the fields above *are* tagged x-secret
in their plugin's schema and were still returned in full, which is what rules
out the schema route as the fix for this endpoint.

Credential-named fields are now blanked. Matching on the name is blunt, and
for a whole-config dump that is the right default: anything named like a
credential should not leave the process, and a new plugin adding a
differently-shaped secret is covered without anyone remembering to tag it.

Blanked rather than removed, and safe to blank: POST /config/main merges into
the freshly loaded config and writes only the keys it was given, so a client
that round-trips this response cannot erase a secret it never saw. The web API
suites confirm it -- 81 passing, unchanged.

On the test that matters: the first version of this suite exercised the two
helpers and nothing else, and reverting the single line that wires the
redactor into the route passed all thirty of them. A property asserted on a
helper is not a property asserted on the endpoint, and it is the endpoint that
is exposed to the network. The added test goes through the view function, and
it does fail on that revert.

This also corrects an earlier claim of mine. I reported that GET /api/v3/config
did not expose these values; that path 404s, so the check proved nothing. The
real route is /config/main and it exposed all of them.
2026-08-20 05:09:12 -04:00
10 changed files with 248 additions and 438 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.debug( self.logger.info(
"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,
+1 -66
View File
@@ -130,12 +130,7 @@ def setup_logging(
# Console handler (always add) # Console handler (always add)
console_handler = logging.StreamHandler(sys.stdout) console_handler = logging.StreamHandler(sys.stdout)
console_handler.setLevel(level) console_handler.setLevel(level)
# Under systemd, tag each line so the journal records the real severity console_handler.setFormatter(formatter)
# 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)
root_logger.addHandler(console_handler) root_logger.addHandler(console_handler)
# File handler (if specified) # 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") 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): class PluginLoggerAdapter(logging.LoggerAdapter):
"""LoggerAdapter that stamps every record with its plugin_id. """LoggerAdapter that stamps every record with its plugin_id.
-21
View File
@@ -178,20 +178,10 @@ class PluginHealthTracker:
) )
return self._health_state[plugin_id] 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: def record_success(self, plugin_id: str) -> None:
"""Record a successful plugin execution.""" """Record a successful plugin execution."""
state = self.get_health_state(plugin_id) state = self.get_health_state(plugin_id)
current_time = time.time() current_time = time.time()
durable_before = self._durable(state)
# Reset consecutive failures # Reset consecutive failures
state['consecutive_failures'] = 0 state['consecutive_failures'] = 0
@@ -209,17 +199,6 @@ class PluginHealthTracker:
state['circuit_state'] = CircuitState.CLOSED.value state['circuit_state'] = CircuitState.CLOSED.value
state['circuit_opened_time'] = None 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: def record_failure(self, plugin_id: str, error: Optional[Exception] = None) -> None:
+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.debug( logger.info(
"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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.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: 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.debug( logger.info(
"[%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.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) # 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.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) 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.debug( logger.info(
"[%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.debug("[%s] ScrollHelper content returned None", plugin_id) logger.info("[%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.debug( logger.info(
"[%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.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) 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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.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 # 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.debug( logger.info(
"[%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.debug("[%s] Native: get_vegas_content() returned None", plugin_id) logger.info("[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug("[%s] Native: no valid images after validation", plugin_id) logger.info("[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.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 # Ensure plugin has fresh data before capturing
has_update_data = hasattr(plugin, 'update_data') 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: if has_update_data:
try: try:
plugin.update_data() 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): 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.debug( logger.info(
"[%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.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) # First try without force_clear (some plugins behave better this way)
try: try:
plugin.display() plugin.display()
logger.debug("[%s] Fallback: display() called successfully", plugin_id) logger.info("[%s] Fallback: display() called successfully", plugin_id)
except TypeError: except TypeError:
# Plugin may require force_clear argument # 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) plugin.display(force_clear=True)
# Capture the result # Capture the result
captured = self.display_manager.image.copy() captured = self.display_manager.image.copy()
logger.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%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.debug( logger.info(
"[%s] Fallback: SUCCESS - captured %dx%d", "[%s] Fallback: SUCCESS - captured %dx%d",
plugin_id, captured.width, captured.height plugin_id, captured.width, captured.height
) )
+143
View File
@@ -0,0 +1,143 @@
"""GET /config/main must not hand out credentials.
The endpoint returned the raw config to anyone who could reach the port, and
this web interface has no authentication of any kind. Measured against a live
rig, an unauthenticated request returned:
github.api_token 40 chars
incoming-packages.ha_token 183 chars
jellyfin-now-playing.api_key 32 chars
ledmatrix-weather.api_key 32 chars
on-air.mqtt_password 8 chars
youtube.api_key 20 chars
youtube-stats.api_key 39 chars
A GitHub token and a Home Assistant long-lived token among them.
The x-secret masking the plugin config endpoints use does not apply here: this
endpoint never consults a schema, and core keys such as github.api_token have
no schema to carry the marker. Several of those fields *are* tagged x-secret in
their plugin's schema and were still returned in full, which is what makes the
schema route the wrong one to rely on for this endpoint.
Matching on field name is blunt. For a whole-config dump it is the right
default: anything named like a credential should not leave the process, and a
new plugin that adds a differently-shaped secret is covered without anyone
remembering to tag it.
"""
import pytest
from web_interface.blueprints.api_v3 import (
_looks_like_a_credential,
_redact_credentials,
)
@pytest.mark.parametrize("name", [
"password", "mqtt_password", "opensky_password", "passwd",
"api_key", "apikey", "API_KEY", "flightaware_api_key",
"token", "ha_token", "api_token", "access_token",
"secret", "client_secret", "spotify_client_secret",
"access_key", "private_key",
])
def test_credential_names_are_recognised(name):
assert _looks_like_a_credential(name)
@pytest.mark.parametrize("name", [
"timezone", "city", "brightness", "enabled", "update_interval",
"favorite_teams", "display_duration", "keyword",
])
def test_ordinary_names_are_left_alone(name):
assert not _looks_like_a_credential(name)
def test_the_measured_leak_is_closed():
"""The exact shape taken off the rig."""
config = {
"github": {"api_token": "ghp_" + "x" * 36},
"incoming-packages": {"ha_token": "y" * 183, "enabled": True},
"jellyfin-now-playing": {"api_key": "z" * 32},
"on-air": {"mqtt_password": "hunter22"},
"youtube": {"api_key": "k" * 20},
"timezone": "America/New_York",
}
out = _redact_credentials(config)
assert out["github"]["api_token"] == ""
assert out["incoming-packages"]["ha_token"] == ""
assert out["jellyfin-now-playing"]["api_key"] == ""
assert out["on-air"]["mqtt_password"] == ""
assert out["youtube"]["api_key"] == ""
# Everything else survives, or the config editor breaks.
assert out["timezone"] == "America/New_York"
assert out["incoming-packages"]["enabled"] is True
def test_nested_and_listed_credentials_are_reached():
config = {"a": {"b": {"c": {"password": "p"}}},
"feeds": [{"name": "x", "api_key": "k"}, {"name": "y"}]}
out = _redact_credentials(config)
assert out["a"]["b"]["c"]["password"] == ""
assert out["feeds"][0]["api_key"] == ""
assert out["feeds"][0]["name"] == "x"
def test_the_original_is_not_mutated():
"""The caller holds the live config; redaction must not edit it in place."""
config = {"github": {"api_token": "keepme"}}
_redact_credentials(config)
assert config["github"]["api_token"] == "keepme"
def test_a_credential_shaped_container_is_still_walked():
"""`secrets: {...}` is a section name, not a value to blank."""
config = {"secrets": {"api_key": "k", "note": "keep"}}
out = _redact_credentials(config)
assert out["secrets"]["api_key"] == ""
assert out["secrets"]["note"] == "keep"
def test_non_dict_input_passes_through():
assert _redact_credentials("plain") == "plain"
assert _redact_credentials(7) == 7
assert _redact_credentials(None) is None
def test_the_endpoint_itself_redacts():
"""Through the view function, not the helper.
The helper tests above all passed with the route still returning
`config` -- reverting the one line that calls the redactor changed
nothing, because nothing exercised the route. A property asserted on a
helper is not a property asserted on the endpoint, and it is the endpoint
that is exposed to the network.
"""
import json as _json
from unittest.mock import MagicMock
import flask
from web_interface.blueprints import api_v3 as mod
raw = {"github": {"api_token": "ghp_secret_value"},
"timezone": "America/New_York"}
manager = MagicMock()
manager.load_config.return_value = raw
previous = getattr(mod.api_v3, "config_manager", None)
mod.api_v3.config_manager = manager
app = flask.Flask(__name__)
try:
with app.test_request_context("/config/main"):
response = mod.get_main_config()
payload = response.get_json() if hasattr(response, "get_json") else _json.loads(response[0].data)
finally:
mod.api_v3.config_manager = previous
data = payload["data"]
assert data["github"]["api_token"] == "", (
"the endpoint returned the token; the redactor is not wired in")
assert data["timezone"] == "America/New_York"
# And the config the manager handed over is untouched.
assert raw["github"]["api_token"] == "ghp_secret_value"
-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() setup_logging()
assert len(logging.getLogger().handlers) == 1 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): def test_json_format_selects_structured_formatter(self):
setup_logging(format_type="json") 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): def test_readable_format_selects_contextual_formatter(self):
setup_logging(format_type="readable") 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): def test_log_file_adds_file_handler(self, tmp_path):
log_file = tmp_path / "test.log" 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
+41 -2
View File
@@ -262,15 +262,54 @@ def _stop_display_service():
result['status'] = status result['status'] = status
return result return result
#: Field names whose value is a credential. Matched by name because this
#: endpoint returns the whole config, core keys included, and core config has
#: no schema to carry x-secret markers.
_CREDENTIAL_NAME_PARTS = ("password", "passwd", "secret", "token", "api_key",
"apikey", "access_key", "private_key", "client_secret")
def _looks_like_a_credential(name: str) -> bool:
lowered = name.lower()
return any(part in lowered for part in _CREDENTIAL_NAME_PARTS)
def _redact_credentials(value):
"""A copy of `value` with credential-named fields blanked.
/config/main returned the raw config to anyone who could reach the port,
and this interface has no authentication. On one rig that meant a 40-char
GitHub token, a 183-char Home Assistant token and five API keys were
readable by anything on the LAN.
The x-secret masking used by the plugin config endpoints does not help
here: this endpoint never consults a schema, and core keys such as
github.api_token have no schema to mark. Matching on the field name is
blunt, but for a whole-config dump the right default is that anything
named like a credential does not leave the process.
Blanked rather than removed, and safe to blank: POST /config/main merges
into the loaded config and only writes the keys it was given, so a client
that round-trips this response cannot erase a secret it never saw.
"""
if isinstance(value, dict):
return {k: ("" if _looks_like_a_credential(k) and not isinstance(v, (dict, list))
else _redact_credentials(v))
for k, v in value.items()}
if isinstance(value, list):
return [_redact_credentials(item) for item in value]
return value
@api_v3.route('/config/main', methods=['GET']) @api_v3.route('/config/main', methods=['GET'])
def get_main_config(): def get_main_config():
"""Get main configuration""" """Get main configuration, with credentials redacted."""
try: try:
if not api_v3.config_manager: if not api_v3.config_manager:
return jsonify({'status': 'error', 'message': 'Config manager not initialized'}), 500 return jsonify({'status': 'error', 'message': 'Config manager not initialized'}), 500
config = api_v3.config_manager.load_config() config = api_v3.config_manager.load_config()
return jsonify({'status': 'success', 'data': config}) return jsonify({'status': 'success', 'data': _redact_credentials(config)})
except Exception as e: except Exception as e:
logger.error('Unhandled exception', exc_info=True) logger.error('Unhandled exception', exc_info=True)
return jsonify({'status': 'error', 'message': 'An error occurred; see logs for details', 'details': describe_exception(e)}), 500 return jsonify({'status': 'error', 'message': 'An error occurred; see logs for details', 'details': describe_exception(e)}), 500