fix(proxy): tell an unreadable usage block apart from a provider that reported none, and record the shape once

[amiddavid]

Closes #200. Independent of #204 (#190) — both branch from main.

The defect

parseUsage returning ok=false meant five different things and nothing distinguished them. Two are benign. The rest mean token accounting is offline, on a request that otherwise looks perfect: a healthy 200, correct savings counters, correct latency, correct everything else, and fresh_input_tokens / cache_read_tokens / cache_write_tokens quietly at 0.

It ran that way for 4,015 of 4,015 requests in one benchmark iteration and was found two iterations later, in a post-mortem chasing a different question. The usage was in the body — LOCA priced those requests from it — so the proxy read a response that carried usage and found nothing in it.

What is classified, and why it is not one counter

usageMiss names all five, and the reason rides on the cg.request log line as usage_miss so a benign miss is legible without being alertable:

usage_miss	Meaning	Counted	Remedy
absent	no usage block anywhere we know to look	—	nothing
all_zero	recognised, every tier zero	—	nothing; legitimate
no_body	empty response	—	nothing
unparsed_dialect	a block is there, no recognised spelling read it	usage_unparsed	add the dialect
unreadable_body	the bytes were not a whole document, so the block was hidden	usage_unreadable	raise sniffMax / buffer

The last two get counters, and separate ones, because their remedies are opposite: one means add the dialect the provider is speaking, the other means the bytes examined were not a whole document and the fix is upstream of any parser. One counter would have said "accounting is offline" without saying which half of the stack to look at — and putting either in with the benign cases is this issue's own defect, restated. Same argument as expand/unresolved.go's malformed/missing split and #188's stash_refused/stash_missing.

A fourth cause the issue did not list

sniffer.bytes returns head + "\n" + tail once a response passes sniffMax (64 KiB) each way, and that is not valid JSON. Reported as an unrecognised dialect it would send someone hunting for a field name that is not missing.

It is narrower than "the response was truncated", and the code and both test tables say so: gjson scans rather than walking a tree, so a spliced document whose top-level usage survived is read correctly and never reaches this classification. It fires only when the splice actually hid the block — the only case where anything is lost. Worth flagging because the obvious fixture (a malformed body) is read correctly and would have made the test vacuous. It did, on the first run; both tables now carry the note and the shape that genuinely hides the block.

The shape record, which is the part that unblocks the dialect fix

On the first unaccounted response per process, cg.usage_unaccounted logs the response's key names: the top-level keys, where a usage block was found, and the key names inside it. No values, and never the body.

That turns "usage_reported is false" into "the provider is sending camelCase", and it needs no captured body, no instrumented capture hop and no extra request — so it works from any deployment that hits the gap rather than only from the one rig with a capture hop in the path. A body dump on this workload writes kilobytes of transcript content to disk per response; this record cannot, by construction, which is why it can ship on by default at DEBUG.

Once per process because a run with this gap has it on every request — 4,015 of 4,015 above — so a per-response record is a log line per request.

Deliberately not here: the dialects themselves

Adding the camelCase or nested spellings needs a real response body to get the field names right. Guessing between cacheWriteInputTokens and cacheCreationInputTokens produces a parser that looks correct and reads zero — this issue's failure reproduced in the code meant to fix it. The nested paths here are probed for existence only and never read, which is what keeps the classification dialect-agnostic.

Verification

gofmt -l . clean, go vet ./... clean, go test ./... all packages pass, go test -race clean over proxy and metrics (Go 1.26.4, eval box).

Four new tests, all revert-verified against a mutation collapsing the classification back to one undifferentiated miss:

Test	Reverted →
TestEveryUsageOutcomeIsDistinguishable — 12 shapes, one per outcome per transport, incl. Bedrock camelCase and nested response.usage	"classified absent, want unparsed_dialect"
TestOnlyAnAccountingOutageMovesTheUsageCounters — the rule itself: alertable cases move their own counter, all four benign shapes move neither	"usage_unparsed moved by 0, want 1"
TestTheShapeRecordNamesTheDialectAndCarriesNoContent — answers the dialect question, once per process, no content and no values	the record is absent entirely
TestTheShapeRecordSaysWhenTheBytesWereNotAWholeDocument — valid_json=false, so a spliced window is not misread as a field-name gap	no record

