diff --git a/src/beaver_gateway/cli.py b/src/beaver_gateway/cli.py index cd9180d..467181d 100644 --- a/src/beaver_gateway/cli.py +++ b/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", diff --git a/src/beaver_gateway/core/redact.py b/src/beaver_gateway/core/redact.py new file mode 100644 index 0000000..83505fc --- /dev/null +++ b/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 `` 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-/basic.ics`` feed and a USOS ``?key=`` 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"(?:(?,;)\]}])+" + +_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 `` 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()) diff --git a/tests/test_auth_query_token.py b/tests/test_auth_query_token.py index 82ad7fe..b714ab0 100644 --- a/tests/test_auth_query_token.py +++ b/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() diff --git a/tests/test_redact.py b/tests/test_redact.py new file mode 100644 index 0000000..df3de33 --- /dev/null +++ b/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",)