Skip to content

Commit d3585d6

Browse files
fix(security): address the follow-up Copilot review on #5053 - numeric secrets, overlap redaction, a load_secrets() crash, a cache race, and a label-priority bug
Six findings from a second round of Copilot review on the #4770 write-time log redaction PR, all confirmed and fixed. Numeric secrets.yaml/redact_strings_labelled values silently dropped (utils.py) ----------------------------------------------------------------------------- collect_log_secret_values() checked isinstance(value, str), so an unquoted numeric MPAN/account ID (landlord_mpan: 1234567890123) loaded from YAML as an int and was silently skipped - never redacted even though log() serializes every message with str(msg). Scalar secrets.yaml and redact_strings_labelled values are now coerced to string before matching (bools excluded, to avoid "True"/"False" matching ordinary log text). redact_strings_labelled schema gave no warning for a non-string value (config.py, predbat.py) ----------------------------------------------------------------------------------------------- The dict-type validator only checked the mapping itself, never its values, so the numeric-MPAN case above passed validation with no warning at all. Added a scalar_value_dict schema flag, checked in validate_config()'s dict branch, that warns (not errors - the value is still usable once coerced) when a mapping value isn't already a string. Two overlapping secrets at different start positions left part of the longer one exposed (utils.py) ------------------------------------------------------------------------------------------------------- pattern.sub() finds the first alternative that matches at the earliest position and resumes scanning after it, so "sec1" and "c123x" both present in "sec123x" only ever matched "sec1" - "c123x" starting one character in was never considered, leaking "23x". redact_log_line() now extends each match to the longest secret starting anywhere inside its span before emitting the mask, chasing chained overlaps until the span stabilises. A malformed secrets.yaml (valid YAML, wrong shape) crashed startup entirely (hass.py) ----------------------------------------------------------------------------------------- load_secrets() only guarded yaml.safe_load()'s exceptions, not a load that succeeds with the wrong shape - a bare scalar/list secrets.yaml reassigns the local `secrets` before the next line's secrets.get("logger") call throws AttributeError. The except caught that, but the reassignment had already happened, so load_secrets() still returned the malformed value - and the very next log() call crashed unhandled reaching collect_log_secret_values()'s secrets.items(). Now checked explicitly and degraded to {} with a warning. The cached redaction pattern build was racy against a concurrent invalidation (hass.py) --------------------------------------------------------------------------------------------- log() runs from component threads as well as the main thread, so two threads could both observe the UNSET sentinel and race to rebuild: a thread that started building from stale args right before another thread invalidated the cache could finish second and overwrite the fresh invalidation with its stale pattern, silently keeping a just-added credential unredacted. Added a lock making "read sentinel, build, store" one atomic step, and two missed invalidation call sites (web_chat.py's provider save, chat_tools.py's set_apps_config) that could leave a saved credential under the stale pattern. redact_strings raced its own more-specific label (utils.py) ------------------------------------------------------------- redact_strings/redact_strings_labelled are secret-flagged (via SECRET_KEY_EXPLICIT_NAMES) so mask_secret_args()'s debug-dump masking hides them wholesale - but that same flag made the generic args-traversal pass in _collect_secret_values() pick up redact_strings as an ordinary secret-valued key too, labelling its values generically BEFORE the dedicated redact_strings_labelled pass ran with its documented "specific label wins" priority. A value present in both denylist forms kept the generic label instead. The two true top-level keys are now skipped in that traversal (an unrelated nested key sharing the name still collects normally). All six verified with mutation testing against the actual fix: reverting each one in turn reproduces exactly the failure the corresponding new/extended test describes, and only that test fails. ./run_all --quick and ./run_pre_commit both green. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
1 parent 2ae7745 commit d3585d6

12 files changed

Lines changed: 404 additions & 22 deletions

