Skip to content

Commit 7d17ea1

Browse files
CIclaude
andcommitted
Pin the redaction fingerprint's mappings, and cover the cache-hit path
Review of #5171: - _log_secret_fingerprint() recorded id(args)/id(secrets). A stored id is only an integer, so once the mapping it came from is freed CPython may hand that address to the next allocation and a same-length replacement landing there compares equal - skipping the rebuild and leaving a just-configured credential unredacted until the next explicit invalidation. It now holds the mappings themselves, compared by _log_secret_fingerprint_matches() with `is` so the recorded address always belongs to a live object and an equal-but-distinct mapping still counts as a change. - Corrected the lock comment: it is acquired on every _log_secret_pattern() call, so on every log line, and only held longer for a rebuild - not "only ever held for the duration of a rebuild". Records the cross-instance cost of sharing it, and that nothing reached under it logs, so there is no re-entrant path back into log() to deadlock a non-reentrant Lock. - test_log_secret_pattern_cache_is_reused() counts rebuilds, closing the gap where a regression that recompiled on every log line passed the whole suite. - test_log_secret_fingerprint_is_not_fooled_by_address_reuse() asserts the fingerprint refers to the mapping it describes (fails without the fix above). - The mixin test caught only AttributeError, so any other failure aborted the run instead of reporting a failed test. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent c6c4f53 commit 7d17ea1

2 files changed

Lines changed: 169 additions & 4 deletions

File tree

‎apps/predbat/log_secrets.py‎

Lines changed: 37 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -53,8 +53,17 @@ class LogRedaction:
5353
# each would each proceed inside their own - the exact interleaving it exists to prevent. A
5454
# class attribute is therefore shared by every instance, which is sound because all it guards
5555
# is the atomicity of one instance's "read sentinel, build, store"; making that atomic
56-
# process-wide is strictly stronger than making it per-instance, and it is only ever held for
57-
# the duration of a rebuild, which happens on a config change rather than per log line.
56+
# process-wide is strictly stronger than making it per-instance.
57+
#
58+
# It is acquired on every _log_secret_pattern() call, so on every log line, and held across
59+
# the fingerprint check - a handful of identity and len() reads - on the warm path; only a
60+
# rebuild holds it for longer, and rebuilds happen on a config change. Sharing it does mean a
61+
# rebuild on one instance briefly blocks log() on every other instance of the class, which
62+
# the single-engine production case never notices but a test process holding several engines
63+
# could (#5171 review). Nothing reached under the lock logs - collect_log_secret_values() and
64+
# compile_log_secret_pattern() are pure helpers in utils.py - so there is no re-entrant path
65+
# back into log() to deadlock a non-reentrant Lock, which is what makes sharing it safe
66+
# rather than merely cheap.
5867
_log_secret_pattern_lock = threading.Lock()
5968