The no-content assertion was verified against a second mutation, because "the record does not contain this string" passes trivially when there is no record, and would also pass on a record that logged the body under a different key. With usageShapeAttrs changed to log the body it fails on its own subject: "the shape record leaked response CONTENT, which is the one thing it must never do".

Two contract tests updated as designed: TestStatsShapeIsUnchanged (both fields added to the reviewed contract) and TestEverySnapshotFieldIsExportedOrExempt — the latter listed in notExportedWhy rather than read off s, for the reason that map's own preamble gives: the /stats handler fills these after renderMetrics takes its snapshot, so a promLine off s would export a permanent 0 while passing the test, which is precisely the silent-zero failure this change exists to report.

What this unblocks

One request through a proxy on this branch produces the key-shape record, which answers the camelCase question that #199 and the parseUsage dialect fix are both waiting on — and #201's cost claim, which is unmeasurable while the three cache-token fields read 0. Per the validation session, no captured body or usage shape exists anywhere today (the capture hop's flap log records request metadata only; LOCA's 11 MB log has none of the twelve candidate spellings), so this is the cheapest available instrument.

🤖 Generated with Claude Code

[amiddavid]

Follow-up in 2da9bd5, from the coref validation session's correction — comment and docs only, no behaviour change.

unreadable_body is reachable only from the sniffed path (Handler.stream, taken when neither proxy-injected tool is advertised), because that is the only place usage is read from a bounded window rather than the whole body. With either tool advertised — which inject_expand: always guarantees from the first turn — proxy.go's default: branch reads the body whole and the window cannot apply.

Worth recording because the call-site distinction has now misled two sessions in opposite directions. I floated the spliced window as a competing explanation for iteration 024's 4,015-of-4,015; it cannot be one, since those runs set INJECT_EXPAND=always so advertised was true (proxy.go:1348) and the full body was read at :1552. The #188 reviewer hit the mirror image — a parseUsage test that passed on the stream branch while the traffic took the buffered one. Same error both times: treating the two responseUsage call sites as interchangeable when the bytes reaching them are not.

Neither counter changes, and valid_json in the shape record already settles which case a reader has without knowing their path. This only stops them forming the wrong hypothesis first.

Scoping consequence for #199 and the dialect fix: for traffic that advertises either injected tool — the common case — camelCase-or-nested is the only remaining explanation for a miss, so the shape record's usage_keys is the whole answer in one request.

[amiddavid]

The classification is the right shape and the unreadable_body cause you added is a real one — the narrowness argument (gjson scans, so a splice that leaves the top-level usage visible is read correctly) checks out, and the fixture note is worth keeping.

But I think the change is currently net-negative on the streamed transport, and the run it is meant to unblock will probably produce no shape record at all. Two findings, both verified by running probes against this branch on the eval box rather than by reading:

=== proxy, branch 2da9bd5, go test -run TestReviewProbe
openai stream chunk with usage:null  -> why=unparsed_dialect ok=false unparsed+1
sse recognised all-zero              -> why=unparsed_dialect ok=false unparsed+1
sse usage empty object               -> why=unparsed_dialect ok=false unparsed+1
spliced window first, camelCase next -> NO RECORD (the once was consumed)

1. Three benign streamed shapes move usage_unparsed, the counter whose whole meaning is "add the dialect". One of them — "usage": null — is what the OpenAI dialect puts in every streamed chunk unless stream_options.include_usage is set, so on the openai_upstream route this counter is driven by healthy traffic.
2. Because the shape record is one sync.Once for both alertable classes, the first of those benign streams (or any unreadable_body) consumes it, and the camelCase response that follows logs nothing. The datum #199 and the dialect fix are waiting on is the first thing this loses.

(1) also explains why review did not catch it: TestOnlyAnAccountingOutageMovesTheUsageCounters has no SSE row, so it asserts the rule on the one transport where the rule holds. Details inline. Everything else — the counter split, the no-content assertion and its second mutation, valid_json in the record, 2da9bd5's call-site scoping — I have no objection to.

[amiddavid]

