headroom/tests/test_outcome_token_scale.py
Tejas Chopra 04e1517ede
fix(telemetry): stop mixing tokenizer scales in RequestOutcome, and fix the overhead framing (#2756)
## Description

Two defects found by reading real beacon payloads, not by inspection.

### 1. `eligible_pct: 120`

A gpt-4o-mini session shipped this:

```json
"tokens": {"original": 10, "attempted": 12, "input": 12, "saved": 0},
"rates":  {"eligible_pct": 120}
```

120% is structurally impossible — you cannot attempt to compress more
than arrived. And nothing had grown.

`original_tokens` is our **local tokenizer** count. `optimized_tokens`
on the OpenAI path carried the **provider's** `usage.prompt_tokens`. Our
estimator undercounted gpt-4o-mini by 2 tokens on a 10-token request,
and every quantity derived from that pair inherited the mismatch:

- `attempted_input_tokens = optimized + saved` → 12, exceeding
`original` → `eligible_pct` 120, `yield_pct` contaminated
- `tokens_inflated` (added in #2708) → reported **2 tokens of phantom
growth**

`optimized_tokens` was dual-purpose by design — *"post-compression bytes
actually forwarded, for `input_tokens` and `tok_after`"*. Billing wants
the provider's count; deltas need the same ruler as `original_tokens`.
Those are different jobs sharing one field.

This is the same class of bug as #2743, on the request path instead of
`/v1/compress`, and it is the exact false positive I flagged as
theoretical when reviewing #2708 — where I measured the margin on a real
722-request log as **exactly zero**, so any provider counting above our
estimator would flip it. gpt-4o-mini does, and it is now in production
telemetry.

### 2. `overhead_pct` was documented as wall-clock, and is not

A 1393-turn session shipped `latency_ms_total: 16396565.8` against
`duration_s: 8904` — **4.55h of latency inside a 2.47h session, 1.84×
over wall clock.**

Both terms are sums over turns, and turns run concurrently (parallel
tool calls, subagents, several clients per proxy), so each sum
over-counts elapsed time. `overhead_pct` is still a meaningful
latency-weighted per-request share, but the comment claiming *"what
fraction of wall-clock did Headroom itself add?"* was wrong, and
shipping `latency_ms_total` beside `duration_s` invites a comparison
that yields nonsense.

Closes #

## Type of Change

- [x] Bug fix (non-breaking change that fixes an issue)

## Changes Made

**Scale split (`outcome.py`, `handlers/openai.py`)**

- `optimized_tokens` is now always the **local** count — same tokenizer
as `original_tokens`, so every delta built from the pair is coherent.
- New optional `provider_input_tokens` carries the provider's own count.
Defaults to `0`, so the other emit sites need no change.
- Cost and volume totals read `provider_input_tokens or
optimized_tokens`, so **billing is unchanged** wherever a provider
reports usage, and falls back exactly as before where it doesn't.
- Removes a band-aid: one of the three OpenAI sites already computed
`effective_original_tokens = max(original_tokens, optimized + saved)`,
inflating `original` upward so `attempted` could not exceed it. That hid
the symptom at one site while the other two shipped the impossible
ratio.

**Overhead framing (`telemetry/session.py`)**

- Corrects the wall-clock comment on `overhead_pct` and states what it
actually is.
- Documents that `latency_ms_total` is a sum of per-request durations,
not elapsed time, and why it can exceed `session.duration_s`.
- Adds `overhead_ms_per_turn` and `latency_ms_per_turn` — unambiguous
under concurrency and comparable across sessions.
- Field names kept for schema-v1 consumers; **additive only**, no schema
bump.

## Testing

- [x] Unit tests pass (new file)
- [x] Linting passes (`ruff check` + `format --check`, pinned 0.15.17)
- [x] New tests added for new functionality
- [x] Manual testing performed

### Test Output

```text
$ uvx ruff@0.15.17 check headroom/proxy/outcome.py headroom/proxy/handlers/openai.py headroom/telemetry/session.py
All checks passed!

$ uvx ruff@0.15.17 format --check <same three>
3 files already formatted

$ pytest tests/test_outcome_token_scale.py -q
5 passed in 0.24s
```

## Real Behavior Proof

- **Environment:** macOS 26.4 arm64, isolated git worktree off
`upstream/main`, throwaway venv (see caveat).

Replayed both reported payloads through the corrected arithmetic:

```text
ENTRY 1 (gpt-4o-mini, the eligible_pct:120 case)
  BEFORE: original=10 (local)  optimized=12 (PROVIDER)  saved=0
          attempted = 12+0 = 12   eligible_pct = 120.0   <- impossible
          tok_inflated = max(0, 12-10) = 2               <- phantom
  AFTER : original=10 (local)  optimized=10 (local)  provider_input=12
          attempted = 10+0 = 10   eligible_pct = 100.0
          tok_inflated = 0
          billed_input = 12  -> cost/cache math unchanged

ENTRY 2 (1393 turns, the overhead case)
  latency_ms_total = 16397s vs duration 8904s -> 1.84x wall clock
  NEW overhead_ms_per_turn = 333.5   latency_ms_per_turn = 11770.7
  wall clock per turn      = 6392.0  -> per-turn latency exceeds it => concurrency
```

Genuine post-compression growth still surfaces: `55,161 → 57,845`
reports `tokens_inflated = 2,684` (pinned as a test), so the fix doesn't
mute what #2708 exists to show.

- **Not tested locally beyond the new file.** The repo venv currently
has no `pytest`, no `ruff`, and no compiled `headroom._core`, so I used
a throwaway venv. The outcome/telemetry suites fail there for missing
deps — `click` (12/12), then `headroom._core` (10/10) — with **zero
assertion failures**, and an **identical failure set on this branch and
on clean `upstream/main`** in the same env. So they are
environment-only, not regressions. CI on this PR is the authoritative
signal for the full suite.
- Unrelated: `Wrap E2E / docker-wrap-e2e` is currently red on `main`
from a quay.io CDN `tls: internal error` pulling the manylinux base
image — infrastructure, transient, and green on the three prior runs.

## 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] My changes generate no new warnings
- [x] I have added tests that prove my fix is effective
- [x] I did **not** edit `CHANGELOG.md`

## Follow-ups not in this PR

- **`cache_write` and `uncached` double-count** on inferred-cache
providers. The same beacon entry shows `input: 12, cache_read: 0,
cache_write: 12, uncached: 12` — both fields describe the identical 12
tokens, because `_infer_openai_cache_write_tokens` and
`uncached_input_tokens` are computed the same way (`input −
cache_read`). Any consumer summing them gets 2×. The payload also
carries no `cache_inferred` flag, so a reader can't distinguish an
inferred write from an Anthropic-reported one.
- **No skip reason for compression itself.** That entry records
`memory_skip:no_handler` but nothing explains why compression didn't
fire; "below the size floor" and "compressor failed" are
indistinguishable — the same ambiguity #2708 just removed for inflation.
- **`eligible_pct` can still legitimately exceed 100** when a request
genuinely grows after compression (memory injection, proactive
expansion), since `attempted = optimized + saved` uses the forwarded
size. Left alone deliberately: clamping would hide real inflation, and
`tokens_inflated` now expresses it properly.

🤖 Generated with [Claude Code](https://claude.com/claude-code)
2026-08-04 13:02:47 -07:00

97 lines
3.6 KiB
Python

"""``original_tokens`` and ``optimized_tokens`` must share a tokenizer scale.
Every derived quantity is a delta between the two — ``tokens_saved``,
``tokens_inflated``, ``attempted_input_tokens``, and the beacon's
``eligible_pct`` / ``yield_pct``. Handlers used to pass the provider's
``usage.prompt_tokens`` as ``optimized_tokens`` because it also fed billing,
which put a provider count against a locally-estimated ``original_tokens``.
A real beacon payload from a gpt-4o-mini session, where our estimator
undercounted by 2 tokens on a 10-token request:
"tokens": {"original": 10, "attempted": 12, "input": 12, "saved": 0}
"rates": {"eligible_pct": 120}
120% is structurally impossible — you cannot attempt to compress more than
arrived. The same mismatch also produces a phantom ``tok_inflated``.
"""
from __future__ import annotations
from headroom.proxy.outcome import RequestOutcome
# The exact numbers from the reported beacon entry.
_LOCAL_ORIGINAL = 10
_LOCAL_OPTIMIZED = 10 # nothing compressed: a 10-token request is below every floor
_PROVIDER_COUNT = 12 # gpt-4o-mini's own prompt_tokens — a different ruler
def _outcome(**kw) -> RequestOutcome:
base: dict = {
"request_id": "r1",
"provider": "openai",
"model": "gpt-4o-mini",
"original_tokens": _LOCAL_ORIGINAL,
"optimized_tokens": _LOCAL_OPTIMIZED,
"output_tokens": 5,
"tokens_saved": 0,
"attempted_input_tokens": _LOCAL_OPTIMIZED,
}
base.update(kw)
return RequestOutcome(**base)
def test_provider_count_does_not_contaminate_the_local_pair() -> None:
"""The provider's number rides alongside instead of replacing tok_after."""
o = _outcome(provider_input_tokens=_PROVIDER_COUNT)
assert o.original_tokens == _LOCAL_ORIGINAL
assert o.optimized_tokens == _LOCAL_OPTIMIZED
assert o.provider_input_tokens == _PROVIDER_COUNT
def test_no_phantom_inflation_when_the_provider_counts_higher() -> None:
"""The regression: provider 12 vs local 10 reported 2 tokens of growth."""
fixed = _outcome(provider_input_tokens=_PROVIDER_COUNT)
assert fixed.tokens_inflated == 0
# What the old shape produced — optimized carrying the provider count.
contaminated = _outcome(optimized_tokens=_PROVIDER_COUNT)
assert contaminated.tokens_inflated == 2, (
"guard is inverted; this asserts the OLD behaviour to document the bug"
)
def test_attempted_cannot_exceed_original_on_a_no_op_turn() -> None:
"""`eligible_pct = attempted / original` must stay <= 100 here.
attempted is built as optimized + saved, so once optimized is local the
ratio is bounded by original for any turn that did not grow.
"""
o = _outcome(
provider_input_tokens=_PROVIDER_COUNT,
attempted_input_tokens=_LOCAL_OPTIMIZED + 0,
)
assert o.attempted_input_tokens <= o.original_tokens
assert 100 * o.attempted_input_tokens / o.original_tokens == 100.0
def test_provider_count_is_optional_and_defaults_to_zero() -> None:
"""18 pre-existing emit sites pass nothing; billing must fall back."""
o = _outcome()
assert o.provider_input_tokens == 0
def test_real_inflation_is_still_reported() -> None:
"""Fixing the scale must not mute genuine post-compression growth.
Same tokenizer both sides, request forwarded larger (memory injection /
proactive expansion) — that is real and must survive.
"""
o = _outcome(
original_tokens=55_161,
optimized_tokens=57_845,
provider_input_tokens=58_000,
tokens_saved=0,
)
assert o.tokens_inflated == 2_684