From a4328e4162d6dddbbdb74cbc33343b535ef181f2 Mon Sep 17 00:00:00 2001 From: 9qeklajc Date: Sun, 27 Sep 2026 12:16:33 +0200 Subject: [PATCH] log: record model and provider on the request completion line --- routstr/core/middleware.py | 30 +++- routstr/proxy.py | 9 ++ .../test_log_model_provider_attribution.py | 143 ++++++++++++++++++ 3 files changed, 174 insertions(+), 8 deletions(-) create mode 100644 tests/unit/test_log_model_provider_attribution.py diff --git a/routstr/core/middleware.py b/routstr/core/middleware.py index cbcab96b..517f4d2c 100644 --- a/routstr/core/middleware.py +++ b/routstr/core/middleware.py @@ -144,6 +144,13 @@ class LoggingMiddleware(BaseHTTPMiddleware): "status_code": response.status_code, "duration_ms": round(duration * 1000, 2), } + # Omitted rather than null on routes that resolve no model. + model = getattr(request.state, "model", None) + if model: + extra["model"] = model + provider = getattr(request.state, "provider", None) + if provider: + extra["provider"] = provider if response.status_code >= 400: error_detail = getattr(request.state, "error_detail", None) if isinstance(error_detail, dict): @@ -162,16 +169,23 @@ class LoggingMiddleware(BaseHTTPMiddleware): except Exception as e: # Always log failures, even for skipped paths, so we don't lose errors. duration = time.time() - start_time + failure_extra: dict[str, object] = { + "request_id": request_id, + "method": request.method, + "path": path, + "duration_ms": round(duration * 1000, 2), + "error": str(e), + "error_type": type(e).__name__, + } + model = getattr(request.state, "model", None) + if model: + failure_extra["model"] = model + provider = getattr(request.state, "provider", None) + if provider: + failure_extra["provider"] = provider logger.error( "Request failed", - extra={ - "request_id": request_id, - "method": request.method, - "path": path, - "duration_ms": round(duration * 1000, 2), - "error": str(e), - "error_type": type(e).__name__, - }, + extra=failure_extra, exc_info=True, ) raise diff --git a/routstr/proxy.py b/routstr/proxy.py index 26bf20e7..9c9e1f6e 100644 --- a/routstr/proxy.py +++ b/routstr/proxy.py @@ -460,6 +460,10 @@ async def _proxy( else: model_id = request_body_dict.get("model", "unknown") + # Set before routing so the completion log is attributed even when the + # request fails before an upstream is chosen (400/401/402). + request.state.model = model_id + # Exact Tinfoil attestation GET routes don't map to models — forward # without model/cost/auth lookups. Do not prefix-match here: paths such as # /attestationjunk must continue through normal authentication. @@ -482,6 +486,7 @@ async def _proxy( last_error_response = None for i, upstream in enumerate(selected_upstreams): + request.state.provider = upstream.provider_type try: headers = upstream.prepare_headers(dict(request.headers)) response = await upstream.forward_get_request(request, path, headers) @@ -780,6 +785,10 @@ async def _proxy( already_stripped: set[str] = set() for i, (model_obj, upstream) in enumerate(candidates): + # Served model id, not the requested alias, so the completion log + # matches the billing lines for this request. + request.state.model = getattr(model_obj, "id", None) or model_id + request.state.provider = upstream.provider_type if i > 0 and request_body_dict: # The reservation was sized to the previous candidate's envelope; # settlement bills the serving candidate, so a pricier fallback diff --git a/tests/unit/test_log_model_provider_attribution.py b/tests/unit/test_log_model_provider_attribution.py new file mode 100644 index 00000000..916f0599 --- /dev/null +++ b/tests/unit/test_log_model_provider_attribution.py @@ -0,0 +1,143 @@ +"""Model and provider attribution on the request completion/failure log lines.""" + +import json +import logging +from collections.abc import Iterator +from pathlib import Path +from typing import Any + +import pytest +from fastapi import FastAPI, Request +from fastapi.testclient import TestClient +from pythonjsonlogger import jsonlogger + +from routstr.core.logging import ( + DailyRotatingFileHandler, + RequestIdFilter, + SecurityFilter, + VersionFilter, +) +from routstr.core.middleware import LoggingMiddleware + + +@pytest.fixture +def handler(tmp_path: Path) -> Iterator[DailyRotatingFileHandler]: + log_dir = tmp_path / "logs" + log_dir.mkdir() + h = DailyRotatingFileHandler( + str(log_dir / "app.log"), when="midnight", interval=1, backupCount=30 + ) + h.setLevel(logging.DEBUG) + h.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 f in (VersionFilter(), RequestIdFilter(), SecurityFilter()): + h.addFilter(f) + try: + yield h + finally: + h.close() + + +def _records(handler: DailyRotatingFileHandler) -> list[dict[str, Any]]: + handler.flush() + text = Path(handler.baseFilename).read_text() + return [json.loads(line) for line in text.strip().splitlines() if line.strip()] + + +def _record(handler: DailyRotatingFileHandler, message: str) -> dict[str, Any]: + matches = [r for r in _records(handler) if r.get("message") == message] + assert matches, f"no {message!r} record was written" + return matches[-1] + + +def _build_app() -> FastAPI: + """Middleware wired like ``main.py``, with routes that set attribution.""" + app = FastAPI() + app.add_middleware(LoggingMiddleware) + + @app.post("/v1/chat/completions") + async def completions(request: Request) -> dict: + request.state.model = "z-ai/glm-5.3-flash" + request.state.provider = "openrouter" + return {"ok": True} + + @app.post("/v1/models") + async def models() -> dict: + return {"ok": True} + + @app.post("/v1/broken") + async def broken(request: Request) -> dict: + request.state.model = "deepseek/deepseek-v4.1-flash" + request.state.provider = "venice" + raise RuntimeError("upstream exploded") + + return app + + +def _with_handler(handler: DailyRotatingFileHandler) -> Any: + 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] + + class _Ctx: + def __enter__(self) -> None: + return None + + def __exit__(self, *exc: object) -> None: + middleware_logger.handlers = original_handlers + + return _Ctx() + + +def test_completion_log_carries_model_and_provider( + handler: DailyRotatingFileHandler, +) -> None: + app = _build_app() + with _with_handler(handler): + with TestClient(app, raise_server_exceptions=False) as client: + response = client.post( + "/v1/chat/completions", json={"model": "glm-5.3-flash"} + ) + assert response.status_code == 200 + + rec = _record(handler, "Request completed") + assert rec["model"] == "z-ai/glm-5.3-flash" + assert rec["provider"] == "openrouter" + assert rec["status_code"] == 200 + assert isinstance(rec["duration_ms"], (int, float)) + + +def test_completion_log_omits_attribution_when_route_sets_none( + handler: DailyRotatingFileHandler, +) -> None: + app = _build_app() + with _with_handler(handler): + with TestClient(app, raise_server_exceptions=False) as client: + response = client.post("/v1/models", json={}) + assert response.status_code == 200 + + rec = _record(handler, "Request completed") + assert "model" not in rec + assert "provider" not in rec + + +def test_failed_request_log_carries_attribution( + handler: DailyRotatingFileHandler, +) -> None: + app = _build_app() + with _with_handler(handler): + with TestClient(app, raise_server_exceptions=False) as client: + response = client.post("/v1/broken", json={}) + assert response.status_code == 500 + + rec = _record(handler, "Request failed") + assert rec["model"] == "deepseek/deepseek-v4.1-flash" + assert rec["provider"] == "venice" + assert rec["error_type"] == "RuntimeError"