sawBlock makes three benign streamed shapes alertable, and one of them is the OpenAI dialect's normal output.

The comment concedes "a stream whose only usage block is all-zero over-reports by one". It is worse than one, because gjson.Result.Exists() is t.Type != Null || len(t.Raw) != 0 — a JSON null has Raw == "null", so "usage": null sets sawBlock, parseUsage falls to its default: branch, and the stream is classified unparsed_dialect.

OpenAI-dialect streaming sends "usage": null on every chunk unless the caller sets stream_options.include_usage, and this proxy routes those through Handler.stream → responseUsageWhy (proxy.go:1489, the non-Anthropic case isSSE:). So on the openai_upstream route, usage_unparsed — documented as "add the dialect the provider is speaking" — is incremented by every healthy streamed response. Verified on this branch:

openai stream chunk with usage:null  -> why=unparsed_dialect ok=false unparsed+1 unreadable+0
sse recognised all-zero              -> why=unparsed_dialect ok=false unparsed+1 unreadable+0
sse usage empty object               -> why=unparsed_dialect ok=false unparsed+1 unreadable+0

That is this issue's own defect with the sign flipped: instead of an outage reading as healthy, healthy traffic reads as an outage — and it costs the same thing, an operator who cannot tell from the counter which they have.

The cheapest fix that keeps the coarseness you want: only set sawBlock when the block is a non-empty object (u.IsObject() && len(u.Get("@keys").Array()) > 0, or just u.IsObject() plus a Raw != "{}" check), and treat "every block seen was recognised and all-zero" as usageMissZero. parseUsage already distinguishes those two internally — parseUsageWhy per event would give you the exact reason without a second pass, which is the same asymmetry the split at :118 was introduced for.

[amiddavid]

This table is transport-blind, which is why the counter rule it names is violated on the stream path.

Every row is application/json. TestEveryUsageOutcomeIsDistinguishable above deliberately covers "one per outcome per transport" and is the stronger table for it — but it does not assert on the counters, and this one does. So the rule the counter must not be moved by a benign outcome is asserted only where parseUsageWhy runs, and never where parseSSEUsageWhy does, which is the half that breaks it (see the note at usage.go:247).

Two rows would have caught it and are worth adding whichever way you fix the classifier:

{"a streamed all-zero block", "text/event-stream",
    "data: {\"type\":\"message_delta\",\"usage\":{\"output_tokens\":0}}\n", 0, 0},
{"a streamed null usage field", "text/event-stream",
    "data: {\"choices\":[{\"delta\":{}}],\"usage\":null}\n", 0, 0},

And TestEveryUsageOutcomeIsDistinguishable has no usageMissZero row for SSE either, so that value is currently unreachable-by-test on the transport where it is misclassified. Both tables want the same discipline the first one already states: one row per outcome per transport, with the transport axis complete rather than sampled.

[amiddavid]

One Once for two classes means the first alertable response wins, and it is unlikely to be the one that answers the question.

The record is the part of this change that unblocks #199 and the dialect fix. It is gated on a single process-wide sync.Once shared by unparsed_dialect and unreadable_body, so whichever fires first consumes it. Verified on this branch — a spliced window, then the camelCase response:

spliced window first, camelCase next -> NO RECORD: the once was consumed by the
                                        unreadable_body, so the camelCase question
                                        is unanswered

Combine that with the sawBlock finding at :247 and the odds get worse: on any deployment carrying OpenAI-dialect streamed traffic, a benign "usage": null chunk is alertable and will almost certainly be the first alertable response in the process, so the record is spent before the interesting response ever arrives. The run this ships for then produces the counters and no shape.

One Once per usageMiss value is the minimum. Better, and still bounded: key it on the record's own identity — usage_at plus the sorted usage_keys — in a small sync.Map capped at, say, 8 distinct shapes. That is one line per distinct dialect rather than one per process, which is what the diagnostic is actually for (a multi-provider deployment has more than one answer), and it still cannot write a line per request: a run with the gap on all 4,015 requests has one shape.

Also: ResetUsageShapeRecordForTest assigning usageShapeOnce = sync.Once{} is a plain data race against a concurrent Do. Harmless as used today (both callers are serial tests), but -race will find it the moment someone marks one of those tests t.Parallel(). Whatever replaces the Once should get a mutex-guarded reset.

