Merge pull request #689 from Routstr/fix/log-secret-redaction

fix: keep spendable credentials out of the structured logs

routstr/balance.py

@@ -368,7 +368,7 @@ async def _restore_balance(
     logger.info(
         "refund_wallet_endpoint: balance restored after mint failure",
         extra={
-            "hashed_key": hashed_key,
+            "key_hash": hashed_key[:8],
             "restored_balance": balance,
             "mint_url": mint_url,
         },
@@ -481,7 +481,7 @@ async def refund_wallet_endpoint(
         logger.warning(
             "refund_wallet_endpoint: released stale reservation before refund",
             extra={
-                "hashed_key": key.hashed_key,
+                "key_hash": key.hashed_key[:8],
                 "stale_timeout_seconds": settings.stale_reservation_timeout_seconds,
             },
         )
@@ -555,7 +555,7 @@ async def refund_wallet_endpoint(
                 "refund_wallet_endpoint: cashu token issued",
                 extra={
                     "path": "/v1/wallet/refund",
-                    "token": result["token"],
+                    "token_length": len(result["token"]),
                     "amount": remaining_balance,
                     "currency": key.refund_currency or "sat",
                 },
@@ -570,7 +570,7 @@ async def refund_wallet_endpoint(
             "pending reconciliation",
             extra={
                 "error": str(e),
-                "hashed_key": key.hashed_key,
+                "key_hash": key.hashed_key[:8],
                 "remaining_balance": remaining_balance,
                 "refund_currency": key.refund_currency,
                 "refund_mint_url": key.refund_mint_url,
@@ -608,7 +608,7 @@ async def refund_wallet_endpoint(
             extra={
                 "error": error_msg,
                 "error_type": type(e).__name__,
-                "hashed_key": key.hashed_key,
+                "key_hash": key.hashed_key[:8],
                 "remaining_balance": remaining_balance,
                 "refund_currency": key.refund_currency,
                 "refund_mint_url": key.refund_mint_url,

routstr/core/logging.py

@@ -51,7 +51,7 @@ from pythonjsonlogger import jsonlogger
 from rich.console import Console
 from rich.logging import RichHandler
 
-from .redaction import redact_obj, redact_org_ids
+from .redaction import redact_field, redact_org_ids
 
 # Only use RichHandler when stdout is a real TTY. In non-TTY contexts
 # (docker logs, pipes, CI) Rich pads every line to width and wraps long
@@ -100,8 +100,10 @@ class DailyRotatingFileHandler(logging.handlers.TimedRotatingFileHandler):
         self.baseFilename = new_filename
         self.current_date = new_date
 
-        # FIX ME: not sure if we need this
-        # self._cleanup_old_files()
+        # `backupCount` alone never prunes these files: the base filename moves
+        # with the date, so the inherited rollover finds no siblings to expire
+        # and every day of logged credentials is retained indefinitely.
+        self._cleanup_old_files()
 
         if not self.delay:
             self.stream = self._open()
@@ -260,13 +262,11 @@ class SecurityFilter(logging.Filter):
 
             # Structured `extra={...}` fields are emitted by the JSON formatter
             # straight from the record dict and never pass through the message
-            # formatting above. Redact organization IDs from any string-valued
-            # extra so they cannot leak via structured logs.
+            # formatting above, so they need their own recursive pass.
             for attr, value in list(record.__dict__.items()):
                 if attr in _NON_EXTRA_RECORD_ATTRS:
                     continue
-                if isinstance(value, (str, dict, list, tuple)):
-                    record.__dict__[attr] = redact_obj(value)
+                record.__dict__[attr] = redact_field(attr, value)
 
         except Exception:
             pass

routstr/core/middleware.py

@@ -84,7 +84,9 @@ class LoggingMiddleware(BaseHTTPMiddleware):
                     "request_id": request_id,
                     "method": request.method,
                     "path": path,
-                    "query_params": dict(request.query_params),
+                    # Names only: query values carry API keys and refund
+                    # tokens on the wallet routes.
+                    "query_param_names": sorted(request.query_params.keys()),
                 },
             )
 

routstr/core/redaction.py

@@ -1,8 +1,9 @@
-"""Redaction helpers for sensitive provider identifiers.
+"""Redaction helpers for sensitive provider identifiers and credentials.
 
 Single source of truth for stripping account-scoped identifiers (e.g. OpenAI
-organization IDs) from any text before it is logged, returned to a caller, or
-written to an audit entry.
+organization IDs) and spendable credentials (Cashu tokens, bearer keys, key
+hashes) from any text before it is logged, returned to a caller, or written to
+an audit entry.
 """
 
 from __future__ import annotations
@@ -33,19 +34,101 @@ def redact_org_ids(text: str) -> str:
     return _ORG_ID_PATTERN.sub(ORG_ID_PLACEHOLDER, text)
 
 
-def redact_obj(obj: Any) -> Any:
-    """Recursively redact organization IDs in arbitrary nested structures.
+SECRET_PLACEHOLDER = "[REDACTED]"
 
-    Strings are redacted in place; dicts and lists/tuples are walked so that
-    identifiers nested inside structured payloads (e.g. log ``extra`` fields or
-    error ``details``) are also stripped. Other types are returned unchanged.
-    """
+# Field names whose value is spendable or authenticating on its own. Matched as
+# substrings of the lowercased key, so ``hashed_key`` (a live ``sk-`` credential)
+# is stripped while the truncated ``key_hash`` prefix used for correlation is
+# not. Numeric values are never stripped, which keeps ``input_tokens`` and the
+# other usage-analytics fields intact.
+_SECRET_KEY_HINTS = (
+    "authorization",
+    "api_key",
+    "apikey",
+    "bearer",
+    "cashu",
+    "cookie",
+    "credential",
+    "hashed_key",
+    "mnemonic",
+    "nsec",
+    "passphrase",
+    "password",
+    "private_key",
+    "privkey",
+    "secret",
+    "token",
+)
+
+# Value shapes that are spendable wherever they appear, including inside URLs,
+# query strings and free-form error text. Every alternative is anchored on a
+# literal prefix and uses a single bounded character class, so matching stays
+# linear on the logging hot path.
+_SECRET_VALUE_PATTERNS: tuple[re.Pattern[str], ...] = (
+    re.compile(r"cashu[A-Z][A-Za-z0-9_\-=/+]{20,}"),
+    re.compile(r"\bnsec1[a-z0-9]{20,}"),
+    re.compile(r"\bBearer\s+[A-Za-z0-9_\-.=]{10,}", re.IGNORECASE),
+    re.compile(r"\bsk-[A-Za-z0-9]{16,}"),
+    re.compile(r"\b[0-9a-f]{64}\b"),
+    re.compile(
+        r"(?<=[?&])([^=&\s]*(?:token|key|secret|password|auth|sig)[^=&\s]*=)[^&\s\"']+",
+        re.IGNORECASE,
+    ),
+)
+
+_MAX_REDACTION_DEPTH = 12
+
+
+def _redact_secret_text(text: str) -> str:
+    for pattern in _SECRET_VALUE_PATTERNS:
+        text = pattern.sub(
+            lambda match: (match.group(1) if match.groups() else "")
+            + SECRET_PLACEHOLDER,
+            text,
+        )
+    return redact_org_ids(text)
+
+
+def _is_secret_key(key: object) -> bool:
+    if not isinstance(key, str):
+        return False
+    lowered = key.lower()
+    return any(hint in lowered for hint in _SECRET_KEY_HINTS)
+
+
+def _redact_secrets(obj: Any, depth: int, seen: frozenset[int]) -> Any:
     if isinstance(obj, str):
-        return redact_org_ids(obj)
+        return _redact_secret_text(obj)
+    if not isinstance(obj, (dict, list, tuple)):
+        return obj
+    if depth >= _MAX_REDACTION_DEPTH or id(obj) in seen:
+        return SECRET_PLACEHOLDER
+    nested = seen | {id(obj)}
     if isinstance(obj, dict):
-        return {key: redact_obj(value) for key, value in obj.items()}
-    if isinstance(obj, list):
-        return [redact_obj(value) for value in obj]
-    if isinstance(obj, tuple):
-        return tuple(redact_obj(value) for value in obj)
-    return obj
+        return {
+            key: _redact_value(key, value, depth + 1, nested)
+            for key, value in obj.items()
+        }
+    redacted = [_redact_secrets(value, depth + 1, nested) for value in obj]
+    return redacted if isinstance(obj, list) else tuple(redacted)
+
+
+def _redact_value(key: object, value: Any, depth: int, seen: frozenset[int]) -> Any:
+    # Containers keep being walked even under a secret-shaped key so that the
+    # surrounding structure stays readable for operators.
+    if isinstance(value, (bool, int, float, dict, list, tuple)) or value is None:
+        return _redact_secrets(value, depth, seen)
+    if _is_secret_key(key):
+        return SECRET_PLACEHOLDER
+    return _redact_secrets(value, depth, seen)
+
+
+def redact_field(key: str, value: Any) -> Any:
+    """Strip credentials from one named field, e.g. a log ``extra`` entry.
+
+    Both secret-shaped keys and secret-shaped values are stripped, so a leak
+    survives neither a renamed field nor a credential embedded in free text.
+    The walk is depth-limited and cycle-safe: a malformed payload degrades to
+    ``[REDACTED]`` rather than taking the logging call down with it.
+    """
+    return _redact_value(key, value, 0, frozenset())

tests/unit/test_log_secret_redaction.py

@@ -0,0 +1,238 @@
+"""Regression tests for spendable credentials leaking into the dated log files.
+
+Everything here asserts against the bytes the ``DailyRotatingFileHandler``
+actually wrote to disk. Asserting against a mock would pass even if the JSON
+formatter emitted the raw ``extra`` dict, which is exactly the bug.
+"""
+
+import json
+import logging
+import os
+import time
+from collections.abc import Callable, Iterator
+from pathlib import Path
+from typing import Any
+
+import pytest
+from fastapi import FastAPI
+from fastapi.testclient import TestClient
+from pythonjsonlogger import jsonlogger
+
+from routstr.core.logging import (
+    DailyRotatingFileHandler,
+    RequestIdFilter,
+    SecurityFilter,
+    VersionFilter,
+)
+from routstr.core.middleware import LoggingMiddleware
+
+REFUND_TOKEN = (
+    "cashuBo2FteCJodHRwczovL21pbnQubWluaWJpdHMuY2FzaC9CaXRjb2luYXVjc"
+    "2F0YXSBomFpSAA5tMOFA4EXYXCBo2FhAmFzeEA5NmY0NTFhZjMzMGY3ZmM2ZGY5"
+)
+HASHED_KEY = "b3d9f1c2a8574e60b7c1f0aa9d2e4c85f6b70a1932de84cc57bf90ae1d2c3f47"
+
+
+@pytest.fixture
+def log_dir(tmp_path: Path) -> Path:
+    directory = tmp_path / "logs"
+    directory.mkdir()
+    return directory
+
+
+@pytest.fixture
+def handler(log_dir: Path) -> Iterator[DailyRotatingFileHandler]:
+    """A file handler configured exactly like the production ``file`` handler."""
+    handler = DailyRotatingFileHandler(
+        str(log_dir / "app.log"),
+        when="midnight",
+        interval=1,
+        backupCount=30,
+    )
+    handler.setLevel(logging.DEBUG)
+    handler.setFormatter(
+        jsonlogger.JsonFormatter(
+            "%(asctime)s %(name)s %(levelname)s %(message)s %(pathname)s "
+            "%(lineno)d %(version)s %(request_id)s",
+            datefmt="%Y-%m-%d %H:%M:%S",
+        )
+    )
+    for log_filter in (VersionFilter(), RequestIdFilter(), SecurityFilter()):
+        handler.addFilter(log_filter)
+    try:
+        yield handler
+    finally:
+        handler.close()
+
+
+@pytest.fixture
+def emit(handler: DailyRotatingFileHandler) -> Callable[..., str]:
+    """Log one record and return the raw text of the dated file it landed in."""
+    logger = logging.getLogger("routstr.test.redaction")
+    logger.setLevel(logging.DEBUG)
+    logger.propagate = False
+    logger.handlers = [handler]
+
+    def _emit(message: str, **extra: Any) -> str:
+        logger.info(message, extra=extra)
+        handler.flush()
+        return Path(handler.baseFilename).read_text()
+
+    return _emit
+
+
+def test_refund_token_never_reaches_the_dated_file(emit: Callable[..., str]) -> None:
+    written = emit(
+        "refund_wallet_endpoint: cashu token issued",
+        token=REFUND_TOKEN,
+        amount=1500,
+        currency="sat",
+    )
+    assert REFUND_TOKEN not in written
+    assert "1500" in written
+
+
+def test_authorization_values_never_reach_the_dated_file(
+    emit: Callable[..., str],
+) -> None:
+    written = emit(
+        "Incoming request",
+        authorization=f"Bearer sk-{HASHED_KEY}",
+        headers={"Authorization": f"Bearer sk-{HASHED_KEY}"},
+    )
+    assert HASHED_KEY not in written
+    assert "Bearer sk-" not in written
+
+
+def test_full_key_hashes_never_reach_the_dated_file(emit: Callable[..., str]) -> None:
+    written = emit(
+        "refund_wallet_endpoint: balance restored after mint failure",
+        hashed_key=HASHED_KEY,
+        key_hash=HASHED_KEY,
+        restored_balance=42,
+    )
+    assert HASHED_KEY not in written
+    assert "42" in written
+
+
+def test_secrets_nested_in_dicts_and_lists_never_reach_the_dated_file(
+    emit: Callable[..., str],
+) -> None:
+    written = emit(
+        "Upstream call failed",
+        context={
+            "attempts": [
+                {"headers": {"authorization": f"Bearer sk-{HASHED_KEY}"}},
+                {"body": {"refund": {"token": REFUND_TOKEN}}},
+            ],
+            "provider": "openai",
+        },
+    )
+    assert HASHED_KEY not in written
+    assert REFUND_TOKEN not in written
+    assert "openai" in written
+
+
+def test_query_string_secrets_never_reach_the_dated_file(
+    emit: Callable[..., str],
+) -> None:
+    written = emit(
+        "Incoming request",
+        path="/v1/wallet/refund",
+        query_params={"api_key": f"sk-{HASHED_KEY}", "page": "2"},
+        target=f"/v1/wallet/refund?token={REFUND_TOKEN}",
+    )
+    assert HASHED_KEY not in written
+    assert REFUND_TOKEN not in written
+    assert "/v1/wallet/refund" in written
+
+
+def test_benign_telemetry_is_not_redacted(emit: Callable[..., str]) -> None:
+    written = emit(
+        "Request completed",
+        method="POST",
+        path="/v1/chat/completions",
+        model="gpt-4o-mini",
+        status_code=200,
+        duration_ms=13.5,
+        input_tokens=120,
+        key_hash=HASHED_KEY[:8],
+        mint_url="https://mint.minibits.cash/Bitcoin",
+    )
+    record = json.loads(written.strip().splitlines()[-1])
+    assert record["model"] == "gpt-4o-mini"
+    assert record["status_code"] == 200
+    assert record["duration_ms"] == 13.5
+    assert record["input_tokens"] == 120
+    assert record["key_hash"] == HASHED_KEY[:8]
+    assert record["mint_url"] == "https://mint.minibits.cash/Bitcoin"
+    assert record["message"] == "Request completed"
+
+
+def test_self_referential_extra_does_not_hang_the_logger(
+    emit: Callable[..., str],
+) -> None:
+    cyclic: dict[str, Any] = {"token": REFUND_TOKEN}
+    cyclic["self"] = cyclic
+    deep: dict[str, Any] = {"token": REFUND_TOKEN}
+    for _ in range(200):
+        deep = {"nested": deep}
+
+    written = emit("Cyclic payload", context=cyclic, deep=deep)
+
+    assert REFUND_TOKEN not in written
+    assert json.loads(written.strip().splitlines()[-1])["message"] == "Cyclic payload"
+
+
+def test_middleware_logs_query_param_names_without_values(
+    handler: DailyRotatingFileHandler,
+) -> None:
+    app = FastAPI()
+    app.add_middleware(LoggingMiddleware)
+
+    @app.get("/v1/wallet/refund")
+    async def refund() -> dict[str, str]:
+        return {"status": "ok"}
+
+    middleware_logger = logging.getLogger("routstr.core.middleware")
+    middleware_logger.setLevel(logging.INFO)
+    middleware_logger.propagate = False
+    original_handlers = middleware_logger.handlers
+    middleware_logger.handlers = [handler]
+    try:
+        with TestClient(app) as client:
+            response = client.get(
+                "/v1/wallet/refund", params={"api_key": f"sk-{HASHED_KEY}", "page": "2"}
+            )
+        assert response.status_code == 200
+    finally:
+        middleware_logger.handlers = original_handlers
+
+    handler.flush()
+    written = Path(handler.baseFilename).read_text()
+    assert HASHED_KEY not in written
+    record = json.loads(written.strip().splitlines()[0])
+    assert record["path"] == "/v1/wallet/refund"
+    assert record["query_param_names"] == ["api_key", "page"]
+
+
+def test_forced_rollover_enforces_the_retention_limit(
+    handler: DailyRotatingFileHandler, log_dir: Path
+) -> None:
+    handler.backupCount = 3
+    handler.emit(
+        logging.LogRecord("t", logging.INFO, "", 0, "current", (), None),
+    )
+    handler.flush()
+
+    now = time.time()
+    for day in range(1, 6):
+        stale = log_dir / f"app_2024-01-0{day}.log"
+        stale.write_text("stale\n")
+        os.utime(stale, (now - day * 86400, now - day * 86400))
+
+    handler.doRollover()
+
+    remaining = sorted(p.name for p in log_dir.glob("app_*.log"))
+    assert len(remaining) == handler.backupCount
+    assert Path(handler.baseFilename).name in remaining