fix(redact,cli): mask credentials in every log line, silence httpx request urls

src/beaver_gateway/cli.py

@@ -24,7 +24,6 @@ import asyncio
 import contextlib
 import functools
 import logging
-import re
 import signal
 from contextlib import AsyncExitStack
 from typing import TYPE_CHECKING, Any
@@ -51,6 +50,8 @@ from beaver_gateway.core.bus import EventBus
 from beaver_gateway.core.conversations import Conversations
 from beaver_gateway.core.envelope import Envelope
 from beaver_gateway.core.gateway_tools import build_tool_server
+from beaver_gateway.core.redact import install as install_redaction
+from beaver_gateway.core.redact import load_secrets as load_secrets_to_mask
 from beaver_gateway.core.registry import AgentRegistry, Gateway, McpRegistry
 from beaver_gateway.core.rotation import Rotation, RotationPolicy
 from beaver_gateway.core.scheduler import Scheduler
@@ -89,6 +90,7 @@ def main() -> None:
     logging.basicConfig(
         level=logging.INFO, format="%(asctime)s %(levelname)s %(name)s: %(message)s"
     )
+    install_redaction()
     _install_sigterm_handler()
     asyncio.run(_async_main(), loop_factory=uvloop.new_event_loop)
 
@@ -124,6 +126,9 @@ async def _async_main() -> None:
     # populates Settings fields, not the process environment.
     # ``override=False``: real env vars (Docker, systemd) win over .env.
     load_dotenv(override=False)
+    # Only now does the process environment hold the credentials the
+    # redactor masks literally (in Docker they arrive via ``env_file``).
+    load_secrets_to_mask()
 
     settings = Settings()  # ty: ignore[missing-argument]
     gateway = config_loader.load(settings.config_path)
@@ -290,30 +295,8 @@ def _plain_postgres_url(url: str) -> str | None:
     return None
 
 
-_TOKEN_IN_QUERY = re.compile(r"(token=)[^&\s\"]+")
-
-
-class ScrubQueryTokens(logging.Filter):
-    """Mask ``?token=…`` in uvicorn access lines.
-
-    Webhook senders that cannot set headers put the secret in the URL, and
-    ``docker logs`` is not a vault.
-    """
-
-    def filter(self, record: logging.LogRecord) -> bool:
-        if isinstance(record.args, tuple):
-            record.args = tuple(
-                _TOKEN_IN_QUERY.sub(r"\1<…>", a) if isinstance(a, str) else a
-                for a in record.args
-            )
-        elif isinstance(record.msg, str):
-            record.msg = _TOKEN_IN_QUERY.sub(r"\1<…>", record.msg)
-        return True
-
-
 async def _serve_root(gateway: Gateway, *, extra: dict[str, ASGIApp]) -> None:
     app = build_root_app(gateway.frontends, extra=extra)
