From 0845b26ee61c507487cd8476cfabe8284f59402b Mon Sep 17 00:00:00 2001 From: Tejas Chopra Date: Fri, 24 Jul 2026 20:40:44 -0700 Subject: [PATCH] fix(proxy/cost): record each request's savings exactly once (drop 3 double-counts) (#2545) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Description An audit of savings accounting found three **double-count** bugs: the P0 outcome-funnel refactor centralized cost + PERF recording in `emit_request_outcome`, but three pre-funnel emits were never removed, so they fire a second time on their paths. | Path | Stray emit | + Funnel | Effect | |---|---|---|---| | OpenAI chat direct, non-streaming | explicit `cost_tracker.record_tokens` (`handlers/openai.py` ~4140) | `outcome.py:418` | **2× spend / requests; budget period cost doubled** → `check_budget` can block at half the real spend | | OpenAI **Responses** buffered (Codex HTTP) | explicit `record_tokens` (~5223) | `outcome.py:418` | same | | Codex **WS** turns | explicit `PERF` log line (~7291) | `outcome.py:482` | `headroom perf` **double-counts** saved + requests every WS turn (analyzer sums per line, no dedup by request_id) | All three are pure duplicates: the funnel's `cost_tracker.record_tokens` is a **superset** of the explicit calls' args, and its PERF line uses the **same per-turn deltas** (verified: `7246-7249` == the explicit line's fields). The `/stats` headline was already correct (SavingsTracker fires once, inside the funnel) — only cost/budget and `headroom perf` were affected. Closes # ## Type of Change - [x] Bug fix (non-breaking) ## Changes Made - Remove the explicit `cost_tracker.record_tokens` on the OpenAI chat non-streaming path and the Responses buffered path — keep the `cache_write`/`uncached` computation the funnel needs. - Remove the duplicate WS PERF log line (+ its now-dead `_perf_*` locals and the now-unused `_summarize_transforms` import). - Add a regression test: cost is recorded exactly once on the non-streaming chat path (was 2×). ## Testing - [x] `ruff check` + `ruff format --check` clean; `mypy` clean - [x] Regression + existing tests pass ### Test Output ```text pytest tests/test_openai_chat_turn_hooks.py -q → 6 passed (incl. new double-count regression) pytest tests/test_openai_responses_context_compaction.py → 12 passed pytest tests/test_openai_codex_ws_lifecycle.py + timings + savings_deferral → 38 passed ruff/mypy → clean ``` ## Real Behavior Proof - **Verified by code trace**, not just tests: `grep cost_tracker.record_tokens` across the handler now returns only the funnel call (`outcome.py:418`); the explicit chat/Responses calls are gone. The WS funnel outcome (`openai.py:7246-7249`) feeds `outcome.py:482`'s PERF with the same deltas the deleted line used. - **Not covered:** a related finding (OpenAI-chat *streaming* skips turn hooks entirely, `openai.py:3484 "and not stream"`) is **intentionally deferred** — that gate protects re-drive-requiring hooks (tool-router deferral) which can't run mid-stream; a proper fix needs a per-hook "safe-on-stream" capability flag, out of scope here. ## Checklist - [x] Self-reviewed - [x] No new warnings; tests pass locally - [x] Did **not** edit `CHANGELOG.md` ## Additional Notes This is the "sources" half of the savings audit. A companion PR will fix the "sinks" half — tool-search/deferral savings are never aggregated into `Metrics`, so the session summary, `cost.py` summary, `headroom perf --json/csv`, and the `all_layers` total under-report them. --- headroom/proxy/handlers/openai.py | 84 ++++++---------------------- tests/test_openai_chat_turn_hooks.py | 30 ++++++++++ 2 files changed, 46 insertions(+), 68 deletions(-) diff --git a/headroom/proxy/handlers/openai.py b/headroom/proxy/handlers/openai.py index b80d6a6bc..1ddd047fb 100644 --- a/headroom/proxy/handlers/openai.py +++ b/headroom/proxy/handlers/openai.py @@ -67,7 +67,7 @@ from headroom.proxy.auth_mode import ( should_stamp_codex_client, ) from headroom.proxy.compression_decision import CompressionDecision -from headroom.proxy.cost import _summarize_transforms, header_safe_transforms +from headroom.proxy.cost import header_safe_transforms from headroom.proxy.handlers._debug_dump import _debug_dump_mode, _redact_debug_value from headroom.proxy.image_isolation import run_image_compression_isolated from headroom.proxy.outcome import RequestOutcome @@ -4135,17 +4135,9 @@ class OpenAIHandlerMixin: # OpenAI has no write penalty — uncached = total - cached uncached_input_tokens = max(0, total_input_tokens - cache_read_tokens) - # (record_tokens clamps negative savings to 0 universally — the - # forwarded request is never larger than the original.) - if self.cost_tracker: - self.cost_tracker.record_tokens( - model, - tokens_saved, - optimized_tokens, - cache_read_tokens=cache_read_tokens, - cache_write_tokens=cache_write_tokens, - uncached_tokens=uncached_input_tokens, - ) + # Cost is recorded exactly once by the outcome funnel below + # (_record_request_outcome -> emit_request_outcome -> cost_tracker. + # record_tokens); recording here too double-counted spend + budget. # Memory: handle memory tool calls in OpenAI Chat Completions response. # After executing tools, send a continuation request so the model @@ -5213,27 +5205,14 @@ class OpenAIHandlerMixin: f"[{request_id}] Memory tool handling failed (responses): {e}" ) - if self.cost_tracker: - cache_write_tokens = _infer_openai_cache_write_tokens( - total_input_tokens, - cache_read_tokens, - ) - uncached_input_tokens = max(0, total_input_tokens - cache_read_tokens) - # (record_tokens clamps negative savings to 0 universally.) - self.cost_tracker.record_tokens( - model, - tokens_saved, - total_input_tokens, - cache_read_tokens=cache_read_tokens, - cache_write_tokens=cache_write_tokens, - uncached_tokens=uncached_input_tokens, - ) - else: - cache_write_tokens = _infer_openai_cache_write_tokens( - total_input_tokens, - cache_read_tokens, - ) - uncached_input_tokens = max(0, total_input_tokens - cache_read_tokens) + # Cost is recorded once by the outcome funnel below; here we only + # compute the cache-write / uncached split the funnel needs. + # (Recording here too double-counted spend + budget on this path.) + cache_write_tokens = _infer_openai_cache_write_tokens( + total_input_tokens, + cache_read_tokens, + ) + uncached_input_tokens = max(0, total_input_tokens - cache_read_tokens) effective_optimized_tokens = ( total_input_tokens if total_input_tokens > 0 else optimized_tokens @@ -7266,41 +7245,10 @@ class OpenAIHandlerMixin: ) ) - # Structured PERF log line so ``headroom perf`` - # counts this Codex turn. Pre-P2 this emit was - # missing, which is why Codex traffic showed up - # as ``Requests: 0`` in the perf report even - # under heavy load — the same visibility bug - # class as #327's "Cache write: 0" report. - _perf_input_tokens = max(0, input_delta) - _perf_cache_read = max(0, cache_read_delta) - _perf_cache_write = max(0, cache_write_delta) - _perf_cache_hit_pct = ( - round( - _perf_cache_read / (_perf_cache_read + _perf_cache_write) * 100 - ) - if (_perf_cache_read + _perf_cache_write) > 0 - else 0 - ) - _perf_tok_before = _perf_input_tokens + max(0, saved_delta) - _perf_num_msgs = ( - len(body.get("messages") or body.get("input") or []) - if isinstance(body, dict) - else 0 - ) - logger.info( - f"[{request_id}] PERF " - f"model={model_for_metrics} msgs={_perf_num_msgs} " - f"tok_before={_perf_tok_before} " - f"tok_after={_perf_input_tokens} " - f"tok_saved={max(0, saved_delta)} " - f"cache_read={_perf_cache_read} " - f"cache_write={_perf_cache_write} " - f"cache_hit_pct={_perf_cache_hit_pct} " - f"opt_ms={overhead_delta_ms:.0f} " - f"transforms={_summarize_transforms(transforms_applied)} " - f"client={client or ''}" - ) + # The PERF line for this Codex turn is emitted once by + # the outcome funnel above (emit_request_outcome), using + # the same per-turn deltas — a second emit here duplicated + # every WS turn in `headroom perf` (double saved + requests). ws_recorded_input_tokens_total = ws_input_tokens_total ws_recorded_output_tokens_total = ws_output_tokens_total diff --git a/tests/test_openai_chat_turn_hooks.py b/tests/test_openai_chat_turn_hooks.py index 0d93a0873..3a7a373fa 100644 --- a/tests/test_openai_chat_turn_hooks.py +++ b/tests/test_openai_chat_turn_hooks.py @@ -308,6 +308,36 @@ def test_in_place_message_fold_is_counted(): assert any(int(lg.get("tokens_saved", 0) or 0) > 0 for lg in logs), logs +def test_cost_recorded_once_not_twice_nonstreaming(): + """Regression: the OpenAI chat non-streaming direct path recorded cost TWICE — + an explicit `cost_tracker.record_tokens` plus the outcome funnel's own call — + doubling spend, request count, and budget consumption. It must fire once.""" + + async def fake_retry(method, url, headers, body, *args, **kwargs): + return httpx.Response( + 200, json=_final_response(), headers={"content-type": "application/json"} + ) + + app = create_app(_config()) + with TestClient(app) as client: + client.app.state.proxy._retry_request = fake_retry + ct = client.app.state.proxy.cost_tracker + calls = {"n": 0} + _orig = ct.record_tokens + + def _counting(*a, **k): + calls["n"] += 1 + return _orig(*a, **k) + + ct.record_tokens = _counting + resp = _post( + client, + {"model": "gpt-4o", "messages": [{"role": "user", "content": "hi"}], "stream": False}, + ) + assert resp.status_code == 200, resp.text + assert calls["n"] == 1, f"cost recorded {calls['n']}x — double-count regression" + + def test_direct_path_noop_when_no_hook_registered(): # No hook registered -> byte-identical passthrough, single upstream call. calls = {"n": 0}