[amiddavid]

Across expand rounds, usageWhy is last-write-wins while usageOK is sticky-true, so the log line can contradict itself.

usageOK is only ever set to true (:1560, :1492, :1544) and never reset; usageWhy is assigned unconditionally on every round. A request whose round 1 parsed usage and whose round 2 (post-expand continuation) carried none logs usage_reported=true usage_miss=absent. The reverse pairing is reachable too. Since the whole point of usage_miss is to let someone read usage_reported=false and know which of the five it was, a pair that can disagree undoes some of that.

Smallest fix: keep the reason of the round that left the request unaccounted — usageWhy = why in the ok branch, and if !usageOK { usageWhy = why } in the else.

Separately, worth a sentence in UsageGaps' doc: these count responses, not requests, so a multi-round request can move them more than once. The docstring already says "how many responses", so it is consistent — but docs/reference/routes.md invites comparison against a request count, and the 4,015-of-4,015 framing in the PR body is a per-request figure.

[amiddavid]

Minor, and possibly deliberate: the nestedUsagePaths probe runs before ValidBytes, so a spliced window that hid the top-level usage but left, say, response.usage scannable is classified unparsed_dialect rather than unreadable_body. I think the current order is defensible — a block that was found really does mean a dialect is missing, whatever else is wrong with the bytes — but it is the one ordering that can produce the mis-signal the paragraph above says it exists to prevent, and valid_json in the record is what saves the reader. One clause saying the precedence is chosen (found-block wins over unparseable-document) would keep the next person from "fixing" it the other way.

[amiddavid]

Re-verified all five on the eval box against a41843c. Every one is fixed, and the null-usage finding is fixed more broadly than I reported it — you were right that parseUsageWhy's top-level and nested probes had the same defect, so five rows rather than three:

json usage null            -> why=absent          unparsed+0
json usage empty obj       -> why=absent          unparsed+0
sse usage null per chunk   -> why=absent          unparsed+0
sse all-zero               -> why=all_zero        unparsed+0   (its own value, not the coarse one)
sse empty obj              -> why=absent          unparsed+0
sse camelCase              -> why=unparsed_dialect unparsed+1

worst with the severity-ordered constants is a better answer than the coarsening your original comment conceded, and stating that the order is part of the type is the right way to keep it. noteUsageMiss, usageShapeKey on usage_at + sorted usage_keys (and not the top-level keys — agreed, and for the reason you give), the mutex-guarded reset, and the RESPONSES-not-requests note all read correctly to me.

Two things still wrong, both in the record rather than the classification — so the counters are now right and the diagnostic they point at can still come out empty. Neither is large; the first is the one I would fix before merge, the second is a word.

On #204 I have nothing further — separate review there. And thank you for the bound on the four no-replay offloaders: a skipped component splices nothing, so nothing dangles while the skip lasts. That is the right narrowing and it is a better statement of the exposure than mine was.

[amiddavid]

usageShapeAttrs still uses Exists() where the classifier now uses usagePresent, so the record can name the wrong location.

The loop here is if u := gjson.GetBytes(doc, p); u.Exists(). parseUsageWhy was changed to usagePresent for exactly this reason, and the two now disagree: a body with a top-level "usage": null and a real nested block is classified from the nested block, then described from the null one. Verified on this branch with {"usage":null,"response":{"usage":{"inputTokens":10,"cacheReadInputTokens":9}}}:

why=unparsed_dialect
cg.usage_unaccounted ... top_level_keys="[response usage]" usage_at=usage usage_keys=[]

usage_at=usage usage_keys=[] — it points at the null and reports no field names, while response.usage held the answer. It also keys the shape as usage|, so a second provider with a genuinely empty top-level usage collides with it.

One word: usagePresent(u) instead of u.Exists(). Worth doing even though the shape is speculative, because the whole reason usagePresent exists is that Exists() on a usage block does not mean what it looks like — leaving one caller on the old predicate is how that comes back.

[amiddavid]

The classifier scans every event; the recorder reads only the last one. An unrecognised dialect in a non-terminal event produces a record that names nothing.

