From 39792c9d61d9e3f40f80c8058e42c6f58af20606 Mon Sep 17 00:00:00 2001 From: ian-at-strix Date: Wed, 7 Oct 2026 21:35:12 -0400 Subject: [PATCH] feat(llm): log the upstream provider behind OpenRouter (#1459) LiteLLM drops OpenRouter's top-level `provider` from stream chunks (including error chunks) and the `metadata.provider_name` of non-2xx replies, so the request log could not say which provider served or failed an attempt. Record both, plus OpenRouter's `metadata.error_type`, per attempt and emit them as `upstream=` / `upstream_error=` on the llm_request line. --- strix/config/models.py | 24 +++++++++++++ strix/llm/request_log.py | 33 ++++++++++++++++-- tests/test_cost_tracking.py | 65 +++++++++++++++++++++++++++++++++++ tests/test_llm_request_log.py | 21 +++++++++++ 4 files changed, 141 insertions(+), 2 deletions(-) diff --git a/strix/config/models.py b/strix/config/models.py index b2d6f9d0..09ff493e 100644 --- a/strix/config/models.py +++ b/strix/config/models.py @@ -5,6 +5,7 @@ from __future__ import annotations import asyncio import contextlib import inspect +import json import logging import os import time @@ -745,6 +746,11 @@ def _install_openrouter_stream_cost_capture() -> None: class _StrixOpenRouterStreamingHandler(OpenRouterChatCompletionStreamingHandler): def chunk_parser(self, chunk: dict[str, Any]) -> Any: + # Before parsing: LiteLLM raises on an error chunk and drops its + # top-level ``provider``. + request_log.record_upstream_provider( + chunk.get("provider"), _openrouter_error_type(chunk.get("error")) + ) stream = super().chunk_parser(chunk) usage = chunk.get("usage") response_id = chunk.get("id") or getattr(stream, "id", None) @@ -763,12 +769,22 @@ def _install_openrouter_stream_cost_capture() -> None: json_mode=json_mode, ) + def get_error_class(self, error_message: str, status_code: int, headers: Any) -> Any: + # A non-2xx reply names the provider in ``error.metadata``. + with contextlib.suppress(Exception): + error = json.loads(error_message)["error"] + request_log.record_upstream_provider( + error["metadata"].get("provider_name"), _openrouter_error_type(error) + ) + return super().get_error_class(error_message, status_code, headers) + def transform_response(self, *args: Any, **kwargs: Any) -> Any: # Non-streamed replies (LLM_DISABLE_STREAMING) skip the chunk parser. response = super().transform_response(*args, **kwargs) raw_response = kwargs.get("raw_response", args[1] if len(args) > 1 else None) with contextlib.suppress(Exception): body = raw_response.json() # type: ignore[union-attr] + request_log.record_upstream_provider(body.get("provider")) if body.get("usage"): record_openrouter_provider(body.get("provider"), body["usage"]) return response @@ -789,6 +805,14 @@ def _install_openrouter_stream_cost_capture() -> None: litellm.OpenrouterConfig = _StrixOpenrouterConfig # type: ignore[misc] +def _openrouter_error_type(error: object) -> object: + if isinstance(error, dict): + metadata = error.get("metadata") + if isinstance(metadata, dict): + return metadata.get("error_type") + return None + + OPENROUTER_ATTRIBUTION_HEADERS = { "HTTP-Referer": "https://strix.ai", "X-Title": "Strix", diff --git a/strix/llm/request_log.py b/strix/llm/request_log.py index 84dd890d..8e55a736 100644 --- a/strix/llm/request_log.py +++ b/strix/llm/request_log.py @@ -159,11 +159,33 @@ class HttpReply: status_code: int | None = None headers: dict[str, str] | None = None + upstream_provider: str | None = None + upstream_error_type: str | None = None _http_reply: ContextVar[HttpReply | None] = ContextVar("strix_llm_http_reply", default=None) +def record_upstream_provider(provider: object, error_type: object = None) -> None: + """Remember which provider behind a gateway served the attempt in flight.""" + reply = _http_reply.get() + if reply is None: + return + if isinstance(provider, str) and provider: + reply.upstream_provider = provider + if isinstance(error_type, str) and error_type: + reply.upstream_error_type = error_type + + +def _upstream_details(reply: HttpReply | None) -> list[tuple[str, object]]: + if reply is None: + return [] + return [ + ("upstream_provider", reply.upstream_provider), + ("upstream_error_type", reply.upstream_error_type), + ] + + async def record_http_reply(response: Response) -> None: """httpx ``response`` event hook: remember the reply for the attempt in flight. @@ -772,6 +794,7 @@ def _litellm_success( ("request", _litellm_request_details(kwargs)), ("response", _litellm_response_details(response)), ("litellm", _litellm_hidden_details(hidden, slo)), + *_upstream_details(_http_reply.get()), ), ) @@ -821,6 +844,7 @@ def _litellm_failure( ("request", _litellm_request_details(kwargs)), ("error", error or None), ("litellm", _litellm_hidden_details(hidden, slo)), + *_upstream_details(_http_reply.get()), ), ) @@ -894,15 +918,18 @@ def _observe_sdk_shared_http_client() -> None: def _log_line_sink(event: LlmRequestEvent) -> None: + details = event.details or {} level = logging.DEBUG if event.outcome == "success" else logging.WARNING logger.log( level, - "llm_request route=%s provider=%s model=%s host=%s outcome=%s status=%s " - "request_id=%s response_id=%s stream=%s duration_ms=%d ttft_ms=%s " + "llm_request route=%s provider=%s upstream=%s upstream_error=%s model=%s host=%s " + "outcome=%s status=%s request_id=%s response_id=%s stream=%s duration_ms=%d ttft_ms=%s " "req_bytes=%s res_bytes=%s finish=%s " "in=%s out=%s cached=%s cost=%s agent=%s attempt=%d%s", event.route, event.provider or "-", + details.get("upstream_provider") or "-", + details.get("upstream_error_type") or "-", event.model, event.api_host or "-", event.outcome, @@ -1070,6 +1097,7 @@ class RequestLoggingModel(Model): details=merge_details( ("request", request.details), ("response", _openai_response_details(response, raw_response)), + *_upstream_details(reply), ), ) status, request_id = _openai_error_fields(exc) @@ -1089,6 +1117,7 @@ class RequestLoggingModel(Model): details=merge_details( ("request", request.details), ("error", _exception_details(exc)), + *_upstream_details(reply), ), ) diff --git a/tests/test_cost_tracking.py b/tests/test_cost_tracking.py index 6a2f81a3..572143eb 100644 --- a/tests/test_cost_tracking.py +++ b/tests/test_cost_tracking.py @@ -2,6 +2,7 @@ from __future__ import annotations +import json import uuid from types import SimpleNamespace from typing import TYPE_CHECKING, Any @@ -389,3 +390,67 @@ def test_openrouter_request_carries_agent_session_id() -> None: assert body()["session_id"] == session_id finally: request_log.reset_call_context(token) + + +def _openrouter_config() -> Any: + _install_openrouter_stream_cost_capture() + config = ProviderConfigManager.get_provider_chat_config( + model="z-ai/glm-5.3", provider=LlmProviders.OPENROUTER + ) + assert config is not None + return config + + +def test_openrouter_records_upstream_of_stream_and_mid_stream_error() -> None: + handler = _openrouter_config().get_model_response_iterator( + streaming_response=iter([]), sync_stream=True + ) + reply = request_log.HttpReply() + token = request_log._http_reply.set(reply) + try: + handler.chunk_parser( + { + "id": "gen-a", + "created": 1, + "model": "z-ai/glm-5.3", + "provider": "Relace", + "choices": [{"index": 0, "delta": {"content": "x"}}], + } + ) + assert reply.upstream_provider == "Relace" + assert reply.upstream_error_type is None + with pytest.raises(Exception, match="incomplete tool call"): + handler.chunk_parser( + { + "id": "gen-a", + "provider": "Relace", + "error": { + "code": 400, + "message": "Generation stopped with an incomplete tool call.", + "metadata": {"error_type": "invalid_request"}, + }, + } + ) + finally: + request_log._http_reply.reset(token) + assert reply.upstream_provider == "Relace" + assert reply.upstream_error_type == "invalid_request" + + +def test_openrouter_records_upstream_of_pre_stream_error() -> None: + body = { + "error": { + "message": "Provider returned error", + "code": 400, + "metadata": {"raw": "...", "provider_name": "InferenceNet"}, + } + } + reply = request_log.HttpReply() + token = request_log._http_reply.set(reply) + try: + _openrouter_config().get_error_class(json.dumps(body), 400, {}) + _openrouter_config().get_error_class("502 Bad Gateway", 502, {}) + finally: + request_log._http_reply.reset(token) + assert reply.upstream_provider == "InferenceNet" + assert reply.upstream_error_type is None diff --git a/tests/test_llm_request_log.py b/tests/test_llm_request_log.py index d82c2e88..41bbc884 100644 --- a/tests/test_llm_request_log.py +++ b/tests/test_llm_request_log.py @@ -394,9 +394,30 @@ def test_log_line_sink_formats_without_content(caplog: pytest.LogCaptureFixture) assert "request_id=req_line01" in line assert "status=400" in line assert "provider=anthropic" in line + assert "upstream=- upstream_error=-" in line assert "SECRET PROMPT" not in line +def test_log_line_names_upstream_recorded_during_attempt( + caplog: pytest.LogCaptureFixture, +) -> None: + exc = _anthropic_error(400, ANTHROPIC_BLOCK_BODY, {}) + token = request_log._http_reply.set(request_log.HttpReply()) + try: + request_log.record_upstream_provider("Together", "provider_unavailable") + event = request_log.event_from_litellm( + _anthropic_kwargs(exc), None, None, None, outcome="error" + ) + finally: + request_log._http_reply.reset(token) + assert event.details is not None + assert event.details["upstream_provider"] == "Together" + with caplog.at_level(logging.DEBUG, logger="strix.llm.request_log"): + request_log._log_line_sink(event) + line = caplog.records[-1].getMessage() + assert "upstream=Together upstream_error=provider_unavailable" in line + + # --------------------------------------------------------------------------- # # sizes, timing, finish reason, free-form headers and details # # --------------------------------------------------------------------------- #