feat(llm): structured per-attempt provider request log with provider request ids (#1353)

pyproject.toml

@@ -308,6 +308,9 @@ ignore = [
 "strix/report/dedupe.py" = ["PLC0415"]
 "strix/telemetry/logging.py" = ["PLC0415"]
 "strix/config/models.py" = ["PLC0415"]
+# LiteLLM is imported lazily: the request log is wired at startup on every
+# route, including the native OpenAI ones that never load LiteLLM.
+"strix/llm/request_log.py" = ["PLC0415"]
 # Heavy inference deps (httpx, openai) imported lazily so auth-status checks
 # don't pull them in.
 "strix/config/codex.py" = ["PLC0415"]

strix/config/codex.py

@@ -356,6 +356,8 @@ def build_openai_client() -> AsyncOpenAI:
     import httpx
     from openai import AsyncOpenAI
 
+    from strix.llm import request_log
+
     get_valid_token()  # fail fast at configure time if the sign-in is dead
 
     async def _auth_hook(request: httpx.Request) -> None:
@@ -367,6 +369,7 @@ def build_openai_client() -> AsyncOpenAI:
         timeout=httpx.Timeout(600.0, connect=30.0),
         event_hooks={"request": [_auth_hook]},
     )
+    request_log.observe_http_client(http_client)
     return AsyncOpenAI(
         api_key="strix-codex-oauth",  # placeholder; the hook overwrites Authorization
         base_url=CODEX_BASE_URL,

strix/config/models.py

@@ -40,6 +40,7 @@ from strix.config import codex
 from strix.config.loader import load_settings
 from strix.config.tool_call_ids import TurnCallIdRewriter, dedupe_input
 from strix.config.tool_call_limits import TurnToolCallLimiter
+from strix.llm import request_log
 
 
 if TYPE_CHECKING:
@@ -525,13 +526,37 @@ class StrixProvider(MultiProvider):
             # The ChatGPT subscription backend is always streamed; it has no
             # non-streaming mode to fall back to, so LLM_DISABLE_STREAMING
             # does not apply here.
-            model: Model = _CodexResponsesModel(
-                slug,
-                codex.get_subscription_client(),
-                reasoning_effort=llm.reasoning_effort,
+            model: Model = request_log.RequestLoggingModel(
+                _CodexResponsesModel(
+                    slug,
+                    codex.get_subscription_client(),
+                    reasoning_effort=llm.reasoning_effort,
+                ),
+                model_name=slug,
+                provider="openai-codex",
+                base_url=None,
             )
         else:
             model = super().get_model(model_name)
+            resolved_name = model_name or llm.model or "unknown"
+            if _routes_via_litellm(model):
+                # LiteLLM's callbacks log every reply; only a cancelled attempt
+                # (stream idle timeout, abandoned turn) escapes them.
+                model = request_log.RequestLoggingModel(
+                    model,
+                    model_name=resolved_name,
+                    provider=_litellm_provider(resolved_name),
+                    base_url=self._override_base_url or llm.api_base,
+                    route="litellm",
+                    abandoned_only=True,
+                )
+            else:
+                model = request_log.RequestLoggingModel(
+                    model,
+                    model_name=resolved_name,
+                    provider="openai",
+                    base_url=self._override_base_url or llm.api_base,
+                )
             if llm.disable_streaming:
                 model = _NonStreamingModel(model)
                 # The wrapper emits its single event only once the whole request
@@ -545,6 +570,23 @@ class StrixProvider(MultiProvider):
         )
 
 
+def _routes_via_litellm(model: Model) -> bool:
+    """LiteLLM-backed models are captured by the LiteLLM callback, not the wrapper."""
+    from agents.extensions.models.litellm_model import LitellmModel
+
+    return isinstance(model, LitellmModel)
+
+
+def _litellm_provider(model_name: str) -> str | None:
+    """The provider LiteLLM will route ``model_name`` to, if it can tell."""
+    try:
+        import litellm
+
+        return str(litellm.get_llm_provider(model_name)[1])
+    except Exception:  # noqa: BLE001 - unknown model ids are the provider's problem, not the log's
+        return None
+
+
 DEFAULT_MODEL_RETRY = ModelRetrySettings(
     max_retries=5,
     backoff=ModelRetryBackoffSettings(
@@ -621,6 +663,7 @@ def configure_sdk_model_defaults(settings: Settings) -> None:
     """Apply Strix config to SDK-native defaults."""
     llm = settings.llm
     set_tracing_disabled(True)
+    request_log.install()
     if codex.subscription_model(llm.model):
         return
     _configure_litellm_compatibility()
@@ -773,12 +816,16 @@ def _merge_litellm_headers(headers: dict[str, str]) -> None:
 
 def _register_openai_client_with_headers(llm: LlmSettings, headers: dict[str, str]) -> None:
     from agents import set_default_openai_client
+    from agents.models.openai_provider import shared_http_client
     from openai import AsyncOpenAI
 
     client = AsyncOpenAI(
         api_key=llm.api_key or "not-needed",
         base_url=llm.api_base,
         default_headers=dict(headers),
+        # The SDK's shared client is the one the request log observes for
+        # reply status, headers and provider request ids.
+        http_client=shared_http_client(),
     )
     set_default_openai_client(client, use_for_tracing=False)
 

strix/core/execution.py

@@ -33,6 +33,7 @@ from strix.core.sessions import (
     seed_initial_input,
     strip_all_images_from_session,
 )
+from strix.llm import request_log
 from strix.llm.compaction import is_context_overflow, maybe_compact
 
 
@@ -197,6 +198,44 @@ async def run_agent_loop(
     start_parked: bool = False,
     event_sink: StreamEventSink | None = None,
     hooks: RunHooks[dict[str, Any]] | None = None,
+) -> RunResultBase | None:
+    agent_name = getattr(agent, "name", None)
+    token = request_log.bind_call_context(
+        agent_id, agent_name if isinstance(agent_name, str) else None
+    )
+    try:
+        return await _run_agent_loop(
+            agent=agent,
+            initial_input=initial_input,
+            run_config=run_config,
+            context=context,
+            max_turns=max_turns,
+            coordinator=coordinator,
+            agent_id=agent_id,
+            interactive=interactive,
+            session=session,
+            start_parked=start_parked,
+            event_sink=event_sink,
+            hooks=hooks,
+        )
+    finally:
+        request_log.reset_call_context(token)
+
+
+async def _run_agent_loop(
+    *,
+    agent: Any,
+    initial_input: Any,
+    run_config: RunConfig,
+    context: dict[str, Any],
+    max_turns: int,
+    coordinator: AgentCoordinator,
+    agent_id: str,
+    interactive: bool,
+    session: Session | None,
+    start_parked: bool,
+    event_sink: StreamEventSink | None,
+    hooks: RunHooks[dict[str, Any]] | None,
 ) -> RunResultBase | None:
     await coordinator.attach_runtime(
         agent_id,
@@ -636,7 +675,7 @@ async def _run_cycle_parked(
         raise
     except Exception as exc:
         logger.exception("error escaped the run cycle for %s; parking as failed", agent_id)
-        await coordinator.set_status(agent_id, "failed", error=str(exc) or type(exc).__name__)
+        await coordinator.set_status(agent_id, "failed", error=request_log.failure_text(exc))
         await notify_parent_on_terminal(coordinator, agent_id, "failed")
         return None
 
@@ -658,6 +697,7 @@ async def _run_cycle(  # noqa: PLR0912, PLR0915
     image_strips = 0
     compactions = 0
     model_retries = 0
+    request_log.set_retry_attempt(0)
     while True:
         stream: Any = None
         pre_run_items: list[Any] = []
@@ -785,6 +825,7 @@ async def _run_cycle(  # noqa: PLR0912, PLR0915
                     exc,
                 )
                 await asyncio.sleep(delay)
+                request_log.set_retry_attempt(model_retries)
                 if session is not None:
                     input_data = []
                 continue
@@ -792,7 +833,9 @@ async def _run_cycle(  # noqa: PLR0912, PLR0915
                 await _salvage_stream_to_session(session, pre_run_items, stream, agent_id)
             if isinstance(exc, ProviderRefusalError):
                 logger.warning("agent %s refused by the model provider: %s", agent_id, exc)
-                await coordinator.set_status(agent_id, "failed", error=str(exc))
+                await coordinator.set_status(
+                    agent_id, "failed", error=request_log.failure_text(exc)
+                )
                 await notify_parent_on_terminal(coordinator, agent_id, "failed")
                 return None
             if isinstance(exc, MaxTurnsExceeded):
@@ -806,7 +849,7 @@ async def _run_cycle(  # noqa: PLR0912, PLR0915
             # non-interactive agent's task: a child that dies still owes its parent a
             # report, and the parent would otherwise wait out its timeout on a message
             # the dead child can no longer send.
-            await coordinator.set_status(agent_id, status, error=str(exc) or type(exc).__name__)
+            await coordinator.set_status(agent_id, status, error=request_log.failure_text(exc))
             await notify_parent_on_terminal(coordinator, agent_id, status)
             if not interactive:
                 raise

tests/test_disable_streaming.py

@@ -32,6 +32,7 @@ from openai.types.responses import (
 from strix.config import codex, loader
 from strix.config.loader import load_settings
 from strix.config.models import StrixProvider, _NonStreamingModel, _TurnGuardModel
+from strix.llm.request_log import RequestLoggingModel
 
 
 if TYPE_CHECKING:
@@ -312,7 +313,8 @@ def test_get_model_keeps_streaming_by_default(
 
     model = StrixProvider().get_model("openai/gpt-4o-mini")
     assert isinstance(model, _TurnGuardModel)
-    assert model._inner is inner
+    assert isinstance(model._inner, RequestLoggingModel)
+    assert model._inner._inner is inner
 
 
 def test_get_model_guards_subscription_model_but_keeps_it_streaming(

tests/test_execution_request_log.py

@@ -0,0 +1,134 @@
+from __future__ import annotations
+
+from typing import TYPE_CHECKING, Any, cast
+
+import httpx
+import pytest
+from agents import RunConfig, Runner
+from openai import APIError, PermissionDeniedError
+
+from strix.core import execution
+from strix.core.agents import AgentCoordinator
+from strix.llm import request_log
+
+
+if TYPE_CHECKING:
+    from collections.abc import AsyncIterator
+
+
+def _request() -> httpx.Request:
+    return httpx.Request("POST", "https://api.openai.com/v1/responses")
+
+
+def _midstream_api_error() -> APIError:
+    return APIError("An error occurred while processing the request.", _request(), body=None)
+
+
+def _blocked_error() -> PermissionDeniedError:
+    response = httpx.Response(
+        403, request=_request(), headers={"x-request-id": "req_blocked_hdr"}, text="blocked"
+    )
+    return PermissionDeniedError("Output blocked by policy", response=response, body=None)
+
+
+class _FakeStream:
+    def __init__(self, exc: BaseException | None = None) -> None:
+        self._exc = exc
+        self.run_loop_exception: BaseException | None = None
+        self.seen_context: request_log.LlmCallContext | None = None
+
+    async def stream_events(self) -> AsyncIterator[Any]:
+        self.seen_context = request_log.current_call_context()
+        if self._exc is not None:
+            raise self._exc
+        items: tuple[Any, ...] = ()
+        for item in items:
+            yield item
+
+
+async def _run(
+    monkeypatch: pytest.MonkeyPatch,
+    streams: list[_FakeStream],
+    coordinator: AgentCoordinator | None = None,
+) -> Any:
+    monkeypatch.setattr(execution, "_TRANSIENT_MODEL_RETRY_BASE_DELAY_S", 0.0)
+    monkeypatch.setattr(execution, "_TRANSIENT_MODEL_RETRY_MAX_DELAY_S", 0.0)
+    calls = {"n": 0}
+
+    def _fake_run_streamed(*_args: Any, **_kwargs: Any) -> _FakeStream:
+        stream = streams[calls["n"]]
+        calls["n"] += 1
+        return stream
+
+    monkeypatch.setattr(Runner, "run_streamed", _fake_run_streamed)
+    coordinator = coordinator or AgentCoordinator()
+    await coordinator.register("root", "strix", parent_id=None)
+    return await execution._run_cycle(
+        object(),
+        coordinator,
+        "root",
+        input_data="task",
+        run_config=cast("RunConfig", object()),
+        context={},
+        max_turns=5,
+        session=None,
+        interactive=False,
+        event_sink=None,
+        hooks=None,
+    )
+
+
+@pytest.mark.asyncio
+async def test_each_transient_replay_is_stamped_with_its_attempt_number(
+    monkeypatch: pytest.MonkeyPatch,
+) -> None:
+    streams = [
+        _FakeStream(exc=_midstream_api_error()),
+        _FakeStream(exc=_midstream_api_error()),
+        _FakeStream(),
+    ]
+    await _run(monkeypatch, streams)
+    assert [s.seen_context.retry_attempt for s in streams if s.seen_context] == [0, 1, 2]
+
+
+@pytest.mark.asyncio
+async def test_blocked_provider_failure_text_carries_request_id(
+    monkeypatch: pytest.MonkeyPatch,
+) -> None:
+    coordinator = AgentCoordinator()
+    with pytest.raises(PermissionDeniedError):
+        await _run(monkeypatch, [_FakeStream(exc=_blocked_error())], coordinator)
+    assert coordinator.statuses["root"] == "failed"
+    error = coordinator.errors["root"]
+    assert "Output blocked by policy" in error
+    assert error.endswith("[provider request id: req_blocked_hdr]")
+
+
+@pytest.mark.asyncio
+async def test_run_agent_loop_binds_agent_context_and_resets(
+    monkeypatch: pytest.MonkeyPatch,
+) -> None:
+    seen: dict[str, request_log.LlmCallContext] = {}
+
+    async def _fake_loop(**_kwargs: Any) -> None:
+        seen["ctx"] = request_log.current_call_context()
+
+    monkeypatch.setattr(execution, "_run_agent_loop", _fake_loop)
+
+    class _Agent:
+        name = "Recon Agent"
+
+    coordinator = AgentCoordinator()
+    await execution.run_agent_loop(
+        agent=_Agent(),
+        initial_input="task",
+        run_config=cast("RunConfig", object()),
+        context={},
+        max_turns=1,
+        coordinator=coordinator,
+        agent_id="agent-42",
+        interactive=False,
+    )
+    assert seen["ctx"].agent_id == "agent-42"
+    assert seen["ctx"].agent_name == "Recon Agent"
+    assert request_log.current_call_context().agent_id is None

tests/test_models.py

@@ -23,6 +23,7 @@ from strix.config.models import (
     uses_chat_completions_tool_schema,
 )
 from strix.config.settings import Settings
+from strix.llm.request_log import RequestLoggingModel
 
 
 @pytest.mark.parametrize("model_name", RECOMMENDED_MODEL_NAMES)
@@ -172,7 +173,7 @@ def test_routes_through_litellm_matches_the_provider(
         # proves the route is not LiteLLM's.
         assert not litellm
         return
-    while isinstance(model, _NonStreamingModel | _TurnGuardModel):
+    while isinstance(model, _NonStreamingModel | _TurnGuardModel | RequestLoggingModel):
         model = model._inner
     assert isinstance(model, LitellmModel) is litellm
 
@@ -215,6 +216,6 @@ def test_api_type_overrides_the_api_base_route(
         monkeypatch.setenv("STRIX_API_TYPE", api_type)
     configure_sdk_model_defaults(Settings())
     model = StrixProvider().get_model("gpt-5")
-    while isinstance(model, _NonStreamingModel | _TurnGuardModel):
+    while isinstance(model, _NonStreamingModel | _TurnGuardModel | RequestLoggingModel):
         model = model._inner
     assert isinstance(model, expected)