fix(proxy): give each Codex /v1/responses WS turn a unique request_id (#2164)

## Description After any Codex traffic, the dashboard "Recent Requests" table goes blank — including the unrelated Anthropic/Claude rows — even though the proxy is actively handling and compressing Codex `/v1/responses` WebSocket turns and aggregate counters keep moving. The feed isn't stale; it is being wiped client-side. Root cause: the Codex WebSocket handler `OpenAIHandlerMixin.handle_openai_responses_ws` (`headroom/proxy/handlers/openai.py`) mints a single `request_id` per WebSocket **session** (`_next_request_id()` near the top of the handler) and reuses it for every per-turn `RequestOutcome` in `_record_ws_response_metrics`, the session-residual outcome, and the session-summary `RequestLog`. Those all flow through `emit_request_outcome` (`headroom/proxy/outcome.py`), which writes a `RequestLog` per outcome into the request logger that backs `/stats.recent_requests` and `/transformations/feed` — so one session with N turns produces N+ feed rows sharing one `request_id`. The dashboard renders that feed with `<template x-for="req in (stats.recent_requests || [])" :key="req.request_id">` (`headroom/dashboard/templates/dashboard.html:1298`); Alpine requires unique `:key`s, so duplicate ids abort the entire `x-for` render and blank the whole table. Anthropic/HTTP requests each get a unique incrementing id from `_next_request_id()` and are unaffected — which is why only Codex traffic triggers the blanking. This PR gives each Codex WS feed emission a fresh unique id from the same authoritative `_next_request_id()` counter (per-turn, residual, and summary sites), restoring the "one unique id per feed row" invariant that Anthropic already satisfies. With unique ids the Alpine `:key`s no longer collide and the table renders Codex turns like any other request. Feed-row counts, per-turn token and savings values, ordering, and per-session metrics/cost bookkeeping are unchanged; the `[{session request_id}]` log prefixes still use the session id so a session's log lines stay greppable together. Scope: this is the backend root-cause fix. Hardening the dashboard `:key` against duplicate/`null` keys is a separate render-robustness change and is deliberately left to a follow-up (`Refs #310`); once the backend guarantees unique ids, the collision that blanks the table is gone. The comment's secondary `savings_percent.toFixed(0)` concern is already resolved on `main` (the row uses `formatOptionalPercent`). Closes #310. The concrete duplicate-`request_id` diagnosis and the live `/stats?cached=1` capture came from @sphynxttl's comment on the issue. ## Type of Change - [x] Bug fix (non-breaking change that fixes an issue) - [ ] New feature (non-breaking change that adds functionality) - [ ] Breaking change (fix or feature that would cause existing functionality to change) - [ ] Documentation update - [ ] Performance improvement - [ ] Code refactoring (no functional changes) ## Changes Made - `headroom/proxy/handlers/openai.py`: in `handle_openai_responses_ws`, mint a fresh `request_id` from `_next_request_id()` at each request-feed emission — the per-turn `RequestOutcome` in `_record_ws_response_metrics`, the session-residual `RequestOutcome`, and the session-summary `RequestLog` — instead of reusing the one session id. The per-turn id is minted after the existing all-deltas-≤0 early-return, so no-op turns still emit nothing. The `[{request_id}]` PERF/log prefixes keep the session id for operator correlation. - `tests/test_openai_codex_ws_lifecycle.py`: new tests driving a two-turn Codex WS session through the `_FakeWebSocket`/`_FakeUpstream` harness with a capturing request logger and an incrementing `_next_request_id`, asserting distinct per-row `request_id`s without relying on local repro artifacts, unchanged per-turn token/savings values, no phantom row for a no-op turn, and session-prefixed logs. - `CHANGELOG.md`: `Unreleased → Fixed` entry. ## Testing - [x] Unit tests pass (`uv run pytest tests/test_openai_codex_ws_lifecycle.py`) - [x] Linting passes (`uv run ruff check .`) - [ ] Type checking passes (`uv run mypy headroom`) - [x] New tests added for new functionality when applicable - [x] Manual testing performed ### Test Output ```text $ uv run pytest tests/test_openai_codex_ws_lifecycle.py -q ............................. [100%] 29 passed in 1.69s $ uv run ruff check . All checks passed! ``` ## Real Behavior Proof - Environment: Windows 11, Python 3.12 via `uv`, no live provider — the WS handler is exercised through the in-process `_FakeWebSocket`/`_FakeUpstream` harness that mirrors the production wire shape. - Exact command / steps: ran `uv run pytest tests/test_openai_codex_ws_lifecycle.py::test_ws_multi_turn_request_ids_are_unique -q` on this branch and `uv run pytest tests/test_openai_codex_ws_lifecycle.py -q` for the focused file; on `origin/main`, the new regression node is absent and the WS emit sites still use `request_id=request_id` in `headroom/proxy/handlers/openai.py`. - Observed result: a two-turn Codex WS session now yields `recent_requests` rows with unique `request_id`s, so the dashboard's Alpine `:key` no longer collides; token/savings values and row counts are unchanged; a no-op turn still emits no row. On `origin/main`, the handler still reuses the session `request_id` at the WS feed emit sites. - Not tested: live dashboard browser render of the fixed feed. ## Review Readiness - [x] I have performed a self-review - [x] This PR is ready for human review ## Checklist - [x] My code follows the project's style guidelines - [x] I have performed a self-review of my code - [x] I have commented my code, particularly in hard-to-understand areas - [x] I have made corresponding changes to the documentation - [x] My changes generate no new warnings - [x] I have added tests that prove my fix is effective or that my feature works - [x] New and existing unit tests pass locally with my changes - [x] I have updated the CHANGELOG.md if applicable ## Additional Notes - Type checking (`mypy`) left unchecked: not run in this pass; the change only swaps the source of an existing `request_id` string field. - Non-goal (out of scope): hardening the dashboard `x-for` `:key` against duplicate/`null` keys is a separate render-robustness fix for a follow-up (`Refs #310`); this PR removes the source of the duplicates. The comment's `savings_percent.toFixed(0)` concern is already fixed on `main` (`formatOptionalPercent`). - Prior art: an earlier change (issue #399 era) added the per-turn Codex WS `RequestLog`/PERF emission but reused the session id; this PR makes those ids unique.
2026-08-12 00:37:08 -04:00
parent a4bd2e62a5
commit d02df10758
2 changed files with 144 additions and 2 deletions
@@ -7779,7 +7779,8 @@ class OpenAIHandlerMixin:
                            # as HTTP turns.
                            await self._record_request_outcome(
                                RequestOutcome(
-                                    request_id=request_id,
+                                    # Per-emission ids keep dashboard request-log keys unique.
+                                    request_id=await self._next_request_id(),
                                    provider="openai",
                                    model=model_for_metrics,
                                    original_tokens=max(0, input_delta) + max(0, saved_delta),
@@ -8354,7 +8355,8 @@ class OpenAIHandlerMixin:
                    ws_messages_for_log.append({"role": "user", "content": ws_input_for_log})
                await self._record_request_outcome(
                    RequestOutcome(
-                        request_id=request_id,
+                        # Per-emission ids keep dashboard request-log keys unique.
+                        request_id=await self._next_request_id(),
                        provider="openai",
                        model=model_name,
                        original_tokens=residual_input_tokens + residual_tokens_saved,
@@ -114,6 +114,14 @@ class _DummyOpenAIHandler(OpenAIHandlerMixin):
        await emit_request_outcome(self, outcome)


+class _CapturingLogger:
+    def __init__(self) -> None:
+        self.entries = []
+
+    def log(self, entry) -> None:  # noqa: ANN001
+        self.entries.append(entry)
+
+
 class _FakeWebSocketDisconnect(Exception):
    """Mirrors the ``WebSocketDisconnect`` type-name check in the handler.

@@ -894,6 +902,138 @@ async def test_ws_session_metrics_include_dashboard_performance_timings():
    )


+@pytest.mark.asyncio
+async def test_ws_multi_turn_request_ids_are_unique():
+    upstream_events = [
+        json.dumps({"type": "response.created", "response": {"id": "r_1"}}),
+        json.dumps(
+            {
+                "type": "response.completed",
+                "response": {
+                    "id": "r_1",
+                    "usage": {
+                        "input_tokens": 100,
+                        "input_tokens_details": {"cached_tokens": 75},
+                        "output_tokens": 12,
+                    },
+                },
+            }
+        ),
+        json.dumps({"type": "response.created", "response": {"id": "r_2"}}),
+        json.dumps(
+            {
+                "type": "response.completed",
+                "response": {
+                    "id": "r_2",
+                    "usage": {
+                        "input_tokens": 160,
+                        "input_tokens_details": {"cached_tokens": 120},
+                        "output_tokens": 20,
+                    },
+                },
+            }
+        ),
+    ]
+    upstream = _FakeUpstream(upstream_events)
+    fake_ws_mod = _make_fake_websockets_module(upstream)
+
+    client_ws = _FakeWebSocket(frames=[_first_frame()])
+    handler = _DummyOpenAIHandler()
+    handler.logger = _CapturingLogger()
+
+    counter = 0
+
+    async def _next_request_id() -> str:
+        nonlocal counter
+        counter += 1
+        return f"req-ws-{counter}"
+
+    handler._next_request_id = _next_request_id  # type: ignore[method-assign]
+
+    with patch.dict(sys.modules, {"websockets": fake_ws_mod}):
+        await handler.handle_openai_responses_ws(client_ws)
+
+    logged = handler.logger.entries
+    assert len(logged) == 2
+    request_ids = [entry.request_id for entry in logged]
+    assert len(set(request_ids)) == len(request_ids)
+    assert [entry.input_tokens_optimized for entry in logged] == [100, 160]
+    assert [entry.output_tokens for entry in logged] == [12, 20]
+
+
+@pytest.mark.asyncio
+async def test_ws_no_delta_turn_emits_no_extra_request_log():
+    upstream_events = [
+        json.dumps({"type": "response.created", "response": {"id": "r_1"}}),
+        json.dumps({"type": "response.completed", "response": {"id": "r_1"}}),
+    ]
+    upstream = _FakeUpstream(upstream_events)
+    fake_ws_mod = _make_fake_websockets_module(upstream)
+
+    client_ws = _FakeWebSocket(frames=[_first_frame()])
+    handler = _DummyOpenAIHandler()
+    handler.logger = _CapturingLogger()
+
+    counter = 0
+
+    async def _next_request_id() -> str:
+        nonlocal counter
+        counter += 1
+        return f"req-ws-{counter}"
+
+    handler._next_request_id = _next_request_id  # type: ignore[method-assign]
+
+    with patch.dict(sys.modules, {"websockets": fake_ws_mod}):
+        await handler.handle_openai_responses_ws(client_ws)
+
+    assert len(handler.logger.entries) == 1
+    assert all(entry.input_tokens_optimized == 0 for entry in handler.logger.entries)
+    assert all(entry.output_tokens == 0 for entry in handler.logger.entries)
+
+
+@pytest.mark.asyncio
+async def test_ws_session_log_prefix_uses_session_id(caplog: pytest.LogCaptureFixture):
+    upstream_events = [
+        json.dumps({"type": "response.created", "response": {"id": "r_1"}}),
+        json.dumps(
+            {
+                "type": "response.completed",
+                "response": {
+                    "id": "r_1",
+                    "usage": {
+                        "input_tokens": 100,
+                        "input_tokens_details": {"cached_tokens": 75},
+                        "output_tokens": 12,
+                    },
+                },
+            }
+        ),
+    ]
+    upstream = _FakeUpstream(upstream_events)
+    fake_ws_mod = _make_fake_websockets_module(upstream)
+
+    client_ws = _FakeWebSocket(frames=[_first_frame()])
+    handler = _DummyOpenAIHandler()
+    handler.logger = _CapturingLogger()
+
+    counter = 0
+
+    async def _next_request_id() -> str:
+        nonlocal counter
+        counter += 1
+        return f"req-ws-{counter}"
+
+    handler._next_request_id = _next_request_id  # type: ignore[method-assign]
+    caplog.set_level(logging.INFO, logger="headroom.proxy")
+
+    with patch.dict(sys.modules, {"websockets": fake_ws_mod}):
+        await handler.handle_openai_responses_ws(client_ws)
+
+    assert handler.logger.entries
+    assert handler.logger.entries[0].request_id != "req-ws-1"
+    assert "[req-ws-1] PERF" in caplog.text
+
+
@pytest.mark.asyncio
 async def test_ws_opt_in_flattens_response_create_for_openai_compatible_upstream(monkeypatch):
    """Some OpenAI-compatible WS gateways expect top-level response.create payloads."""