-    logging.getLogger("uvicorn.access").addFilter(ScrubQueryTokens())
     config = uvicorn.Config(app, host=gateway.host, port=gateway.port, log_level="info")
     _log.info(
         "gateway on http://%s:%d - %s",

src/beaver_gateway/core/redact.py

@@ -0,0 +1,178 @@
+"""Keep credentials out of the process log.
+
+``docker logs`` is not a vault: the stack's stdout lands in an unrotated
+json file on the host, and the model itself can page through it (the
+komodo tool has ``logs`` / ``search_logs``). Nobody has to write a
+careless log call for a secret to end up there — two habits do it on
+their own:
+
+* ``httpx`` logs ``HTTP Request: POST <full url>`` at ``INFO``, so every
+  request to an upstream that keeps its credential *in* the URL prints
+  the credential once per call;
+* a transport error carries that same URL through the traceback, which
+  ``_log.exception`` writes out in full.
+
+Two of our upstreams are exactly that shape: a Google Calendar
+``.../private-<token>/basic.ics`` feed and a USOS ``?key=<token>`` ical
+feed, both handed to the calendar MCP as query parameters.
+
+So: silence the HTTP clients' per-request chatter (nothing here reads
+it), and run one redaction pass over every formatted record as a second
+line of defence. Redaction knows two things — patterns for credentials
+that live in URLs and headers, and the literal values of the
+secret-looking environment variables this process was started with.
+"""
+
+from __future__ import annotations
+
+import logging
+import os
+import re
+from typing import TYPE_CHECKING
+from urllib.parse import quote, unquote
+
+if TYPE_CHECKING:
+    from collections.abc import Mapping
+
+MASK = "<…>"
+
+# Loggers that print request URLs at INFO. We keep their warnings.
+CHATTY: tuple[str, ...] = ("httpx", "httpcore", "aiohttp.client", "urllib3")
+
+# Loggers that bring their own handlers (uvicorn re-runs ``dictConfig``
+# when a server starts), so wrapping the root formatter misses them.
+# ``dictConfig`` drops a logger's handlers but keeps its filters.
+OWN_HANDLERS: tuple[str, ...] = ("uvicorn", "uvicorn.access", "uvicorn.error")
+
+# Env vars whose *value* is a credential — matched as a substring of the
+# name, so ``FIREFLY_PAT`` and ``T3_MAC_TOKEN`` both qualify.
+_SECRET_NAME = re.compile(
+    r"TOKEN|SECRET|KEY|PASSWORD|PASS\b|PAT\b|BEARER|CREDENTIAL|MCPS", re.IGNORECASE
+)
+_MIN_SECRET = 8
+
+# A query parameter may sit behind a plain ``?``/``&`` or behind their
+# percent-encoded twins when a whole URL is nested in another one.
+_LEFT = r"(?:(?<![A-Za-z0-9])|(?<=%26)|(?<=%3F))"
+# ...and runs until the next separator, encoded ``&`` included.
+_VALUE = r"(?:(?!%26)[^&\s\"'<>,;)\]}])+"
+
+_RULES: tuple[tuple[re.Pattern[str], str], ...] = (
+    # Google Calendar's secret path segment; the ``/basic.ics`` after it
+    # survives, encoded or not, so the line still says what it fetched.
+    (
+        re.compile(r"(private-)(?:(?!%2F)[A-Za-z0-9_%-]){8,}", re.IGNORECASE),
+        r"\1" + MASK,
+    ),
+    # ``key=…``, ``api_key=…``, ``token=…``, … in a query string.
+    (
+        re.compile(
+            _LEFT
+            + r"(api[-_]?key|access[-_]?token|auth[-_]?token"
+            + r"|token|key|secret|password|passwd|pat|signature|sig)"
+            + r"(=|%3D)"
+            + _VALUE,
+            re.IGNORECASE,
+        ),
+        r"\1\2" + MASK,
+    ),
+    # ``Authorization: Bearer …`` in a header dump; scheme goes too.
+    (
+        re.compile(
+            r"(authorization[\"']?\s*[:=]\s*[\"']?)(?:\S+\s+)?\S+", re.IGNORECASE
+        ),
+        r"\1" + MASK,
+    ),
+    # A bare ``Bearer <token>`` anywhere else.
+    (re.compile(r"\b(bearer)\s+[A-Za-z0-9._~+/=-]{8,}", re.IGNORECASE), r"\1 " + MASK),
+)
+
+_ENV_SECRETS: list[str] = []
+"""Literal secret values to mask, longest first. Filled by :func:`install`."""
+
+
+def env_secrets(env: Mapping[str, str]) -> list[str]:
+    """Literal values worth masking, longest first.
+
+    Each secret-looking variable contributes its value plus the
+    percent-encoded and percent-decoded spellings of it, because a
+    credential that travels inside another URL is logged encoded.
+    """
+    found: set[str] = set()
+    for name, value in env.items():
+        if not _SECRET_NAME.search(name):
+            continue
+        for form in (value, quote(value, safe=""), unquote(value)):
+            if len(form.strip()) >= _MIN_SECRET:
+                found.add(form.strip())
+    ordered = list(found)
+    ordered.sort(key=len, reverse=True)
+    return ordered
+
+
+def redact(text: str) -> str:
+    """Mask every credential we can recognise in ``text``."""
+    for value in _ENV_SECRETS:
+        if value in text:
+            text = text.replace(value, MASK)
+    for pattern, repl in _RULES:
+        text = pattern.sub(repl, text)
+    return text
+
+
+class RedactingFormatter(logging.Formatter):
+    """Wrap another formatter and redact whatever it produced.
+
+    Formatting first is the point: it catches the message, its ``%``
+    arguments and the traceback of an ``exception()`` call in one pass,
+    which a record-level filter cannot do.
+    """
+
+    def __init__(self, inner: logging.Formatter | None = None) -> None:
+        super().__init__()
+        self._inner = inner if inner is not None else logging.Formatter()
+
+    def format(self, record: logging.LogRecord) -> str:
+        return redact(self._inner.format(record))
+
+
+class RedactFilter(logging.Filter):
+    """Redact at record level, for loggers whose handlers aren't ours.
+
+    Interpolates first and replaces the record with the result, because
+    a secret is often split across the template and its arguments
+    (``"key=%s", token``) and neither half looks like a credential on
+    its own. The arguments are dropped only when something was actually
+    masked, so untouched records stay structured.
+    """
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        try:
+            message = record.getMessage()
+        except (TypeError, ValueError):  # a broken template is not ours to fix
+            return True
+        masked = redact(message)
+        if masked != message:
+            record.msg = masked
+            record.args = ()
+        return True
+
+
+def load_secrets(env: Mapping[str, str] | None = None) -> None:
+    """(Re)read the literal values to mask.
+
+    Called once at startup and again after ``.env`` is loaded, because
+    in dev the process environment only fills up at that point.
+    """
+    _ENV_SECRETS[:] = env_secrets(os.environ if env is None else env)
+
+
+def install(env: Mapping[str, str] | None = None) -> None:
+    """Wire redaction into the root logger. Call right after ``basicConfig``."""
+    load_secrets(env)
+    for handler in logging.getLogger().handlers:
+        handler.setFormatter(RedactingFormatter(handler.formatter))
+    for name in CHATTY:
+        logging.getLogger(name).setLevel(logging.WARNING)
+    for name in OWN_HANDLERS:
+        logging.getLogger(name).addFilter(RedactFilter())

tests/test_auth_query_token.py

@@ -61,7 +61,7 @@ async def test_bootstrap_entry_can_carry_a_scope() -> None:
 
 
 def test_access_log_filter_masks_query_tokens() -> None:
-    from beaver_gateway.cli import ScrubQueryTokens
+    from beaver_gateway.core.redact import RedactFilter
 
     record = logging.LogRecord(
         "uvicorn.access",
@@ -72,6 +72,6 @@ def test_access_log_filter_masks_query_tokens() -> None:
         ("1.2.3.4:1", "POST", "/hooks/komodo?token=s3cret&x=1", "1.1", 202),
         None,
     )
-    assert ScrubQueryTokens().filter(record)
+    assert RedactFilter().filter(record)
     assert "s3cret" not in record.getMessage()
     assert "/hooks/komodo?token=<…>&x=1" in record.getMessage()

tests/test_redact.py

@@ -0,0 +1,120 @@
+from __future__ import annotations
+
+import io
+import logging
+
+import pytest
+
+from beaver_gateway.core import redact as redact_mod
+from beaver_gateway.core.redact import (
+    RedactFilter,
+    RedactingFormatter,
+    env_secrets,
+    redact,
+)
+
+# The two lines the gateway actually printed (httpx at INFO), verbatim
+# apart from the token bodies: the calendar MCP takes the private ical
+# feed as a query parameter, so the feed's secret is in the URL.
+GOOGLE = (
+    "HTTP Request: POST https://calendar-mcp.com/api/mcp"
+    "?email=someone%40gmail.com&icsUrl=https%3A%2F%2Fcalendar.google.com"
+    "%2Fcalendar%2Fical%2Fsomeone%2540gmail.com"
+    "%2Fprivate-1f4a9c0de1f4a9c0de1f4a9c0de%2Fbasic.ics"
+    ' "HTTP/1.1 200 OK"'
+)
+USOS = (
+    "HTTP Request: POST https://calendar-mcp.com/api/mcp"
+    "?email=someone%40gmail.com&icsUrl=https%3A%2F%2Fusosapps.put.poznan.pl"
+    "%2Fservices%2Ftt%2Fupcoming_ical%3Flang%3Dpl%26user_id%3D145744"
+    "%26key%3DABCDEF0123456789abcdef"
+    ' "HTTP/1.1 202 Accepted"'
+)
+
+
+@pytest.fixture(autouse=True)
+def _no_env_secrets() -> None:
+    redact_mod._ENV_SECRETS[:] = []  # noqa: SLF001
+
+
+def test_google_private_ical_token_is_masked() -> None:
+    out = redact(GOOGLE)
+    assert "1f4a9c0de1f4a9c0de1f4a9c0de" not in out
+    assert "private-<…>" in out
+    # The harmless part of the line survives, so the log stays useful.
+    assert out.startswith("HTTP Request: POST https://calendar-mcp.com/api/mcp")
+    assert out.endswith('"HTTP/1.1 200 OK"')
+
+
+def test_usos_key_is_masked_through_percent_encoding() -> None:
+    out = redact(USOS)
+    assert "ABCDEF0123456789abcdef" not in out
+    assert "key%3D<…>" in out
+    assert out.endswith('"HTTP/1.1 202 Accepted"')
+
+
+@pytest.mark.parametrize(
+    ("line", "secret"),
+    [
+        ("GET /hooks/komodo?token=s3cret-value&x=1", "s3cret-value"),
+        ("GET /x?api_key=s3cret-value", "s3cret-value"),
+        ("GET /x?session_key=s3cret-value", "s3cret-value"),
+        ("headers={'Authorization': 'Bearer s3cret-value'}", "s3cret-value"),
+        ("authorization: token s3cret-value", "s3cret-value"),
+        ("retrying with Bearer s3cret-value", "s3cret-value"),
+    ],
+)
+def test_credentials_in_urls_and_headers(line: str, secret: str) -> None:
+    assert secret not in redact(line)
+
+
+def test_known_env_values_are_masked() -> None:
+    redact_mod._ENV_SECRETS[:] = env_secrets(  # noqa: SLF001
+        {"FIREFLY_PAT": "pat-0123456789", "POSTGRES_USER": "beaver"}
+    )
+    out = redact("firefly said no to pat-0123456789 (user beaver)")
+    assert "pat-0123456789" not in out
+    # Only credential-shaped names contribute; ordinary config survives.
+    assert "beaver" in out
+
+
+def test_env_values_are_masked_percent_encoded_too() -> None:
+    raw = "https://cal/private-xyz/basic.ics"
+    redact_mod._ENV_SECRETS[:] = env_secrets({"CALENDAR_MCPS": raw})  # noqa: SLF001
+    assert raw not in redact(f"fetching {raw}")
+    assert "%2Fprivate-xyz%2F" not in redact(
+        "fetching https%3A%2F%2Fcal%2Fprivate-xyz%2Fbasic.ics"
+    )
+
+
+def test_formatter_redacts_the_traceback_too() -> None:
+    stream = io.StringIO()
+    handler = logging.StreamHandler(stream)
+    handler.setFormatter(RedactingFormatter(logging.Formatter("%(message)s")))
+    log = logging.getLogger("test_redact.traceback")
+    log.propagate = False
+    log.handlers = [handler]
+    try:
+        msg = f"connect failed: {GOOGLE}"
+        raise ConnectionError(msg)  # noqa: TRY301
+    except ConnectionError:
+        log.exception("failed to list tools for MCP %r", "calendar-personal")
+    out = stream.getvalue()
+    assert "calendar-personal" in out
+    assert "1f4a9c0de1f4a9c0de1f4a9c0de" not in out
+
+
+def test_filter_masks_a_secret_split_across_template_and_args() -> None:
+    record = logging.LogRecord(
+        "uvicorn.access", logging.INFO, __file__, 1, "key=%s", ("s3cret-value",), None
+    )
+    assert RedactFilter().filter(record)
+    assert record.getMessage() == "key=<…>"
+
+
+def test_filter_leaves_a_clean_record_structured() -> None:
+    record = logging.LogRecord(
+        "uvicorn.access", logging.INFO, __file__, 1, "closing %s", ("conv-1",), None
+    )
+    assert RedactFilter().filter(record)
+    assert record.args == ("conv-1",)