mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
## 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)
97 lines
3.6 KiB
Python
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
|