diff --git a/backend/app/logs.py b/backend/app/logs.py index 135e35ee..700c6aa6 100644 --- a/backend/app/logs.py +++ b/backend/app/logs.py @@ -182,9 +182,25 @@ _SECRET_KEY_PARTS = ( # Query/fragment parameters that carry a credential in a URL we log (OAuth `code`/`state`, our own # `?token=` setup and share links, `#verify=` / `#reset=` fragments). +_SECRET_PARAM_NAMES = ( + "access_token", + "refresh_token", + "id_token", + "token", + "code", + "state", + "key", + "secret", + "password", + "pwd", + "sig", + "signature", + "verify", + "reset", + "setup", +) _SECRET_PARAM_RE = re.compile( - r"\b((?:access_token|refresh_token|id_token|token|code|state|key|secret|password|pwd|sig|" - r"signature|verify|reset|setup)=)([^&\s\"']+)", + r"\b((?:" + "|".join(_SECRET_PARAM_NAMES) + r")=)([^&\s\"']+)", re.IGNORECASE, ) @@ -210,7 +226,18 @@ def redact_query(query: str) -> str: sends it percent-encoded — `someone%40example.com` is an address `_EMAIL_RE` cannot see. Each parameter also goes through the key rules, so `?new_password=` goes as `redact` would drop it.""" pairs = parse_qsl(query, keep_blank_values=True) - return "&".join(redact_text(f"{key}={redact(value, key=key)}") for key, value in pairs) + return "&".join(f"{key}={_redact_param(key, value)}" for key, value in pairs) + + +def _redact_param(key: str, value: str) -> str: + """One decoded `key=value` pair. The parameter-NAME rule is applied to the key here rather than + left to `_SECRET_PARAM_RE` over the rebuilt pair: that pattern was written for the raw, + percent-encoded query, where a value holds no literal space, `&` or quote, and its value class + stops at the first one. On decoded text `?state=a%20b` would keep its tail and `?code=%20abc` + would not match at all — the whole credential straight into the line.""" + if key.lower() in _SECRET_PARAM_NAMES: + return REDACTED + return str(redact(value, key=key)) def redact(value: Any, *, key: str = "") -> Any: @@ -509,6 +536,10 @@ def forget_user(user_id: int) -> None: _erased[user_id] = now with _elevations_lock: _elevations.pop(user_id, None) + # That pop can have removed the lowest elevation, and the root level is the lowest of the base + # and every unexpired one. Recomputed here rather than left to whichever later request happens + # to call `_track_elevation` — the invariant `_apply_root_level` documents holds at every pop. + _apply_root_level() def is_erased(user_id: int | None) -> bool: diff --git a/backend/app/logsink.py b/backend/app/logsink.py index d1b5db4b..444fe5bd 100644 --- a/backend/app/logsink.py +++ b/backend/app/logsink.py @@ -246,7 +246,12 @@ class LogSink(logging.Handler): if not rows: return 0 try: - with logs.erasure_guard(), self._bind.begin() as conn: + # The connection is checked out BEFORE the guard, and every request path takes them in + # that order too (its session already holds a connection when it reaches the guard). The + # other way round, this thread would hold a process-global lock while waiting up to + # `pool_timeout` for a connection, and the requests that could return one are the ones + # blocked on the lock. The guard still spans the check, the insert and the commit. + with self._bind.connect() as conn, logs.erasure_guard(), conn.begin(): conn.execute(insert(LogEvent), without_erased(rows)) except Exception as exc: # noqa: BLE001 — the database is down or refused the batch print( diff --git a/backend/app/routes/diagnostics.py b/backend/app/routes/diagnostics.py index 1f9b5028..2cf62804 100644 --- a/backend/app/routes/diagnostics.py +++ b/backend/app/routes/diagnostics.py @@ -169,7 +169,10 @@ def _budget_notice(user: User, now: datetime) -> dict[str, Any]: "source": "web", "logger": "web", "event": "diagnostics.budget_spent", - "msg": "The browser log passed its hourly storage budget; the rest of the hour is not kept", + # What the budget does, exactly: it is a SLIDING hour, and a refused batch is not + # charged to it, so smaller batches keep landing while there is room for them. Saying + # "the rest of the hour is not kept" would be a row contradicting the rows beneath it. + "msg": "The browser log passed its hourly storage budget; a batch bigger than what is left of it is not kept", "attrs": {"budget_bytes": STORED_BYTES_PER_HOUR}, "user_id": user.id, } diff --git a/backend/tests/conftest.py b/backend/tests/conftest.py index 10c811af..4472445b 100644 --- a/backend/tests/conftest.py +++ b/backend/tests/conftest.py @@ -214,3 +214,15 @@ def _reset_rate_limiters(): for obj in vars(mod).values(): if isinstance(obj, RateLimiter): obj.reset() + + +@pytest.fixture(autouse=True) +def _reset_log_erasures(): + """`logs._erased` is module-level and remembers an erased account for an hour of monotonic time + — longer than any suite run — while the `db` fixture hands serial ids back out from 1 via + TRUNCATE … RESTART IDENTITY. So a test that purges user 1 would otherwise make a LATER test's + rows for user 1 store with `user_id = None`, failing somewhere nowhere near the cause and only + in some file orders. Same reasoning as the limiter sweep above, different global.""" + from app import logs + + logs._erased.clear() diff --git a/backend/tests/test_diagnostics.py b/backend/tests/test_diagnostics.py index 5027ed46..d2915a23 100644 --- a/backend/tests/test_diagnostics.py +++ b/backend/tests/test_diagnostics.py @@ -181,6 +181,20 @@ def test_a_batch_is_stored_as_the_sessions_web_events_and_redacted_again(elevate assert (warning.sev, click.level, click.version) == (13, "DEBUG", "0.88.0") +def test_an_erased_accounts_batch_is_stored_without_the_account(elevated): + """The sink's writer is not the only path into `log_events` — this route inserts too, and an + account erased while its browser was mid-flush must not get its rows back through it. Faked at + the `forget_user` seam the purge itself calls: once the User row is actually gone the session + no longer resolves, so the reachable window is exactly a request already past `current_user`. + (`logs._erased` is cleared before every test by conftest's `_reset_log_erasures`.)""" + user, client, rows = elevated("DEBUG") + logs.forget_user(user.id) + r = client.post("/api/diagnostics/events", json={"events": [_event(level="WARNING")]}) + assert r.json() == {"ok": True, "stored": 1} + (stored,) = rows() + assert (stored.source, stored.user_id) == ("web", None) + + def test_an_event_under_the_consented_level_is_dropped(elevated): _user, client, rows = elevated("DEBUG") r = client.post( @@ -370,6 +384,18 @@ def test_an_address_typed_into_a_search_is_redacted_though_the_browser_encodes_i assert line.attrs["query"] == "level=TRACE&q=[email]&new_password=[redacted]" +@pytest.mark.parametrize( + "raw", + ["state=a%20b", "code=%20SECRET", "sig=a%22b", "key=a%26b", "reset=a+b"], + ids=["space", "leading-space", "quote", "ampersand", "plus"], +) +def test_a_credential_param_goes_whole_however_its_value_decodes(raw): + """Decoding is what lets `_EMAIL_RE` see `%40`, but it also puts spaces and separators into a + value that `_SECRET_PARAM_RE`'s value class stops at — so the name rule decides, not the text.""" + name = raw.split("=", 1)[0] + assert logs.redact_query(f"{raw}&q=lofi") == f"{name}={logs.REDACTED}&q=lofi" + + def test_an_admin_level_of_trace_does_not_log_other_users_query_strings(gated): logs.set_level("TRACE") _app().get("/api/thing/7", params={"q": "something private"}) @@ -388,6 +414,22 @@ def test_the_admin_level_applies_to_the_running_process_when_set_and_when_reset( assert logs.current_level() == settings.log_level +def test_erasing_the_only_elevated_account_puts_the_process_level_back(gated): + """The root level is the lowest of the base and every unexpired elevation. `forget_user` drops + an elevation like any other path that drops one, so it owes the same recompute — or the process + keeps building every TRACE record for an account that no longer exists, to throw them away.""" + until = datetime.now(timezone.utc) + timedelta(hours=1) + try: + logs.set_user(7, "TRACE", until) + assert logging.getLogger().level == logs.TRACE + logs.forget_user(7) + assert logging.getLogger().level == logging.INFO + finally: + # `set_user` writes the request scope, and outside a request that scope is this process's + # for good — a later test would store its INFO lines as an elevated session's. + logs.set_user(None) + + def test_the_stored_admin_level_is_applied_at_boot(gated, db, monkeypatch): import asyncio diff --git a/backend/tests/test_logsink.py b/backend/tests/test_logsink.py index 06f96dec..1e166d5c 100644 --- a/backend/tests/test_logsink.py +++ b/backend/tests/test_logsink.py @@ -180,18 +180,31 @@ def test_an_erased_accounts_late_lines_are_stored_without_it(stored, db, make_us or the erasing request's own access line, logged after the handler committed.""" _sink, log, rows = stored user = make_user() - try: - log.warning("queued before the erasure", extra={"user_id": user.id}) - purge_user(db, user, BackgroundTasks()) - log.info( - "DELETE /api/me/account 200", extra={**logs.event("http.request"), "user_id": user.id} - ) - assert [(r.msg, r.user_id) for r in rows()] == [ - ("queued before the erasure", None), - ("DELETE /api/me/account 200", None), - ] - finally: - logs._erased.clear() + # `logs._erased` outlives the test; conftest's `_reset_log_erasures` clears it before each one. + log.warning("queued before the erasure", extra={"user_id": user.id}) + purge_user(db, user, BackgroundTasks()) + log.info("DELETE /api/me/account 200", extra={**logs.event("http.request"), "user_id": user.id}) + assert [(r.msg, r.user_id) for r in rows()] == [ + ("queued before the erasure", None), + ("DELETE /api/me/account 200", None), + ] + + +def test_every_path_into_the_table_drops_an_erased_account(): + """The two behavioural tests above cover the two writers there are today (this sink and + `POST /api/diagnostics/events`). This one covers the THIRD one nobody has written yet: a new + `insert(LogEvent)` that forgets the filter would leave an erased account's rows named, and no + test of an existing path can notice. Source-level on purpose — it is a rule about call sites.""" + import pathlib + + root = pathlib.Path(__file__).resolve().parents[1] / "app" + unfiltered = [ + f"{path.relative_to(root)}:{n}" + for path in root.rglob("*.py") + for n, line in enumerate(path.read_text(encoding="utf-8").splitlines(), 1) + if "insert(LogEvent)" in line and "without_erased" not in line + ] + assert unfiltered == [], f"insert(LogEvent) without logsink.without_erased at {unfiltered}" def test_a_nul_character_costs_nothing_but_itself(stored):