diff --git a/routstr/balance.py b/routstr/balance.py index e7d4468d..10f483f7 100644 --- a/routstr/balance.py +++ b/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, diff --git a/routstr/core/logging.py b/routstr/core/logging.py index 3886637c..c6840fb8 100644 --- a/routstr/core/logging.py +++ b/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 diff --git a/routstr/core/middleware.py b/routstr/core/middleware.py index 442c0a18..63d43888 100644 --- a/routstr/core/middleware.py +++ b/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()), }, ) diff --git a/routstr/core/redaction.py b/routstr/core/redaction.py index c0519581..bf8d9cc6 100644 --- a/routstr/core/redaction.py +++ b/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()) diff --git a/tests/unit/test_log_secret_redaction.py b/tests/unit/test_log_secret_redaction.py new file mode 100644 index 00000000..0f660dda --- /dev/null +++ b/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