diff --git a/routstr/core/logging.py b/routstr/core/logging.py index 4decdb84..563b368d 100644 --- a/routstr/core/logging.py +++ b/routstr/core/logging.py @@ -183,26 +183,15 @@ class RequestIdFilter(logging.Filter): class ClientAppFilter(logging.Filter): - """Filter to add the requesting client app to all log records. - - The middleware resolves it from the OpenRouter-convention identity headers - (X-Title, then Referer, then User-Agent) into a context variable, so even - errors raised deep in the wallet/mint code carry it. - """ + """Filter to add the requesting client app to all log records.""" def filter(self, record: logging.LogRecord) -> bool: - """Add the client app to the log record unless set explicitly.""" - if hasattr(record, "client_app"): - return True - try: - # Import here to avoid circular imports - from .middleware import UNKNOWN_CLIENT_APP, client_app_context + """Add the client app to the log record if available.""" + # Import here to avoid circular imports + from .middleware import UNKNOWN_CLIENT_APP, client_app_context - client_app = client_app_context.get(None) - record.client_app = client_app if client_app else UNKNOWN_CLIENT_APP - except ImportError: - # If middleware isn't available yet, just use default - record.client_app = "unknown" + client_app = client_app_context.get(None) + record.client_app = client_app if client_app else UNKNOWN_CLIENT_APP return True diff --git a/routstr/core/middleware.py b/routstr/core/middleware.py index 7adfe296..cff7d39a 100644 --- a/routstr/core/middleware.py +++ b/routstr/core/middleware.py @@ -14,26 +14,26 @@ logger = get_logger(__name__) # Context variable to store request ID across async context request_id_context: ContextVar[str | None] = ContextVar("request_id") -# Context variable holding the client app behind the current request, so log -# lines emitted while handling it (wallet/mint errors included) can say who -# triggered it. +# Context variable to store the client app across async context client_app_context: ContextVar[str | None] = ContextVar("client_app") UNKNOWN_CLIENT_APP = "unknown" -# OpenRouter-convention identity headers, in priority order: X-Title carries -# the app name, HTTP-Referer its URL; User-Agent covers SDKs and scripts that -# set neither. -_CLIENT_APP_HEADERS: tuple[str, ...] = ("x-title", "referer", "user-agent") +# Identity headers in priority order. X-Title and HTTP-Referer are the +# OpenRouter convention; User-Agent covers SDKs and scripts that set neither. +_CLIENT_APP_HEADERS: tuple[str, ...] = ( + "x-title", + "http-referer", + "referer", + "user-agent", +) -# Headers are attacker-controlled free text: cap the length so one request -# can't bloat every log line, strip control characters so a crafted value -# can't forge log records. +# Header values are attacker-controlled: cap the length so one request can't +# bloat every log line. _CLIENT_APP_MAX_LENGTH = 120 def client_app_from_headers(headers: Headers) -> str: - """Resolve the requesting app from identity headers, or "unknown".""" for header in _CLIENT_APP_HEADERS: raw = headers.get(header) if raw is None: @@ -101,9 +101,9 @@ class LoggingMiddleware(BaseHTTPMiddleware): # Set request ID in context for logging token = request_id_context.set(request_id) - client_app = client_app_from_headers(request.headers) - request.state.client_app = client_app - client_app_token = client_app_context.set(client_app) + client_app_token = client_app_context.set( + client_app_from_headers(request.headers) + ) path = request.url.path should_log = _should_log(request.method, path) @@ -118,7 +118,6 @@ class LoggingMiddleware(BaseHTTPMiddleware): "request_id": request_id, "method": request.method, "path": path, - "client_app": client_app, "query_params": dict(request.query_params), }, ) @@ -135,7 +134,6 @@ class LoggingMiddleware(BaseHTTPMiddleware): "request_id": request_id, "method": request.method, "path": path, - "client_app": client_app, "status_code": response.status_code, "duration_ms": round(duration * 1000, 2), }, @@ -154,7 +152,6 @@ class LoggingMiddleware(BaseHTTPMiddleware): "request_id": request_id, "method": request.method, "path": path, - "client_app": client_app, "duration_ms": round(duration * 1000, 2), "error": str(e), "error_type": type(e).__name__, @@ -172,6 +169,5 @@ __all__ = [ "LoggingMiddleware", "UNKNOWN_CLIENT_APP", "client_app_context", - "client_app_from_headers", "request_id_context", ] diff --git a/tests/unit/test_client_app_logging.py b/tests/unit/test_client_app_logging.py index ddeaec97..3f527083 100644 --- a/tests/unit/test_client_app_logging.py +++ b/tests/unit/test_client_app_logging.py @@ -2,7 +2,8 @@ import logging -from fastapi import FastAPI, Request +import pytest +from fastapi import FastAPI from fastapi.testclient import TestClient from starlette.datastructures import Headers @@ -27,49 +28,42 @@ def _record() -> logging.LogRecord: ) -# --------------------------------------------------------------------------- -# client_app_from_headers -# --------------------------------------------------------------------------- - - -def test_x_title_takes_priority() -> None: - """X-Title wins over Referer and User-Agent.""" - headers = Headers( - { - "x-title": "Goose", - "referer": "https://myapp.example.com", - "user-agent": "python-httpx/0.27", - } - ) - assert client_app_from_headers(headers) == "Goose" - - -def test_referer_used_when_no_x_title() -> None: - headers = Headers( - {"referer": "https://myapp.example.com", "user-agent": "python-httpx/0.27"} - ) - assert client_app_from_headers(headers) == "https://myapp.example.com" - - -def test_user_agent_is_last_fallback() -> None: - assert ( - client_app_from_headers(Headers({"user-agent": "curl/8.4.0"})) == "curl/8.4.0" - ) - - -def test_unknown_when_no_identity_headers() -> None: - assert client_app_from_headers(Headers({})) == UNKNOWN_CLIENT_APP - - -def test_blank_header_falls_through_to_next() -> None: - """A whitespace-only X-Title must not shadow a usable User-Agent.""" - headers = Headers({"x-title": " ", "user-agent": "curl/8.4.0"}) - assert client_app_from_headers(headers) == "curl/8.4.0" - - -def test_all_blank_resolves_to_unknown() -> None: - headers = Headers({"x-title": " ", "user-agent": "\t"}) - assert client_app_from_headers(headers) == UNKNOWN_CLIENT_APP +@pytest.mark.parametrize( + ("headers", "expected"), + [ + ( + { + "x-title": "Goose", + "http-referer": "https://myapp.example.com", + "user-agent": "python-httpx/0.27", + }, + "Goose", + ), + ( + {"http-referer": "https://myapp.example.com", "user-agent": "curl/8.4.0"}, + "https://myapp.example.com", + ), + ( + {"referer": "https://myapp.example.com", "user-agent": "curl/8.4.0"}, + "https://myapp.example.com", + ), + ({"user-agent": "curl/8.4.0"}, "curl/8.4.0"), + ({}, UNKNOWN_CLIENT_APP), + ({"x-title": " ", "user-agent": "curl/8.4.0"}, "curl/8.4.0"), + ({"x-title": " ", "user-agent": "\t"}, UNKNOWN_CLIENT_APP), + ], + ids=[ + "x-title-wins", + "http-referer", + "referer", + "user-agent-fallback", + "no-identity-headers", + "blank-falls-through", + "all-blank", + ], +) +def test_client_app_from_headers(headers: dict[str, str], expected: str) -> None: + assert client_app_from_headers(Headers(headers)) == expected def test_value_is_truncated_to_120_chars() -> None: @@ -82,11 +76,6 @@ def test_control_characters_are_stripped() -> None: assert client_app_from_headers(headers) == "evil-app[0m fake INFO line" -# --------------------------------------------------------------------------- -# ClientAppFilter -# --------------------------------------------------------------------------- - - def test_filter_reads_context_variable() -> None: token = client_app_context.set("Goose") try: @@ -103,47 +92,24 @@ def test_filter_defaults_to_unknown_outside_request_context() -> None: assert record.client_app == UNKNOWN_CLIENT_APP # type: ignore[attr-defined] -def test_filter_keeps_explicit_extra() -> None: - """extra={"client_app": ...} on a log call wins over the context value.""" - token = client_app_context.set("context-app") +def test_handler_logs_carry_client_app(caplog: pytest.LogCaptureFixture) -> None: + """A log line emitted inside a handler still names the app that triggered it.""" + app = FastAPI() + handler_logger = logging.getLogger("routstr.test.handler") + + @app.get("/whoami") + async def whoami() -> dict[str, bool]: + handler_logger.warning("something went wrong") + return {"ok": True} + + app.add_middleware(LoggingMiddleware) + + caplog.handler.addFilter(ClientAppFilter()) + handler_logger.addHandler(caplog.handler) try: - record = _record() - record.client_app = "explicit-app" # type: ignore[attr-defined] - assert ClientAppFilter().filter(record) is True - assert record.client_app == "explicit-app" # type: ignore[attr-defined] + TestClient(app).get("/whoami", headers={"X-Title": "Goose"}) finally: - client_app_context.reset(token) + handler_logger.removeHandler(caplog.handler) - -# --------------------------------------------------------------------------- -# LoggingMiddleware integration -# --------------------------------------------------------------------------- - - -def test_middleware_exposes_client_app_on_request_state() -> None: - app = FastAPI() - - @app.get("/whoami") - async def whoami(request: Request) -> dict: - return {"client_app": request.state.client_app} - - app.add_middleware(LoggingMiddleware) - client = TestClient(app) - - response = client.get("/whoami", headers={"X-Title": "Goose"}) - assert response.json() == {"client_app": "Goose"} - - -def test_middleware_reports_unknown_without_identity_headers() -> None: - app = FastAPI() - - @app.get("/whoami") - async def whoami(request: Request) -> dict: - return {"client_app": request.state.client_app} - - app.add_middleware(LoggingMiddleware) - # TestClient sets its own User-Agent; blank it out to simulate a bare client. - client = TestClient(app, headers={"user-agent": ""}) - - response = client.get("/whoami") - assert response.json() == {"client_app": UNKNOWN_CLIENT_APP} + record = next(r for r in caplog.records if r.name == "routstr.test.handler") + assert record.client_app == "Goose" # type: ignore[attr-defined]