Mask query-string tokens in uvicorn's log lines and support bundles

backend/app/core/logging_filters.py

@@ -9,7 +9,9 @@ import them without pulling in ``backend.app.main``'s startup graph.
 
 Also holds :data:`URL_CREDENTIALS_PATTERN` and
 :func:`redact_url_credentials`, the single place where the shape of a
-credentialed URL is defined for the whole backend.
+credentialed URL is defined for the whole backend, and
+:data:`QUERY_TOKEN_PATTERN` / :class:`QueryTokenRedactFilter` for tokens
+carried in a query string.
 """
 
 from __future__ import annotations
@@ -60,6 +62,49 @@ def redact_url_credentials(text: str | None) -> str | None:
     return URL_CREDENTIALS_PATTERN.sub(r"\g<scheme>\g<user>:[REDACTED]@", text)
 
 
+# ``?token=<value>`` and its kin. The SPA passes its short-lived WebSocket and
+# media tokens in the query string (a browser cannot set headers on a
+# WebSocket upgrade, an <img> or a <video>), and uvicorn logs every request
+# path with its query: the access line for each GET, and the "WebSocket ...
+# [accepted]" line for each upgrade. Those reach the console, so `docker logs`,
+# and from there anything that collects container logs -- the appliance's
+# support bundle among them. The value ends at the next ``&``, whitespace or
+# quote, which is where uvicorn's format closes the path.
+QUERY_TOKEN_PATTERN = re.compile(r"(?P<key>[?&](?:token|access_token|api_key)=)[^&\s\"']+")
+
+
+def redact_query_tokens(text: str | None) -> str | None:
+    """Mask the value of every token-bearing query parameter in *text*."""
+    if not text or "=" not in text:
+        return text
+    return QUERY_TOKEN_PATTERN.sub(r"\g<key>[REDACTED]", text)
+
+
+class QueryTokenRedactFilter(logging.Filter):
+    """Mask query-string tokens in uvicorn's request and WebSocket log lines.
+
+    Rewrites the record rather than dropping it: the line is still the record
+    of a request, only its credential goes. Uvicorn passes the path as a
+    ``%s`` argument (``'%s - "%s %s HTTP/%s" %d'`` for HTTP,
+    ``'%s - "WebSocket %s" [accepted]'`` for an upgrade), so the arguments are
+    rewritten as well as the message.
+
+    Attach to ``logging.getLogger("uvicorn.access")`` and
+    ``logging.getLogger("uvicorn.error")`` -- the latter carries the WebSocket
+    lines. A logger-level filter runs whichever handler then writes the record,
+    so the console is covered as well as ``bambuddy.log``.
+    """
+
+    def filter(self, record: logging.LogRecord) -> bool:  # noqa: A003 — stdlib API name
+        if isinstance(record.msg, str):
+            record.msg = redact_query_tokens(record.msg)
+        if isinstance(record.args, tuple):
+            record.args = tuple(redact_query_tokens(a) if isinstance(a, str) else a for a in record.args)
+        elif isinstance(record.args, dict):
+            record.args = {k: redact_query_tokens(v) if isinstance(v, str) else v for k, v in record.args.items()}
+        return True
+
+
 class WriteRequestsOnlyFilter(logging.Filter):
     """Keep uvicorn access log records for state-changing HTTP methods only.
 

backend/app/main.py

@@ -370,6 +370,13 @@ if app_settings.log_to_file:
     # log records that pre-existing pools still emit during their cleanup.
     logging.getLogger("sqlalchemy.pool").addFilter(CancelledPoolNoiseFilter())
 
+# Query-string tokens out of uvicorn's request and WebSocket lines, on every
+# handler (console included), whether or not file logging is on.
+from backend.app.core.logging_filters import QueryTokenRedactFilter  # noqa: E402
+
+for _uvicorn_logger in ("uvicorn.access", "uvicorn.error"):
+    logging.getLogger(_uvicorn_logger).addFilter(QueryTokenRedactFilter())
+
 # Reduce noise from third-party libraries in production
 if not app_settings.debug:
     logging.getLogger("sqlalchemy.engine").setLevel(logging.WARNING)

backend/app/services/log_reader.py

@@ -14,7 +14,7 @@ from sqlalchemy import select
 from sqlalchemy.ext.asyncio import AsyncSession
 
 from backend.app.core.config import settings
-from backend.app.core.logging_filters import URL_CREDENTIALS_PATTERN
+from backend.app.core.logging_filters import URL_CREDENTIALS_PATTERN, redact_query_tokens
 from backend.app.models.printer import Printer
 from backend.app.models.settings import Settings
 from backend.app.models.user import User