‎apps/predbat/chat_tools.py‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -771,6 +771,11 @@ def set_apps_config(base, key, value, apps_yaml_path=APPS_YAML_PATH, backup_path
771771
return {"success": False, "error": "Could not write apps.yaml: {}".format(error), "data": None}
772772

773773
base.args[key] = value
774+
# The written key can itself be a credential (or the redact_strings/redact_strings_labelled
775+
# denylists), so log()'s cached redaction pattern (hass.py) must be rebuilt on next use or a
776+
# newly saved value keeps leaking into the log under the stale pattern until restart (#5053
777+
# review).
778+
base._invalidate_log_secret_pattern()
774779

775780
description = "Changed apps.yaml key '{}' from {!r} to {!r}. {}".format(key, previous_value, value, APPS_YAML_RESTART_WARNING)
776781
return {

‎apps/predbat/config.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2806,5 +2806,5 @@
28062806
# <your_label> instead of the generic <redact_strings>, the same way a built-in credential is
28072807
# labelled by its own apps.yaml key name - e.g. "my_landlords_mpan: '1234567890123'" redacts
28082808
# as <my_landlords_mpan> rather than every entry collapsing into one indistinguishable label.
2809-
"redact_strings_labelled": {"type": "dict"},
2809+
"redact_strings_labelled": {"type": "dict", "scalar_value_dict": True},
28102810
}

‎apps/predbat/hass.py‎

Lines changed: 46 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -185,6 +185,16 @@ class Hass:
185185
# rebuild (recompute the value set, recompile) on every single log() call instead of caching.
186186
_LOG_SECRET_PATTERN_UNSET = object()
187187

188+
def _invalidate_log_secret_pattern(self):
189+
"""
190+
Mark the cached redaction pattern stale so the next log() call rebuilds it from the
191+
current args/secrets (GH#4770). Every call site that mutates self.args or self.secrets
192+
after startup must call this - see _log_secret_pattern()'s docstring for why a missed
193+
site is a real leak, not just a staleness bug.
194+
"""
195+
with self._log_secret_pattern_lock:
196+
self._log_secret_pattern_cache = self._LOG_SECRET_PATTERN_UNSET
197+
188198
def _log_secret_pattern(self):
189199
"""
190200
Return the cached compiled redaction pattern log() must apply, rebuilding it the first
@@ -194,14 +204,24 @@ def _log_secret_pattern(self):
194204
args/secrets only change on startup and on a config reload, so rebuilding the value set
195205
and recompiling the pattern that rarely - rather than on every call - keeps the
196206
redaction check to a single compiled-regex scan per line on the hot path.
207+
208+
Guarded by a lock, not just the sentinel check: log() runs from component threads as well
209+
as the main thread (create_task()), so two threads can both observe the sentinel and race
210+
to rebuild. Without the lock, a thread that started building from stale args right before
211+
another thread invalidates the cache (a credential just added via set_arg()) can finish
212+
second and overwrite the fresh invalidation with its stale, already-out-of-date pattern -
213+
silently keeping the just-added credential unredacted until something invalidates the
214+
cache again. The lock makes "read sentinel, build, store" one atomic step so a build that
215+
started before an invalidation can never win a race against it.
197216
"""
198-
if self._log_secret_pattern_cache is self._LOG_SECRET_PATTERN_UNSET:
199-
args = getattr(self, "args", None)
200-
redact_strings = args.get("redact_strings") if args else None
201-
redact_strings_labelled = args.get("redact_strings_labelled") if args else None
202-
values = collect_log_secret_values(args, getattr(self, "secrets", None), redact_strings, redact_strings_labelled)
203-
self._log_secret_pattern_cache = compile_log_secret_pattern(values)
204-
return self._log_secret_pattern_cache
217+
with self._log_secret_pattern_lock:
218+
if self._log_secret_pattern_cache is self._LOG_SECRET_PATTERN_UNSET:
219+
args = getattr(self, "args", None)
220+
redact_strings = args.get("redact_strings") if args else None
221+
redact_strings_labelled = args.get("redact_strings_labelled") if args else None
222+
values = collect_log_secret_values(args, getattr(self, "secrets", None), redact_strings, redact_strings_labelled)
223+
self._log_secret_pattern_cache = compile_log_secret_pattern(values)
224+
return self._log_secret_pattern_cache
205225

206226
def log(self, msg, quiet=True):
207227
"""
@@ -302,10 +322,22 @@ def load_secrets(self):
302322
self.log(f"Loading secrets from {secrets_file}", quiet=False)
303323
try:
304324
with io.open(secrets_file, "r") as stream:
305-
secrets = yaml.safe_load(stream) or {}
306-
# Check for debug logging option
307-
if secrets.get("logger") == "debug":
308-
self.log(f"Info: Secrets loaded from {secrets_file}", quiet=False)
325+
loaded = yaml.safe_load(stream) or {}
326+
if not isinstance(loaded, dict):
327+
# Valid YAML (a bare scalar or list at the top level) but the wrong shape -
328+
# yaml.safe_load() raises nothing here, so without this check `secrets`
329+
# below would be reassigned to that scalar/list before the .get() call two
330+
# lines down throws AttributeError. The generic except then logs the crash
331+
# but the reassignment has already happened and is never undone, so
332+
# load_secrets() still returns the malformed value - and the very next
333+
# log() call reaches collect_log_secret_values()'s secrets.items(), which
334+
# raises unhandled and aborts startup entirely (#5053 review).
335+
self.log(f"Error: secrets.yaml at {secrets_file} must be a mapping of name: value, found {type(loaded).__name__} - ignoring it", quiet=False)
336+
else:
337+
secrets = loaded
338+
# Check for debug logging option
339+
if secrets.get("logger") == "debug":
340+
self.log(f"Info: Secrets loaded from {secrets_file}", quiet=False)
309341
except yaml.YAMLError as exc:
310342
self.log(f"Error: Failed to load secrets from {secrets_file}: {exc}", quiet=False)
311343
except Exception as exc:
@@ -335,13 +367,14 @@ def __init__(self):
335367
self.threads = []
336368
self.fatal_error = False
337369
self.hass_api_version = 2
370+
self._log_secret_pattern_lock = threading.Lock()
338371
self._log_secret_pattern_cache = self._LOG_SECRET_PATTERN_UNSET
339372

340373
self.logfile = open("predbat.log", "a")
341374

342375
# Load secrets first
343376
self.secrets = self.load_secrets()
344-
self._log_secret_pattern_cache = self._LOG_SECRET_PATTERN_UNSET
377+
self._invalidate_log_secret_pattern()
345378

346379
# Register custom YAML constructor for !secret tag
347380
yaml.add_constructor("!secret", self.secret_constructor, Loader=yaml.SafeLoader)
@@ -353,7 +386,7 @@ def __init__(self):
353386
try:
354387
config = yaml.safe_load(stream)
355388
self.args = config["pred_bat"]
356-
self._log_secret_pattern_cache = self._LOG_SECRET_PATTERN_UNSET
389+
self._invalidate_log_secret_pattern()
357390
except yaml.YAMLError as exc:
358391
print(exc)
359392
sys.exit(1)

‎apps/predbat/predbat.py‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1641,6 +1641,18 @@ def validate_config(self):
16411641
self.arg_errors[name] = "Invalid type, element {} expected dict".format(item)
16421642
errors += 1
16431643
break
1644+
1645+
# scalar_value_dict (e.g. redact_strings_labelled): a mapping value
1646+
# that isn't already a string passes this branch silently since it
1647+
# only checks item is a dict, but the consumer collecting these
1648+
# values only matches strings - an unquoted numeric MPAN/account ID
1649+
# loads from YAML as an int and would otherwise go unredacted with
1650+
# no warning at all (#5053 review). Warn, don't error: the value is
1651+
# still usable once coerced to a string by the collector.
1652+
if spec.get("scalar_value_dict", False):
1653+
for key, sub_value in item.items():
1654+
if not isinstance(sub_value, str):
1655+
self.log("Warn: Validation of apps.yaml found configuration item '{}' entry '{}' value {} is not a string - quote it to ensure it is matched".format(name, key, sub_value))
16441656
elif expected_type == "int_float_dict":
16451657
if spec.get("or_auto", False) and value == "auto":
16461658
matches = True

‎apps/predbat/tests/test_chat_tools.py‎

Lines changed: 40 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,7 @@
2828
import tempfile
2929

3030
import chat_tools
31-
from utils import mask_secret_args, parse_yaml_path
31+
from utils import mask_secret_args, parse_yaml_path, compile_log_secret_pattern
3232
from chat_tools import CHAT_TOOL_DEFS, DOCS_READ_MAX_CHARS, read_docs, score_documents, search_docs, read_source, search_source, resolve_source_path, SourceAccessError, is_endpoint_key
3333
from chat_tools import DEFAULT_FETCH_ALLOWLIST, FetchRefusedError, host_allowed, html_to_text, validate_fetch_target
3434
from chat_tools import APPS_YAML_RESTART_WARNING, set_apps_config, validate_apps_schema_type
@@ -922,6 +922,44 @@ def test_set_apps_config_success_preserves_formatting_backs_up_and_mirrors_args(
922922
return failed
923923

924924

925+
def test_set_apps_config_success_invalidates_log_secret_cache(my_predbat):
926+
"""A successful write must invalidate log()'s cached redaction pattern (#5053 review).
927+
928+
set_apps_config() writes straight to base.args (base.args[key] = value) rather than going
929+
through set_arg() or the web editor's batch apply - both of which already invalidate the
930+
cache - so it was its own separate gap: a credential-adjacent value saved through the chat
931+
agent's tool would keep leaking into the log under the stale pattern until restart, the same
932+
class of bug GH#4770 exists to close.
933+
"""
934+
failed = False
935+
print("**** Testing set_apps_config invalidates the cached log redaction pattern ****")
936+
root = tempfile.mkdtemp(prefix="predbat_apps_")
937+
original_args_value = my_predbat.args.get("num_inverters")
938+
saved_cache = my_predbat._log_secret_pattern_cache
939+
try:
940+
apps_path = _apps_yaml_fixture(root)
941+
backup_path = apps_path + ".backup"
942+
my_predbat.args["num_inverters"] = 1
943+
# A stale value built the real way, not an arbitrary sentinel - matches the convention in
944+
# test_web_apps_edit.py's equivalent cache-invalidation test.
945+
stale_cache_marker = compile_log_secret_pattern({"stale-pattern-marker-5053xx": "marker"})
946+
my_predbat._log_secret_pattern_cache = stale_cache_marker
947+
948+
result = set_apps_config(my_predbat, "num_inverters", 2, apps_yaml_path=apps_path, backup_path=backup_path)
949+
950+
if not result.get("success"):
951+
print("ERROR: a valid change was refused: {}".format(result))
952+
return True
953+
if my_predbat._log_secret_pattern_cache is stale_cache_marker:
954+
print("ERROR: a successful set_apps_config write left the cached log redaction pattern stale")
955+
failed = True
956+
finally:
957+
my_predbat.args["num_inverters"] = original_args_value
958+
my_predbat._log_secret_pattern_cache = saved_cache
959+
shutil.rmtree(root, ignore_errors=True)
960+
return failed
961+
962+
925963
def test_validate_apps_schema_type(my_predbat):
926964
"""validate_apps_schema_type checks a value's shape against APPS_SCHEMA, permissively for a
927965
key with no schema entry at all - not every apps.yaml key is declared there."""
@@ -1385,5 +1423,6 @@ def run_chat_tools_tests(my_predbat):
13851423
failed |= test_set_apps_config_refuses_unknown_key(my_predbat)
13861424
failed |= test_set_apps_config_refuses_a_schema_type_mismatch(my_predbat)
13871425
failed |= test_set_apps_config_success_preserves_formatting_backs_up_and_mirrors_args(my_predbat)
1426+
failed |= test_set_apps_config_success_invalidates_log_secret_cache(my_predbat)
13881427
failed |= test_validate_apps_schema_type(my_predbat)
13891428
return failed

0 commit comments

Comments
 (0)