fix(logging): resolve caller identity before early-return rejections

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

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

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"] == []