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
4 changed files with 49 additions and 161 deletions
+1 -54
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,54 +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
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.
-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()
@@ -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()