From 89d316a1401c2954277459f8065eae3896e5e6a2 Mon Sep 17 00:00:00 2001 From: 9qeklajc Date: Tue, 18 Aug 2026 02:23:28 +0200 Subject: [PATCH 1/5] feat: identify client app in request and error logs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Resolve the app or agent that made each request from the OpenRouter-convention identity headers — X-Title (app name), then HTTP-Referer (app URL), then User-Agent — falling back to 'unknown' when none are present. The value is stored in a context variable by the logging middleware, so every log line emitted while handling a request carries a client_app field, including error messages raised deep in the wallet/mint code, and is attached explicitly to the incoming/completed/ failed request log events. Header values are attacker-controlled free text: they are capped at 120 characters and stripped of control characters so a crafted header cannot bloat log lines or inject fake log records. The existing SecurityFilter still runs after the new filter, so secrets accidentally placed in identity headers are redacted as usual. --- routstr/core/logging.py | 40 +++++++++-- routstr/core/middleware.py | 50 +++++++++++++- tests/unit/test_client_app_logging.py | 95 +++++++++++++++++++++++++++ 3 files changed, 180 insertions(+), 5 deletions(-) create mode 100644 tests/unit/test_client_app_logging.py diff --git a/routstr/core/logging.py b/routstr/core/logging.py index 3886637c..2ca5872e 100644 --- a/routstr/core/logging.py +++ b/routstr/core/logging.py @@ -182,6 +182,32 @@ class RequestIdFilter(logging.Filter): return True +class ClientAppFilter(logging.Filter): + """Filter to add the requesting client app to all log records. + + The client app (the app or agent that made the request) is resolved by the + logging middleware from the OpenRouter-convention identity headers + (``X-Title``/``HTTP-Referer``, falling back to ``User-Agent``) and stored + in a context variable, so every log line emitted while handling a request + carries it — including error messages raised deep in the wallet/mint code. + """ + + 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 + + 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" + return True + + # Standard ``LogRecord`` attributes that are never user-supplied ``extra`` # fields; skipped when redacting structured extras (``msg``/``message`` are # handled separately above). @@ -323,7 +349,7 @@ def setup_logging() -> None: "rich_tracebacks": True, "markup": True, "console": _console, - "filters": ["request_id_filter", "security_filter"], + "filters": ["request_id_filter", "client_app_filter", "security_filter"], } else: console_handler = { @@ -331,7 +357,7 @@ def setup_logging() -> None: "level": log_level, "formatter": "plain", "stream": "ext://sys.stdout", - "filters": ["request_id_filter", "security_filter"], + "filters": ["request_id_filter", "client_app_filter", "security_filter"], } LOGGING_CONFIG = { @@ -340,7 +366,7 @@ def setup_logging() -> None: "formatters": { "json": { "()": jsonlogger.JsonFormatter, - "format": "%(asctime)s %(name)s %(levelname)s %(message)s %(pathname)s %(lineno)d %(version)s %(request_id)s", + "format": "%(asctime)s %(name)s %(levelname)s %(message)s %(pathname)s %(lineno)d %(version)s %(request_id)s %(client_app)s", "datefmt": "%Y-%m-%d %H:%M:%S", }, "plain": { @@ -351,6 +377,7 @@ def setup_logging() -> None: "filters": { "version_filter": {"()": VersionFilter}, "request_id_filter": {"()": RequestIdFilter}, + "client_app_filter": {"()": ClientAppFilter}, "security_filter": {"()": SecurityFilter}, }, "handlers": { @@ -364,7 +391,12 @@ def setup_logging() -> None: "interval": 1, # Every 1 day "backupCount": 30, # Keep 30 days of logs "atTime": None, # Rotate at midnight (00:00) - "filters": ["version_filter", "request_id_filter", "security_filter"], + "filters": [ + "version_filter", + "request_id_filter", + "client_app_filter", + "security_filter", + ], }, }, "loggers": { diff --git a/routstr/core/middleware.py b/routstr/core/middleware.py index 442c0a18..557cb9f6 100644 --- a/routstr/core/middleware.py +++ b/routstr/core/middleware.py @@ -4,6 +4,7 @@ from contextvars import ContextVar from typing import Callable from fastapi import Request, Response +from starlette.datastructures import Headers from starlette.middleware.base import BaseHTTPMiddleware from .logging import get_logger @@ -13,6 +14,39 @@ 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 that made the current request, so +# every log line emitted while handling it (including deep wallet/mint errors) +# can say who triggered it. "unknown" when the client sent no identity headers. +client_app_context: ContextVar[str | None] = ContextVar("client_app") + +UNKNOWN_CLIENT_APP = "unknown" + +# Client identity headers, in priority order. Follows the OpenRouter +# convention: apps identify themselves with ``X-Title`` (human-readable app +# name) and/or ``HTTP-Referer`` (app URL); ``User-Agent`` is the fallback for +# SDKs and scripts that set neither. +_CLIENT_APP_HEADERS: tuple[str, ...] = ("x-title", "referer", "user-agent") + +# Header values are attacker-controlled free text; cap the length so a single +# request can't bloat every log line, and strip control characters so a crafted +# header can't inject fake log records. +_CLIENT_APP_MAX_LENGTH = 120 + + +def client_app_from_headers(headers: Headers) -> str: + """Resolve the client app identity from request headers. + + Priority: ``X-Title`` > ``HTTP-Referer`` > ``User-Agent`` > "unknown". + """ + for header in _CLIENT_APP_HEADERS: + raw = headers.get(header) + if raw is None: + continue + cleaned = "".join(ch for ch in raw if ch.isprintable()).strip() + if cleaned: + return cleaned[:_CLIENT_APP_MAX_LENGTH] + return UNKNOWN_CLIENT_APP + # Methods that are never logged: HEAD requests are health probes from # monitoring/load balancers, OPTIONS are CORS preflights — both are framework @@ -71,6 +105,10 @@ 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) + path = request.url.path should_log = _should_log(request.method, path) @@ -84,6 +122,7 @@ class LoggingMiddleware(BaseHTTPMiddleware): "request_id": request_id, "method": request.method, "path": path, + "client_app": client_app, "query_params": dict(request.query_params), }, ) @@ -100,6 +139,7 @@ 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), }, @@ -118,6 +158,7 @@ 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__, @@ -128,6 +169,13 @@ class LoggingMiddleware(BaseHTTPMiddleware): finally: # Reset context request_id_context.reset(token) + client_app_context.reset(client_app_token) -__all__ = ["LoggingMiddleware", "request_id_context"] +__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 new file mode 100644 index 00000000..935b168c --- /dev/null +++ b/tests/unit/test_client_app_logging.py @@ -0,0 +1,95 @@ +"""Unit tests for client-app identification in request logging.""" + +import logging + +from starlette.datastructures import Headers + +from routstr.core.logging import ClientAppFilter +from routstr.core.middleware import ( + UNKNOWN_CLIENT_APP, + client_app_context, + client_app_from_headers, +) + + +def _headers(**kwargs: str) -> Headers: + return Headers({k.replace("_", "-"): v for k, v in kwargs.items()}) + + +def _record() -> logging.LogRecord: + return logging.LogRecord( + name="routstr.test", + level=logging.INFO, + pathname=__file__, + lineno=1, + msg="test", + args=None, + exc_info=None, + ) + + +class TestClientAppFromHeaders: + def test_x_title_wins_over_all(self) -> None: + 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(self) -> 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(self) -> None: + headers = _headers(user_agent="python-httpx/0.27") + assert client_app_from_headers(headers) == "python-httpx/0.27" + + def test_unknown_when_no_identity_headers(self) -> None: + assert client_app_from_headers(Headers({})) == UNKNOWN_CLIENT_APP + assert UNKNOWN_CLIENT_APP == "unknown" + + def test_blank_header_falls_through_to_next(self) -> None: + 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(self) -> None: + headers = _headers(x_title=" ", user_agent="\t") + assert client_app_from_headers(headers) == UNKNOWN_CLIENT_APP + + def test_value_is_truncated(self) -> None: + headers = _headers(x_title="a" * 500) + assert client_app_from_headers(headers) == "a" * 120 + + def test_control_characters_are_stripped(self) -> None: + # A crafted header must not be able to inject fake log records. + headers = _headers(user_agent="evil-app\x1b[0m fake INFO line") + assert client_app_from_headers(headers) == "evil-app[0m fake INFO line" + + +class TestClientAppFilter: + def test_uses_context_variable(self) -> None: + token = client_app_context.set("Goose") + try: + record = _record() + assert ClientAppFilter().filter(record) is True + assert record.client_app == "Goose" # type: ignore[attr-defined] + finally: + client_app_context.reset(token) + + def test_defaults_to_unknown_outside_request_context(self) -> None: + record = _record() + assert ClientAppFilter().filter(record) is True + assert record.client_app == UNKNOWN_CLIENT_APP # type: ignore[attr-defined] + + def test_explicit_extra_is_not_overwritten(self) -> None: + token = client_app_context.set("context-app") + 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] + finally: + client_app_context.reset(token) From 56fb540383a20b9e90f323266e49d03464cfc770 Mon Sep 17 00:00:00 2001 From: 9qeklajc Date: Tue, 18 Aug 2026 02:28:43 +0200 Subject: [PATCH 2/5] refactor: align client-app tests with suite style, tighten comments Flatten the test classes into plain test functions matching the rest of tests/unit, add LoggingMiddleware integration tests covering request.state.client_app and the unknown fallback, and trim docstrings and comments to house density. --- routstr/core/logging.py | 8 +- routstr/core/middleware.py | 24 ++-- tests/unit/test_client_app_logging.py | 182 +++++++++++++++++--------- 3 files changed, 131 insertions(+), 83 deletions(-) diff --git a/routstr/core/logging.py b/routstr/core/logging.py index 2ca5872e..4decdb84 100644 --- a/routstr/core/logging.py +++ b/routstr/core/logging.py @@ -185,11 +185,9 @@ class RequestIdFilter(logging.Filter): class ClientAppFilter(logging.Filter): """Filter to add the requesting client app to all log records. - The client app (the app or agent that made the request) is resolved by the - logging middleware from the OpenRouter-convention identity headers - (``X-Title``/``HTTP-Referer``, falling back to ``User-Agent``) and stored - in a context variable, so every log line emitted while handling a request - carries it — including error messages raised deep in the wallet/mint code. + 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. """ def filter(self, record: logging.LogRecord) -> bool: diff --git a/routstr/core/middleware.py b/routstr/core/middleware.py index 557cb9f6..7adfe296 100644 --- a/routstr/core/middleware.py +++ b/routstr/core/middleware.py @@ -14,30 +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 that made the current request, so -# every log line emitted while handling it (including deep wallet/mint errors) -# can say who triggered it. "unknown" when the client sent no identity headers. +# 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. client_app_context: ContextVar[str | None] = ContextVar("client_app") UNKNOWN_CLIENT_APP = "unknown" -# Client identity headers, in priority order. Follows the OpenRouter -# convention: apps identify themselves with ``X-Title`` (human-readable app -# name) and/or ``HTTP-Referer`` (app URL); ``User-Agent`` is the fallback for -# SDKs and scripts that set neither. +# 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") -# Header values are attacker-controlled free text; cap the length so a single -# request can't bloat every log line, and strip control characters so a crafted -# header can't inject fake log records. +# 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. _CLIENT_APP_MAX_LENGTH = 120 def client_app_from_headers(headers: Headers) -> str: - """Resolve the client app identity from request headers. - - Priority: ``X-Title`` > ``HTTP-Referer`` > ``User-Agent`` > "unknown". - """ + """Resolve the requesting app from identity headers, or "unknown".""" for header in _CLIENT_APP_HEADERS: raw = headers.get(header) if raw is None: diff --git a/tests/unit/test_client_app_logging.py b/tests/unit/test_client_app_logging.py index 935b168c..ddeaec97 100644 --- a/tests/unit/test_client_app_logging.py +++ b/tests/unit/test_client_app_logging.py @@ -1,21 +1,20 @@ -"""Unit tests for client-app identification in request logging.""" +"""Tests for client-app identification in request logging.""" import logging +from fastapi import FastAPI, Request +from fastapi.testclient import TestClient from starlette.datastructures import Headers from routstr.core.logging import ClientAppFilter from routstr.core.middleware import ( UNKNOWN_CLIENT_APP, + LoggingMiddleware, client_app_context, client_app_from_headers, ) -def _headers(**kwargs: str) -> Headers: - return Headers({k.replace("_", "-"): v for k, v in kwargs.items()}) - - def _record() -> logging.LogRecord: return logging.LogRecord( name="routstr.test", @@ -28,68 +27,123 @@ def _record() -> logging.LogRecord: ) -class TestClientAppFromHeaders: - def test_x_title_wins_over_all(self) -> None: - 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(self) -> 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(self) -> None: - headers = _headers(user_agent="python-httpx/0.27") - assert client_app_from_headers(headers) == "python-httpx/0.27" - - def test_unknown_when_no_identity_headers(self) -> None: - assert client_app_from_headers(Headers({})) == UNKNOWN_CLIENT_APP - assert UNKNOWN_CLIENT_APP == "unknown" - - def test_blank_header_falls_through_to_next(self) -> None: - 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(self) -> None: - headers = _headers(x_title=" ", user_agent="\t") - assert client_app_from_headers(headers) == UNKNOWN_CLIENT_APP - - def test_value_is_truncated(self) -> None: - headers = _headers(x_title="a" * 500) - assert client_app_from_headers(headers) == "a" * 120 - - def test_control_characters_are_stripped(self) -> None: - # A crafted header must not be able to inject fake log records. - headers = _headers(user_agent="evil-app\x1b[0m fake INFO line") - assert client_app_from_headers(headers) == "evil-app[0m fake INFO line" +# --------------------------------------------------------------------------- +# client_app_from_headers +# --------------------------------------------------------------------------- -class TestClientAppFilter: - def test_uses_context_variable(self) -> None: - token = client_app_context.set("Goose") - try: - record = _record() - assert ClientAppFilter().filter(record) is True - assert record.client_app == "Goose" # type: ignore[attr-defined] - finally: - client_app_context.reset(token) +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_defaults_to_unknown_outside_request_context(self) -> None: + +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 + + +def test_value_is_truncated_to_120_chars() -> None: + assert client_app_from_headers(Headers({"x-title": "a" * 500})) == "a" * 120 + + +def test_control_characters_are_stripped() -> None: + """A crafted header must not be able to forge log records.""" + headers = Headers({"user-agent": "evil-app\x1b[0m fake INFO line"}) + 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: record = _record() assert ClientAppFilter().filter(record) is True - assert record.client_app == UNKNOWN_CLIENT_APP # type: ignore[attr-defined] + assert record.client_app == "Goose" # type: ignore[attr-defined] + finally: + client_app_context.reset(token) - def test_explicit_extra_is_not_overwritten(self) -> None: - token = client_app_context.set("context-app") - 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] - finally: - client_app_context.reset(token) + +def test_filter_defaults_to_unknown_outside_request_context() -> None: + record = _record() + assert ClientAppFilter().filter(record) is True + 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") + 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] + finally: + client_app_context.reset(token) + + +# --------------------------------------------------------------------------- +# 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} From 172cb87a998a12c035319aec5b5617409d9df53a Mon Sep 17 00:00:00 2001 From: 9qeklajc Date: Tue, 18 Aug 2026 14:47:31 +0200 Subject: [PATCH 3/5] clean up --- routstr/core/logging.py | 23 ++-- routstr/core/middleware.py | 32 +++--- tests/unit/test_client_app_logging.py | 146 ++++++++++---------------- 3 files changed, 76 insertions(+), 125 deletions(-) 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] From efad99b938a2a56d64ff5a7b615df167f6b56d32 Mon Sep 17 00:00:00 2001 From: 9qeklajc Date: Tue, 8 Sep 2026 20:03:38 +0200 Subject: [PATCH 4/5] Keep client referrer attribution free of private URL data --- routstr/core/middleware.py | 10 +++ tests/unit/test_client_app_logging.py | 87 ++++++++++++++++++++++++++- 2 files changed, 96 insertions(+), 1 deletion(-) diff --git a/routstr/core/middleware.py b/routstr/core/middleware.py index cff7d39a..228cd68a 100644 --- a/routstr/core/middleware.py +++ b/routstr/core/middleware.py @@ -2,6 +2,7 @@ import time import uuid from contextvars import ContextVar from typing import Callable +from urllib.parse import urlsplit from fastapi import Request, Response from starlette.datastructures import Headers @@ -39,6 +40,15 @@ def client_app_from_headers(headers: Headers) -> str: if raw is None: continue cleaned = "".join(ch for ch in raw if ch.isprintable()).strip() + if header in ("http-referer", "referer"): + try: + url = urlsplit(cleaned) + if url.scheme not in ("http", "https") or not url.hostname: + continue + except ValueError: + continue + # Attribution needs the origin, not credentials or private page URLs. + cleaned = f"{url.scheme}://{url.netloc.rsplit('@', 1)[-1]}" if cleaned: return cleaned[:_CLIENT_APP_MAX_LENGTH] return UNKNOWN_CLIENT_APP diff --git a/tests/unit/test_client_app_logging.py b/tests/unit/test_client_app_logging.py index 3f527083..a76d411c 100644 --- a/tests/unit/test_client_app_logging.py +++ b/tests/unit/test_client_app_logging.py @@ -1,9 +1,10 @@ """Tests for client-app identification in request logging.""" +import asyncio import logging import pytest -from fastapi import FastAPI +from fastapi import FastAPI, Request, Response from fastapi.testclient import TestClient from starlette.datastructures import Headers @@ -66,6 +67,27 @@ def test_client_app_from_headers(headers: dict[str, str], expected: str) -> None assert client_app_from_headers(Headers(headers)) == expected +@pytest.mark.parametrize("header", ["http-referer", "referer"]) +@pytest.mark.parametrize( + ("url", "expected"), + [ + ( + "https://alice:password@app.example:8443/private/chat?token=secret#access_token=secret", + "https://app.example:8443", + ), + ("http://[::1]:3000/chat?key=secret", "http://[::1]:3000"), + ("https://app.example/" + "a" * 200, "https://app.example"), + ("https://[invalid", "curl/8.4.0"), + ("/private/chat?token=secret", "curl/8.4.0"), + ("javascript:secret", "curl/8.4.0"), + ("https:///private", "curl/8.4.0"), + ], +) +def test_referrer_only_identifies_origin(header: str, url: str, expected: str) -> None: + headers = Headers({header: url, "user-agent": "curl/8.4.0"}) + assert client_app_from_headers(headers) == expected + + def test_value_is_truncated_to_120_chars() -> None: assert client_app_from_headers(Headers({"x-title": "a" * 500})) == "a" * 120 @@ -86,6 +108,69 @@ def test_filter_reads_context_variable() -> None: client_app_context.reset(token) +@pytest.mark.parametrize("fail", [False, True]) +async def test_context_is_restored_after_request(fail: bool) -> None: + middleware = LoggingMiddleware(FastAPI()) + request = Request( + { + "type": "http", + "method": "GET", + "path": "/test", + "query_string": b"", + "headers": [], + } + ) + + async def call_next(request: Request) -> Response: + assert client_app_context.get() == UNKNOWN_CLIENT_APP + if fail: + raise RuntimeError("handler failed") + return Response() + + token = client_app_context.set("outer") + try: + if fail: + with pytest.raises(RuntimeError, match="handler failed"): + await middleware.dispatch(request, call_next) + else: + await middleware.dispatch(request, call_next) + assert client_app_context.get() == "outer" + finally: + client_app_context.reset(token) + + +async def test_concurrent_requests_keep_their_own_client_app() -> None: + middleware = LoggingMiddleware(FastAPI()) + ready = asyncio.Event() + apps: list[str] = [] + + async def call_next(request: Request) -> Response: + apps.append(request.headers["x-title"]) + if len(apps) == 2: + ready.set() + await asyncio.wait_for(ready.wait(), timeout=5) + assert client_app_context.get() == request.headers["x-title"] + return Response() + + await asyncio.gather( + *( + middleware.dispatch( + Request( + { + "type": "http", + "method": "GET", + "path": "/test", + "query_string": b"", + "headers": [(b"x-title", app)], + } + ), + call_next, + ) + for app in (b"Goose", b"Pi") + ) + ) + + def test_filter_defaults_to_unknown_outside_request_context() -> None: record = _record() assert ClientAppFilter().filter(record) is True From e970e150149ace5336fbd3e83ae021335fa55ade Mon Sep 17 00:00:00 2001 From: 9qeklajc Date: Tue, 8 Sep 2026 20:07:36 +0200 Subject: [PATCH 5/5] Trim redundant client attribution comments --- routstr/core/logging.py | 3 +-- routstr/core/middleware.py | 7 ++----- tests/unit/test_client_app_logging.py | 2 -- 3 files changed, 3 insertions(+), 9 deletions(-) diff --git a/routstr/core/logging.py b/routstr/core/logging.py index 563b368d..bc088ed5 100644 --- a/routstr/core/logging.py +++ b/routstr/core/logging.py @@ -183,10 +183,9 @@ class RequestIdFilter(logging.Filter): class ClientAppFilter(logging.Filter): - """Filter to add the requesting client app to all log records.""" + """Attach request-local app attribution to log records.""" def filter(self, record: logging.LogRecord) -> bool: - """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 diff --git a/routstr/core/middleware.py b/routstr/core/middleware.py index 228cd68a..da073cd5 100644 --- a/routstr/core/middleware.py +++ b/routstr/core/middleware.py @@ -15,13 +15,11 @@ logger = get_logger(__name__) # Context variable to store request ID across async context request_id_context: ContextVar[str | None] = ContextVar("request_id") -# Context variable to store the client app across async context client_app_context: ContextVar[str | None] = ContextVar("client_app") UNKNOWN_CLIENT_APP = "unknown" -# Identity headers in priority order. X-Title and HTTP-Referer are the -# OpenRouter convention; User-Agent covers SDKs and scripts that set neither. +# Prefer OpenRouter app headers, then browser and SDK fallbacks. _CLIENT_APP_HEADERS: tuple[str, ...] = ( "x-title", "http-referer", @@ -29,8 +27,7 @@ _CLIENT_APP_HEADERS: tuple[str, ...] = ( "user-agent", ) -# Header values are attacker-controlled: cap the length so one request can't -# bloat every log line. +# Limit untrusted header data repeated in every log record. _CLIENT_APP_MAX_LENGTH = 120 diff --git a/tests/unit/test_client_app_logging.py b/tests/unit/test_client_app_logging.py index a76d411c..107f8c2c 100644 --- a/tests/unit/test_client_app_logging.py +++ b/tests/unit/test_client_app_logging.py @@ -93,7 +93,6 @@ def test_value_is_truncated_to_120_chars() -> None: def test_control_characters_are_stripped() -> None: - """A crafted header must not be able to forge log records.""" headers = Headers({"user-agent": "evil-app\x1b[0m fake INFO line"}) assert client_app_from_headers(headers) == "evil-app[0m fake INFO line" @@ -178,7 +177,6 @@ def test_filter_defaults_to_unknown_outside_request_context() -> None: 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")