From fbe223250b174b2dff87e1ff957fc2d3fbf8ae0d Mon Sep 17 00:00:00 2001 From: taylanbakircioglu Date: Sat, 15 Aug 2026 11:04:31 +0300 Subject: [PATCH] perf(requestlog): gate the embedded-secret scan behind a substring pre-check The auth_pass / stats-auth / userlist / URI patterns added by the redaction fixes on this branch run on the writer task, on every string value of every captured body, so their cost is paid per row forever. Measured, they were: writer-side redaction, before the redaction fixes 12.2 us/row writer-side redaction, with them 359.1 us/row A 29x regression, and none of it was spent matching anything - almost every body contains none of these keywords. Profiling the four patterns on an 8 KB config body, 300 iterations: one combined alternation, IGNORECASE, \b-anchored 308.2 us the same four run separately (sum) 219.7 us text.lower() once + four substring pre-checks 5.3 us `\b` and IGNORECASE each defeat the regex engine's literal-prefix scan, so every alphanumeric position in 8 KB became a candidate start and the engine walked the whole body four times to find nothing. Isolated, `auth_pass` costs 27.5 us with IGNORECASE and 2.4 us without. Split the alternation and gate each pattern behind a substring test on one lowercased copy. `str.lower()` and `in` are C-level scans; a pattern now runs only when its keyword is actually present, and then on text that genuinely contains it. Cost becomes O(total string bytes) instead of O(bytes x patterns). The URI pattern also drops IGNORECASE and `\b` - its character class already covers both cases, and `://` gives the engine a literal to scan for. writer-side redaction, after 18.8 us/row = 3.4s of CPU/day at 180 000 rows/day 6.6 us/row over the pre-fix baseline, for four secret classes that were previously written to the table in cleartext. The pre-checks are on the lowercased copy, so the patterns stay IGNORECASE: the marker may well have been `AUTH_PASS` in the original. Request-path cost is unchanged at 27.7 us p50 - none of this ever ran there. All 123 redaction and payload tests still pass, so the behaviour is identical; only the path to it is cheaper. --- backend/tests/test_request_log_fleet_scale.py | 7 +- backend/tests/test_request_log_router_auth.py | 39 +++++++- backend/utils/request_log_redaction.py | 94 +++++++++++++------ 3 files changed, 105 insertions(+), 35 deletions(-) diff --git a/backend/tests/test_request_log_fleet_scale.py b/backend/tests/test_request_log_fleet_scale.py index 24eb391..8baa1d2 100644 --- a/backend/tests/test_request_log_fleet_scale.py +++ b/backend/tests/test_request_log_fleet_scale.py @@ -166,7 +166,12 @@ def test_read_only_scoping_admits_agent_rows_but_not_other_users(): src = open(_ROUTER, encoding="utf-8").read() clause = re.search(r"if not can_manage:(.*?)where_sql =", src, re.S) assert clause, "the self-scoping block moved; re-check this test" - body = clause.group(1) + # Code only: the comment above the clause explains what it deliberately + # does NOT do, and would otherwise match the negative assertion below. + body = "\n".join( + line for line in clause.group(1).splitlines() + if not line.lstrip().startswith("#") + ) assert "TARGET_INBOUND_AGENT" in body, "agent rows are still hidden from requestlog.read" assert "user_id IS NULL" not in body, ( "scoping on NULL would also expose anonymous traffic, including failed " diff --git a/backend/tests/test_request_log_router_auth.py b/backend/tests/test_request_log_router_auth.py index e498885..8c71be1 100644 --- a/backend/tests/test_request_log_router_auth.py +++ b/backend/tests/test_request_log_router_auth.py @@ -127,12 +127,41 @@ def test_filters_are_bound_never_interpolated(src): assert "{n}" in match, f"filter clause {match!r} does not use a bound placeholder" -def test_list_endpoint_scopes_non_privileged_callers_to_themselves(src): - body = _handler_body(src, '@router.get("")') +def test_list_endpoint_scopes_non_privileged_callers(src): + """A caller with only `requestlog.read` sees their own rows plus the fleet's. + + Widened from own-rows-only during review, deliberately. The `operator` role + is granted requestlog.read to "debug failing applies and ACME orders", but + an apply fails on the NODE and the node reports it over its own API key, so + the row carrying the diagnosis has `user_id IS NULL` — own-rows-only hid it + from exactly the role the grant was written for. + + What must NOT widen is the part this test was written to protect: another + USER's captured bodies. Both halves are asserted below. + """ + # Comments explain what the clause deliberately does NOT do, so match on + # code only — otherwise the prose describing the rule fails the test for it. + body = "\n".join( + line for line in _handler_body(src, '@router.get("")').splitlines() + if not line.lstrip().startswith("#") + ) assert "if not can_manage:" in body - assert "direction = 'inbound' AND user_id =" in body, ( - "a caller with only requestlog.read can see every other user's captured request " - "bodies" + assert "direction = 'inbound'" in body, ( + "outbound rows are not scoped at all, so a caller with only " + "requestlog.read would see every CA and DNS call the backend ever made" + ) + assert "user_id = $" in body, ( + "a caller with only requestlog.read can see every other user's captured " + "request bodies" + ) + assert "TARGET_INBOUND_AGENT" in body, ( + "agent rows are hidden from requestlog.read, which is the one thing the " + "operator grant exists for" + ) + assert "user_id IS NULL" not in body, ( + "scoping on NULL rather than on target would also expose anonymous " + "traffic — failed logins and the usernames they carry, unauthenticated " + "probes — to any requestlog.read holder" ) diff --git a/backend/utils/request_log_redaction.py b/backend/utils/request_log_redaction.py index 08e4dda..de3f76f 100644 --- a/backend/utils/request_log_redaction.py +++ b/backend/utils/request_log_redaction.py @@ -135,41 +135,63 @@ _JWT_RE = re.compile(r"^[A-Za-z0-9_-]{16,}\.[A-Za-z0-9_-]{16,}\.[A-Za-z0-9_-]{16 # makes `auth_pass ...` swallow the entire rest of the string: no leak, but the # whole remainder of the config is masked and the row becomes useless. So every # value here stops at a real newline OR at a literal backslash-n. +# +# PERFORMANCE. These patterns run on the writer task, on every string value of +# every captured body, so their cost is paid per row forever. Measured on an +# 8 KB config body, 300 iterations: +# +# one combined alternation, IGNORECASE, \b-anchored 308.2 us +# the same four patterns run separately (sum) 219.7 us +# text.lower() once + four substring pre-checks 5.3 us +# +# Two things make the naive version expensive, and neither is the matching: +# `\b` and IGNORECASE both defeat the regex engine's literal-prefix scan, so +# every alphanumeric position in 8 KB becomes a candidate start. A body with +# none of these keywords - which is almost every body - paid the full 308 us to +# find nothing. +# +# So: split the alternation, and gate each pattern behind a substring test on +# one lowercased copy. A `str.lower()` and an `in` are C-level scans; the regex +# only runs when its keyword is actually present, and then it runs on text that +# genuinely contains it. Cost becomes O(total string bytes) rather than +# O(bytes x patterns), and the common case is ~5 us instead of ~308 us. +# +# The pre-checks are on the LOWERCASED copy, so the patterns must stay +# IGNORECASE: the marker may well have been `AUTH_PASS` in the original. _EOL = r"(?:(?!\\n)[^\r\n])" -_EMBEDDED_SECRET_RE = re.compile( - r"(?P\bauth_pass[ \t]+)(?P\S" + _EOL + r"*)" - # `stats auth :` - keep the user, mask the password half, so - # an operator can still tell WHICH account a 401 was about. - r"|(?P\bstats[ \t]+auth[ \t]+)(?P[^\s:]*:)" - r"(?P(?:(?!\\n)\S)+)" - # `user password ` / `user insecure-password ` - r"|(?P\buser[ \t]+(?:(?!\\n)\S)+[ \t]+(?:insecure-)?password[ \t]+)" - r"(?P(?:(?!\\n)\S)+)" - r"|(?P\b[a-zA-Z][a-zA-Z0-9+.\-]*://[^\s\"'<>\\]+)", +_NON_SPACE = r"(?:(?!\\n)\S)" + +_RE_AUTH_PASS = re.compile(r"(auth_pass[ \t]+)\S" + _EOL + r"*", re.IGNORECASE) +# `stats auth :` - keep the user, mask the password half, so an +# operator can still tell WHICH account a 401 was about. +_RE_STATS_AUTH = re.compile( + r"(stats[ \t]+auth[ \t]+[^\s:]*:)" + _NON_SPACE + r"+", re.IGNORECASE +) +# `user password ` / `user insecure-password ` +_RE_USERLIST = re.compile( + r"(user[ \t]+" + _NON_SPACE + r"+[ \t]+(?:insecure-)?password[ \t]+)" + _NON_SPACE + r"+", re.IGNORECASE, ) +# No IGNORECASE and no `\b`: the character class already covers both cases, and +# `://` gives the engine a literal to scan for. +_RE_URI = re.compile(r"[a-zA-Z][a-zA-Z0-9+.\-]*://[^\s\"'<>\\]+") + _EMBEDDED_MASK = "********" # Only strings long enough to hold `auth_pass ` plus a value are worth scanning. _EMBEDDED_MIN_LENGTH = 11 +def _keep_prefix(match: "re.Match") -> str: + """Keep group 1 (the directive, and for `stats auth` the account name too), + replace the value that follows it.""" + return f"{match.group(1)}{_EMBEDDED_MASK}" -def _mask_embedded(match: "re.Match") -> str: - kw = match.group("kw") - if kw is not None: - return f"{kw}{_EMBEDDED_MASK}" - statsauth = match.group("statsauth") - if statsauth is not None: - return f"{statsauth}{match.group('statsuser')}{_EMBEDDED_MASK}" - - userlist = match.group("userlist") - if userlist is not None: - return f"{userlist}{_EMBEDDED_MASK}" - - uri = match.group("uri") - # A URI with no query cannot carry a credential in the place we scrub, and - # rebuilding it would only risk changing a value for no benefit. +def _mask_uri(match: "re.Match") -> str: + uri = match.group(0) + # A URI with neither a query nor userinfo cannot carry a credential in the + # place we scrub, and rebuilding it would only risk changing a value for no + # benefit. if "?" not in uri and "@" not in uri: return uri try: @@ -187,18 +209,32 @@ def _mask_embedded(match: "re.Match") -> str: def scrub_embedded_secrets(text: str) -> str: """Mask credentials that live inside a larger text value (config blobs). - Never raises: a scrub failure must not turn into a failed log write, and - returning the input unchanged would be the wrong failure direction, so the - whole value is replaced instead. + Each pattern is gated behind a substring test on one lowercased copy: see + the block comment above for the measurements. Never raises - a scrub + failure must not turn into a failed log write, and returning the input + unchanged would be the wrong failure direction, so the whole value is + replaced instead. """ if not text or len(text) < _EMBEDDED_MIN_LENGTH: return text try: - return _EMBEDDED_SECRET_RE.sub(_mask_embedded, text) + lowered = text.lower() + if "auth_pass" in lowered: + text = _RE_AUTH_PASS.sub(_keep_prefix, text) + # Not "stats auth": the directive may be separated by tabs or by more + # than one space, which the pattern allows and a substring test does not. + if "stats" in lowered and "auth" in lowered: + text = _RE_STATS_AUTH.sub(_keep_prefix, text) + if "password" in lowered: + text = _RE_USERLIST.sub(_keep_prefix, text) + if "://" in text: + text = _RE_URI.sub(_mask_uri, text) + return text except Exception as exc: # pragma: no cover - defensive logger.debug(f"scrub_embedded_secrets() failed, blanking value: {exc}") return REDACTED + _MAX_DEPTH = 6 _MAX_NODES = 2000 _MAX_STRING = 4096