parseSSEUsageWhy walks all data: lines and keeps the worst reason any of them produced. usageShapeAttrs builds its record from lastSSEPayload(body) — a single event. When the block that drove the classification was not in the terminal event, the record describes the wrong object. Verified on this branch, a stream whose message_start carries camelCase and whose last event is message_stop:

why=unparsed_dialect
cg.usage_unaccounted sse=true bytes=255 valid_json=true top_level_keys=[type]
GAP: the record does not name the dialect that was actually found

No usage_at, no usage_keys, and top_level_keys=[type] from message_stop. Two consequences: the counter fires with nothing to act on, and via usageShapeKey this takes the "|" slot — the stable key you reserved for "no block found at all" — so the shape budget is spent on a record that says nothing.

This is the Anthropic-family transport shape, where the input-token block lives in message_start. Since the motivating provider is aws/claude-* through Bedrock, a streamed instance of exactly the gap this change exists to name can land here.

The fix that keeps the two in agreement is to record the event that produced the classification rather than the last one: have parseSSEUsageWhy also return the raw payload of the event that set worst, and pass that to usageShapeAttrs instead of calling lastSSEPayload. That also removes the current duplication, where the transport is parsed once to classify and again to describe. A cheaper version — scan events backwards for the first one containing a usagePresent block, falling back to the last — fixes the record but leaves the two walks able to disagree.

[amiddavid]

Both fixed, verified from the record's own text on the eval box against 7a70d76:

sse dialect in a non-terminal event:
  cg.usage_unaccounted sse=true bytes=125 valid_json=true
    top_level_keys="[message type]" usage_at=message.usage
    usage_keys="[cacheReadInputTokens inputTokens]"

null top-level beside a real nested block:
  cg.usage_unaccounted sse=false bytes=71 valid_json=true
    top_level_keys="[response usage]" usage_at=response.usage
    usage_keys="[inputTokens outputTokens]"

And every shape from all three rounds re-checked for regressions — the five null/empty/all-zero cases still benign with no counter movement, camelCase still unparsed_dialect, both healthy shapes still parsed. Keeping bytes as the whole response while narrowing only the described document is the right split; deleting lastSSEPayload rather than leaving it unused is what makes the one-walk property hold. No objection left on this branch — LGTM (this account cannot file a formal approval on its own PR).

One last observation below. It is a residual gap rather than a defect in this change, it is non-blocking, and I would be equally happy with a comment as with code — I am raising it because it is #200's own shape on the one transport that is not covered, and because the signal it needs already exists.

I have nothing further on #204 either — separate note there.

[amiddavid]

Non-blocking, and last thing from me: parseSSEUsageWhy can never return usageMissUnreadable, so a spliced window that hides usage on the streamed transport is classified benign.

A data: line cut mid-JSON does not yield a usagePresent block, so worst stays at its initial usageMissAbsent and the response is reported as "the provider streamed no usage" — no counter, no record. Verified on this branch:

spliced sse window -> why=absent  unparsed+0 unreadable+0  record: (none)

The reason this is worth a line: 2da9bd5 established that unreadable_body is reachable only from the sniffed path, and the sniffed path is exactly where SSE responses get a head+"\n"+tail window. So usage_unreadable fires for sniffed JSON bodies (which is what the fixture models, via ValidBytes) and is structurally unreachable for sniffed streams — where a splice that hides the block reads as absent, which is an accounting outage indistinguishable from a provider that reported none. That is #200's defect, in the corner this classification does not reach.

In practice the head window saves the common case: Anthropic puts input_tokens in message_start, which is at the front of the head, so found is true and the classification is parsed. So this is narrow, and I would not hold the PR for it.

If you do want it closed, the signal is already there and needs no new parsing: sniffer knows it spliced — s.total > len(s.head) in bytes(). Exposing that as a spliced() bool and letting Handler.stream pass it into responseUsageWhy would turn absent on a spliced window into unreadable, and it would make the buffered case exact rather than inferred from ValidBytes failing. Either way it belongs on the issue rather than in this diff, and a sentence at worst's initialiser saying the streamed transport has no unreadable value would be enough to stop the next reader assuming symmetry between the two parsers.