From 52a4037248792f67b9fa98f2f4408a81166c3a35 Mon Sep 17 00:00:00 2001 From: Carl Boettiger Date: Wed, 19 Aug 2026 19:34:57 +0000 Subject: [PATCH] fix(logging): resolve caller identity before early-return rejections MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `origin`, `client`, `session_id` and `request_id` were derived only after routing succeeded, but three rejections log a response row before that point — unroutable model, missing provider key, and the new streaming refusal. Every one of those rows carried "origin": null. Caught by grepping the live pod straight after deploying the streaming rejection: the row was there, but anonymous. That defeats the reason it is logged — "who is asking for streaming?" needs the calling app, not just a model id and a timestamp. Resolve identity immediately after auth, ahead of all three rejections. This also fixes the pre-existing gap on the `unrouted` path, so a model-id miss is attributable to the app that sent it. Both rejection tests now assert origin and request_id are captured; reverting the hoist fails them. --- CHANGELOG.md | 9 +++++++++ llm_proxy.py | 27 ++++++++++++++++++--------- test_logging.py | 8 ++++++++ 3 files changed, 35 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6ea645a..b0cf934 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,15 @@ See [Releases](README.md#releases) for how a release is cut. ## [Unreleased] ### Fixed +- **Early-return rejections now log *which caller* was rejected.** `origin`, `client`, + `session_id` and `request_id` were derived only after routing succeeded, but three + rejections log a response row before that point — unroutable model, missing provider + key, and the new streaming refusal — so every one of those rows carried + `"origin": null`. Caught by grepping the live pod right after deploying the streaming + rejection: the row was there, but anonymous, which defeats the reason it is logged at + all ("who is asking for streaming?" needs the app, not just the model id). Identity is + now resolved immediately after auth, ahead of all three. Fixes the pre-existing gap on + the `unrouted` path too, so a model-id miss is attributable to the app that sent it. - **headless: undici's 300s `headersTimeout` no longer caps a slow LLM call (#128).** Node's `fetch` is undici, and undici enforces its own `headersTimeout` (default **300s**) that `AbortSignal` does not override. The runner posts *non-streaming* completions, so no diff --git a/llm_proxy.py b/llm_proxy.py index cc99069..a3076d1 100644 --- a/llm_proxy.py +++ b/llm_proxy.py @@ -793,6 +793,18 @@ async def proxy_chat(request: ChatRequest, http_request: Request, authorization: if not client_key or client_key not in VALID_PROXY_KEYS: raise HTTPException(status_code=401, detail="Unauthorized: Invalid or missing proxy key") + # Caller identity, derived before any early return: the three rejections below + # (streaming, unroutable model, missing provider key) each log a response row, + # and a row without `origin` cannot be traced to the app that sent it — which is + # the whole point of logging the rejection. This used to be computed after + # routing, so those rows carried "origin": null. + request_id = uuid.uuid4().hex[:8] + origin = http_request.headers.get("origin") or http_request.headers.get("referer") + # Session id: prefer the OpenAI `user` body field (geo-agent already sends its + # per-session UUID there); fall back to the X-Session-Id header for other clients. + session_id = request.user or http_request.headers.get("x-session-id") + client = http_request.headers.get("x-client") # e.g. "geo-agent/v3.13.1"; null until clients send it + # Streaming is not supported, and saying so is better than pretending (#129). # Logged against a synthetic provider — as with unrouted models — because the # request never reaches log_request, and "who is asking for streaming?" is @@ -802,7 +814,8 @@ async def proxy_chat(request: ChatRequest, http_request: Request, authorization: "Streaming is not supported by this proxy: it buffers each completion to " "log the request/response pair. Omit `stream` or set it to false." ) - log_response("streaming-unsupported", request.model, {}, 0, error=error_msg) + log_response("streaming-unsupported", request.model, {}, 0, error=error_msg, + origin=origin, request_id=request_id, session_id=session_id, client=client) raise HTTPException(status_code=400, detail=error_msg) # Determine provider based on model @@ -812,23 +825,19 @@ async def proxy_chat(request: ChatRequest, http_request: Request, authorization: # Client asked for something this deployment doesn't serve. Log it against a # synthetic provider so the miss is visible in the logs (the request never # reaches log_request, which runs after routing succeeds). - log_response("unrouted", request.model, {}, 0, error=str(e)) + log_response("unrouted", request.model, {}, 0, error=str(e), + origin=origin, request_id=request_id, session_id=session_id, client=client) raise HTTPException(status_code=400, detail=str(e)) endpoint = provider_config["endpoint"] api_key = provider_config["api_key"] if not api_key: error_msg = f"{provider_name.upper()} API key not configured on server" - log_response(provider_name, request.model, {}, 0, error=error_msg) + log_response(provider_name, request.model, {}, 0, error=error_msg, + origin=origin, request_id=request_id, session_id=session_id, client=client) raise HTTPException(status_code=500, detail=error_msg) # Log incoming request - request_id = uuid.uuid4().hex[:8] - origin = http_request.headers.get("origin") or http_request.headers.get("referer") - # Session id: prefer the OpenAI `user` body field (geo-agent already sends its - # per-session UUID there); fall back to the X-Session-Id header for other clients. - session_id = request.user or http_request.headers.get("x-session-id") - client = http_request.headers.get("x-client") # e.g. "geo-agent/v3.13.1"; null until clients send it log_request(provider_name, request.model, request.messages, len(request.tools or []), origin=origin, request_id=request_id, session_id=session_id, client=client, enable_thinking=request.enable_thinking) # Prepare request to LLM provider diff --git a/test_logging.py b/test_logging.py index c4a3223..5e13c02 100644 --- a/test_logging.py +++ b/test_logging.py @@ -956,6 +956,10 @@ class _FakeRequest: responses = [e for e in p._log_buffer if e.get("type") == "response"] assert len(responses) == 1 and responses[0]["provider"] == "unrouted" assert "glm-5" in responses[0]["error"] + # Same requirement as the streaming rejection: identity is resolved before the + # early return, so the miss is attributable to a caller rather than anonymous. + assert responses[0]["origin"] == "https://app" + assert responses[0]["request_id"] is not None # --------------------------------------------------------------------------- @@ -996,6 +1000,10 @@ class _FakeRequest: assert len(responses) == 1 assert responses[0]["provider"] == "streaming-unsupported" assert "Streaming is not supported" in responses[0]["error"] + # Traceable to the app that asked: a rejection row with a null origin cannot + # answer "who is asking for streaming?", which is why it is logged at all. + assert responses[0]["origin"] == "https://app" + assert responses[0]["request_id"] is not None # Rejected before routing, so no request row was emitted. assert [e for e in p._log_buffer if e.get("type") == "request"] == []