6069
def _invalidate_log_secret_pattern(self):
@@ -78,6 +87,17 @@ def _log_secret_fingerprint(self):
7887
web.py's batch editor does via clear()/update() and web_chat.py does by assigning a new
7988
block.
8089
90+
The mappings themselves are held here, not their id(): a stored id() is only an integer,
91+
so once the mapping it was taken from is freed CPython is free to hand that same address
92+
to the next allocation, and a rebind to a same-length dict landing there would produce a
93+
fingerprint equal to the stored one - skipping the rebuild and leaving a just-configured
94+
credential unredacted until the next explicit invalidation (#5171 review). Holding the
95+
objects means an address recorded in a live fingerprint cannot be recycled while it is
96+
still recorded, at the cost of keeping a superseded args/secrets mapping reachable until
97+
the next rebuild. They are compared by _log_secret_fingerprint_matches() rather than ==,
98+
because == on two dicts is an O(number of values) comparison that would also report two
99+
distinct-but-equal mappings as unchanged - identity is the question being asked.
100+
81101
An in-place edit of an existing key that keeps the size the same is NOT caught here, so
82102
the explicit _invalidate_log_secret_pattern() call sites remain load-bearing. This is a
83103
safety net under them, not a replacement: with it, a missed or mis-ordered call site
@@ -88,7 +108,20 @@ def _log_secret_fingerprint(self):
88108
"""
89109
args = getattr(self, "args", None)
90110
secrets = getattr(self, "secrets", None)
91-
return (id(args), len(args) if isinstance(args, dict) else -1, id(secrets), len(secrets) if isinstance(secrets, dict) else -1)
111+
return (args, len(args) if isinstance(args, dict) else -1, secrets, len(secrets) if isinstance(secrets, dict) else -1)
112+
113+
@staticmethod
114+
def _log_secret_fingerprint_matches(left, right):
115+
"""
116+
Whether two fingerprints from _log_secret_fingerprint() describe the same args/secrets.
117+
118+
The mapping halves are compared with `is` and only their sizes with ==, so a rebind to an
119+
equal-but-distinct mapping counts as a change (a rebuild) rather than a match. `right` is
120+
None before the first build, which never matches a real fingerprint.
121+
"""
122+
if left is None or right is None:
123+
return left is right
124+
return left[0] is right[0] and left[1] == right[1] and left[2] is right[2] and left[3] == right[3]
92125

93126
def _log_secret_pattern(self):
94127
"""
@@ -111,7 +144,7 @@ def _log_secret_pattern(self):
111144
"""
112145
with self._log_secret_pattern_lock:
113146
fingerprint = self._log_secret_fingerprint()
114-
if self._log_secret_pattern_cache is self._LOG_SECRET_PATTERN_UNSET or fingerprint != self._log_secret_pattern_fingerprint:
147+
if self._log_secret_pattern_cache is self._LOG_SECRET_PATTERN_UNSET or not self._log_secret_fingerprint_matches(fingerprint, self._log_secret_pattern_fingerprint):
115148
args = getattr(self, "args", None)
116149
redact_strings = args.get("redact_strings") if args else None
117150
redact_strings_labelled = args.get("redact_strings_labelled") if args else None

‎apps/predbat/tests/test_secrets.py‎

Lines changed: 132 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -902,6 +902,13 @@ def __init__(self):
902902
except AttributeError as error:
903903
print("ERROR: redaction needed state that only Hass.__init__ establishes: {}".format(error))
904904
failed = True
905+
except Exception as error:
906+
# Not just AttributeError: log() has other ways to fail on an engine that skipped
907+
# Hass.__init__ (a TypeError from an unexpected mixin-state shape, predbat_log_count()),
908+
# and letting one escape would abort the whole suite run instead of reporting a failed
909+
# test like every other case here (#5171 review).
910+
print("ERROR: logging on an engine that skipped Hass.__init__ raised {}: {}".format(type(error).__name__, error))
911+
failed = True
905912
else:
906913
content = engine.logfile.getvalue()
907914
if "OVERLAY-SECRET-VALUE-5169" in content:
@@ -948,6 +955,129 @@ def __init__(self, args):
948955
return failed
949956

950957

958+
def test_log_secret_pattern_cache_is_reused():
959+
"""A second _log_secret_pattern() call must return the cached pattern without rebuilding it.
960+
961+
The rest of this suite asserts the cold path (a build happens), the invalidation call sites and
962+
the fingerprint safety net, but nothing counted rebuilds - so a regression that recomputed the
963+
value set and recompiled the regex on every log line, which is the one thing the cache exists
964+
to avoid on log()'s hot path, would have passed the whole suite silently (#5171 review).
965+
"""
966+
print("**** Testing the log redaction pattern is cached across calls ****")
967+
failed = False
968+
969+
# Patched in log_secrets.py's namespace, where _log_secret_pattern() looks the name up, for the
970+
# same reason as test_log_secret_pattern_build_is_not_racy().
971+
import log_secrets as log_secrets_module
972+
from log_secrets import LogRedaction
973+
974+
class CountingRedactor(LogRedaction):
975+
"""A mixin-only object, so a shared engine's own logging cannot disturb the build count."""
976+
977+
def __init__(self, args):
978+
"""Hold the args the redaction pattern is built from."""
979+
self.args = args
980+
981+
saved_collect = log_secrets_module.collect_log_secret_values
982+
builds = []
983+
984+
def counting_collect(*args, **kwargs):
985+
"""Count each rebuild on the way through to the real collector."""
986+
builds.append(1)
987+
return saved_collect(*args, **kwargs)
988+
989+
try:
990+
log_secrets_module.collect_log_secret_values = counting_collect
991+
redactor = CountingRedactor({"api_key": "CACHE-REUSE-SECRET-5171"})
992+
993+
first = redactor._log_secret_pattern()
994+
if len(builds) != 1:
995+
print("ERROR: the first call made {} builds, expected exactly 1".format(len(builds)))
996+
failed = True
997+
998+
stored_fingerprint = redactor._log_secret_pattern_fingerprint
999+
second = redactor._log_secret_pattern()
1000+
if len(builds) != 1:
1001+
print("ERROR: a second call rebuilt the pattern instead of returning the cached one - {} builds".format(len(builds)))
1002+
failed = True
1003+
if second is not first:
1004+
print("ERROR: a second call returned a different pattern object from the one it cached")
1005+
failed = True
1006+
if redactor._log_secret_pattern_fingerprint is not stored_fingerprint:
1007+
print("ERROR: a cache hit replaced the stored fingerprint, so it did not take the cached path")
1008+
failed = True
1009+
1010+
# A cache that can never be rebuilt would satisfy everything above just as well as a
1011+
# correct one, so confirm the counter still moves when it is supposed to.
1012+
redactor._invalidate_log_secret_pattern()
1013+
redactor._log_secret_pattern()
1014+
if len(builds) != 2:
1015+
print("ERROR: the pattern was not rebuilt after an invalidation - {} builds".format(len(builds)))
1016+
failed = True
1017+
finally:
1018+
log_secrets_module.collect_log_secret_values = saved_collect
1019+
1020+
if not failed:
1021+
print("**** test_log_secret_pattern_cache_is_reused PASSED ****")
1022+
return failed
1023+
1024+
1025+
def test_log_secret_fingerprint_is_not_fooled_by_address_reuse():
1026+
"""Rebinding args to a mapping that could land on the freed one's address must still rebuild.
1027+
1028+
The fingerprint is the safety net under the explicit invalidation call sites, so a false
1029+
"unchanged" verdict there is a leak rather than mere staleness: the rebuild is skipped and a
1030+
just-configured credential stays in plaintext until something else invalidates the cache.
1031+
Recording id(args) permitted exactly that - the id is only an integer, so CPython may hand the
1032+
freed mapping's address to the next allocation and a same-length replacement landing there
1033+
compares equal (#5171 review). The fingerprint holds the mappings themselves, which is what
1034+
keeps an address it recorded from being recycled while it is still recorded.
1035+
"""
1036+
print("**** Testing the redaction fingerprint is not fooled by a recycled mapping address ****")
1037+
failed = False
1038+
1039+
import gc
1040+
from utils import redact_log_line
1041+
from log_secrets import LogRedaction
1042+
1043+
class BareRedactor(LogRedaction):
1044+
"""An object carrying args and the redaction mixin, and nothing else."""
1045+
1046+
def __init__(self, args):
1047+
"""Hold the args the redaction pattern is built from."""
1048+
self.args = args
1049+
1050+
redactor = BareRedactor({"api_key": "FIRST-ADDRESS-SECRET-5171"})
1051+
if "FIRST-ADDRESS-SECRET-5171" in redact_log_line("Info: using FIRST-ADDRESS-SECRET-5171", redactor._log_secret_pattern()):
1052+
print("ERROR: the first pattern did not redact the args it was built from")
1053+
failed = True
1054+
1055+
# Rebind args and keep hold of the superseded mapping only through this local, so what the
1056+
# stored fingerprint retains is the question. Asserted by referrer rather than by trying to
1057+
# provoke a real address collision: whether CPython actually hands the freed address to the
1058+
# next allocation depends on the allocator's pool state, so a probe that allocates same-shaped
1059+
# dicts and looks for the old address passes with or without the fix and proves nothing. The
1060+
# property that rules the collision out is that the recorded address still belongs to a live
1061+
# object, which is exactly "the fingerprint refers to the mapping".
1062+
superseded_args = redactor.args
1063+
redactor.args = {"api_key": "SECOND-ADDRESS-SECRET-5171"}
1064+
gc.collect()
1065+
1066+
stored_fingerprint = redactor._log_secret_pattern_fingerprint
1067+
if not any(referrer is stored_fingerprint for referrer in gc.get_referrers(superseded_args)):
1068+
print("ERROR: the stored fingerprint does not refer to the mapping it describes, so that mapping can be freed and its address handed to a same-length replacement - which would compare as unchanged and skip the rebuild")
1069+
failed = True
1070+
1071+
second_line = redact_log_line("Info: using SECOND-ADDRESS-SECRET-5171", redactor._log_secret_pattern())
1072+
if "SECOND-ADDRESS-SECRET-5171" in second_line or "<api_key>" not in second_line:
1073+
print("ERROR: rebinding args to a same-length mapping did not rebuild the pattern: {}".format(second_line))
1074+
failed = True
1075+
1076+
if not failed:
1077+
print("**** test_log_secret_fingerprint_is_not_fooled_by_address_reuse PASSED ****")
1078+
return failed
1079+
1080+
9511081
def test_resolve_arg_re_masks_secret_arg_matches(my_predbat):
9521082
"""
9531083
resolve_arg_re() logs the entity id it matched before auto_config()'s caller has invalidated
@@ -1004,6 +1134,8 @@ def run_secrets_tests(my_predbat=None):
10041134
failed |= test_log_redaction_survives_a_missed_invalidation(my_predbat)
10051135
failed |= test_auto_config_invalidates_log_secret_cache(my_predbat)
10061136
failed |= test_log_redaction_mixin_needs_no_init()
1137+
failed |= test_log_secret_pattern_cache_is_reused()
1138+
failed |= test_log_secret_fingerprint_is_not_fooled_by_address_reuse()
10071139
failed |= test_log_secret_pattern_build_is_not_racy(my_predbat)
10081140
failed |= test_resolve_arg_re_masks_secret_arg_matches(my_predbat)
10091141
return failed

0 commit comments

Comments
 (0)