@@ -175,6 +175,10 @@ def sanitize_log_content(content: str, sensitive_strings: dict[str, str] | None
     # it for diagnosis.
     content = URL_CREDENTIALS_PATTERN.sub(r"\g<scheme>[CREDENTIALS]@", content)
 
+    # Query-string tokens (?token=...), for log lines written before the live
+    # filter existed or by a logger it is not attached to.
+    content = redact_query_tokens(content) or ""
+
     # Replace email addresses
     content = re.sub(r"\b[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Z|a-z]{2,}\b", "[EMAIL]", content)
 

backend/tests/unit/test_query_token_redaction.py

@@ -0,0 +1,112 @@
+"""Query-string tokens must not reach the logs.
+
+The SPA authenticates its WebSocket and media requests with a short-lived
+token in the query string, and uvicorn logs every path with its query -- the
+access line for a GET and the "WebSocket ... [accepted]" line for an upgrade.
+Those go to the console, and from there into `docker logs` and support
+bundles built from them. ``QueryTokenRedactFilter`` masks the value on the way
+out; ``sanitize_log_content`` does the same for log text already written.
+"""
+
+from __future__ import annotations
+
+import io
+import logging
+
+import pytest
+
+from backend.app.core.logging_filters import QueryTokenRedactFilter, redact_query_tokens
+from backend.app.services.log_reader import sanitize_log_content
+
+TOKEN = "M8qxtTy4sHgSkUhAwwrOHSji8stuLIq0"
+
+
+def _record(msg: str, args) -> logging.LogRecord:
+    return logging.LogRecord(
+        name="uvicorn.error", level=logging.INFO, pathname="", lineno=0, msg=msg, args=args, exc_info=None
+    )
+
+
+class TestRedactQueryTokens:
+    @pytest.mark.parametrize(
+        "text, expected",
+        [
+            (f"/api/v1/ws?token={TOKEN}", "/api/v1/ws?token=[REDACTED]"),
+            (
+                f"/api/v1/printers/1/camera/stream?fps=10&token={TOKEN}",
+                "/api/v1/printers/1/camera/stream?fps=10&token=[REDACTED]",
+            ),
+            (f"/x?token={TOKEN}&fps=5", "/x?token=[REDACTED]&fps=5"),
+            (f'"WebSocket /api/v1/ws?token={TOKEN}" [accepted]', '"WebSocket /api/v1/ws?token=[REDACTED]" [accepted]'),
+            (f"/x?access_token={TOKEN}", "/x?access_token=[REDACTED]"),
+            (f"/x?api_key={TOKEN}", "/x?api_key=[REDACTED]"),
+        ],
+    )
+    def test_masks_the_value(self, text, expected):
+        assert redact_query_tokens(text) == expected
+
+    @pytest.mark.parametrize(
+        "text",
+        [
+            "/api/v1/printers?status=online",
+            "/api/v1/archives?mytoken=abc",  # a different parameter that merely ends in "token"
+            "token=abc in prose, not a query",
+            "",
+            None,
+        ],
+    )
+    def test_leaves_everything_else_alone(self, text):
+        assert redact_query_tokens(text) == text
+
+
+class TestQueryTokenRedactFilter:
+    def test_websocket_accept_line(self):
+        """Uvicorn's own format: the path is an argument, not part of msg."""
+        record = _record('%s - "WebSocket %s" [accepted]', ("192.168.255.4:0", f"/api/v1/ws?token={TOKEN}"))
+        assert QueryTokenRedactFilter().filter(record) is True
+        assert TOKEN not in record.getMessage()
+        assert record.getMessage() == '192.168.255.4:0 - "WebSocket /api/v1/ws?token=[REDACTED]" [accepted]'
+
+    def test_access_line_keeps_its_other_arguments(self):
+        record = _record(
+            '%s - "%s %s HTTP/%s" %d',
+            ("10.0.0.2:5000", "GET", f"/api/v1/printers/1/camera/stream?token={TOKEN}", "1.1", 200),
+        )
+        QueryTokenRedactFilter().filter(record)
+        assert record.getMessage() == (
+            '10.0.0.2:5000 - "GET /api/v1/printers/1/camera/stream?token=[REDACTED] HTTP/1.1" 200'
+        )
+
+    def test_message_without_arguments(self):
+        record = _record(f"GET /api/v1/ws?token={TOKEN}", None)
+        QueryTokenRedactFilter().filter(record)
+        assert record.getMessage() == "GET /api/v1/ws?token=[REDACTED]"
+
+    def test_through_a_real_logger_and_handler(self):
+        """Attached to the logger, it covers whatever handler writes the line."""
+        logger = logging.getLogger("test.query_token_redaction")
+        stream = io.StringIO()
+        handler = logging.StreamHandler(stream)
+        logger.addHandler(handler)
+        logger.addFilter(QueryTokenRedactFilter())
+        logger.setLevel(logging.INFO)
+        logger.propagate = False
+        try:
+            logger.info('%s - "WebSocket %s" [accepted]', "fe80::1:0", f"/api/v1/ws?token={TOKEN}")
+        finally:
+            logger.removeHandler(handler)
+        assert TOKEN not in stream.getvalue()
+        assert "token=[REDACTED]" in stream.getvalue()
+
+
+def test_main_attaches_the_filter_to_both_uvicorn_loggers():
+    import backend.app.main  # noqa: F401 -- importing configures logging
+
+    for name in ("uvicorn.access", "uvicorn.error"):
+        assert any(isinstance(f, QueryTokenRedactFilter) for f in logging.getLogger(name).filters), name
+
+
+def test_support_bundle_sanitizer_masks_tokens():
+    line = f'INFO: 192.168.255.4:0 - "WebSocket /api/v1/ws?token={TOKEN}" [accepted]'
+    assert TOKEN not in sanitize_log_content(line)
+    assert "token=[REDACTED]" in sanitize_log_content(line)