fix(metrics): scope extraction accounting per component, and log every extraction call - #178
Conversation
…y extraction call Closes #176. Closes #177. WHAT THE COUNTERS WERE ACTUALLY SCOPED TO Established from the code that writes them, not from the names: - The `extract` nested map in /stats was PROCESS-GLOBAL, not per component. metrics/extract.go held one set of package-level atomics, and both components/offload/extract_llm.go and components/offload/extract_sweep.go wrote them. So `calls`, `avg_latency_ms`, `calls_avoided`, `calls_suppressed`, `gross_saved_tokens`, `reasons` and the whole net-value block were the SUM of extract_llm and extract_llm_sweep, presented under a name that reads as one of them. The file even said so as a design statement ("these are process-global counters"), and cheapmodel/usage.go states the premise it rested on: "today the LLM component in a config is extract, so the global total is that component's cost". That premise stopped being true when the cold-transcript sweep became its own component. The 101 `calls` reported for extract_llm in iteration 023 arm B were very nearly the sweep's 96 asks, and the 59,009 ms mean was the sweep's frontier-model ask latency. - `extraction_cost_usd` was scoped WIDER STILL — not to extraction at all. The proxy derived it from cheapmodel's process-global token totals through one rate card, and every cheap-model call in the process lands in those totals, including `summarize` and `agentdiet`. The same figure also mispriced the sweep, whose asks go to the request's own frontier model while the card is haiku's. - `components.extract_llm.acted` DOES count frozen replays as acts, and it is correctly scoped otherwise. It is `Saved() > 0 && !Reverted && !Skipped`, keyed on Report.Component; a same-session replay splices previously frozen bytes and so saves tokens, landing in the same counter as the call that derived them. `acted: 239` beside `reapplied_same_session: 2,291` was read as 239 paid extractions. - `cands: 0` was NOT the wrong side. Replays `continue` before a candidate is appended, so `cands: 0` with a nonzero `reapplied` is exactly what a request that only replayed looks like. cands=0 on every request and acted=239 are consistent and both true: extract_llm acted 239 times without making a single fresh call. The number that was wrong was `calls`, and it was wrong because it was pooled. - `saved_tokens: 6,077,421` vs `saved_tokens_unique: 597,764` is NOT a defect. Saved is documented as cumulative and SavedUnique dedups by content key; overcount_ratio 31.58 is the intended signal that this workload re-sends history verbatim. Left alone deliberately. WHAT CHANGED - metrics/extract.go: the counters are keyed by component. Every recorder takes the component name; the aggregate is DERIVED by summing, not maintained alongside. ExtractStats gains `by_component`, and the enclosing block stays the sum because deploy/harbor/*.py parses it. - RecordExtractionSpend: each component records what its own call cost, priced with the rates of the model it actually addressed, so per-component net value is real and does not inherit summarize's and agentdiet's spend. The host's global figure remains the fallback for an embedding that records nothing. - The latency accessors are keyed too, which is a BEHAVIOUR change: the exploration brake in offload.tooSlowToExplore read the global p50, so the sweep's ~59s asks braked extract_llm's cheap-model exploration on another component's evidence. - components.Report gains Replays, set through Report.Replay(name) so the count and the descriptive Event cannot drift. metrics splits `acted` into `acted_fresh` and `acted_replay` (a run that saved tokens, made no model call, and replayed at least one frozen decision is free work). `acted` keeps its meaning and its value. - components/offload/extract_llm.go emits `cg.extract_llm.call`, one DEBUG record per call, carrying session, content key, candidate tokens, model, latency, input/output and cache tokens, cost, the never-worse accept/reject outcome with its rejection reason, the resulting saving, the gate reason and strategy. Guarded by the `dbg` flag already resolved once per request. VACUITY Every new assertion was verified to fail with its subject broken. Six single-point mutations, five killed: M1 xFor returns one shared bucket for all names (INTRODUCING the original bug, because the fix makes it unrepresentable) -> TestExtractStatsAreScopedPerComponent, TestLatencyAccessorsAreScopedPerComponent and the proxy /stats test all fail, reporting extract_llm with the sweep's 2 calls, 59,009 ms and -$1.162. M2 spend always taken from the host's global figure -> cost 9.99 against 0.32. M3 ByComponent never attached to the snapshot -> both the JSON test and the rendered /stats test fail. M4 act() ignores Replays -> acted_fresh 4 / acted_replay 0 against 1/3, in the package test and in the rendered /stats body. M5 the per-call record neutralized -> 0 records for 1 reported call. M6 Debug -> Info on the per-call record -> STILL PASSED. The DEBUG gate is defended redundantly (the `if dbg` guard for the payload, the slog level for the output), so no single-point mutant kills TestExtractLLMCallRecordIsDebugGated. The combined mutant (`if dbg` -> `if true` AND Debug -> Info) does fail it; that is recorded in the test's own doc comment so nobody reads its passing as proof the guard is there. The two golden contract lists (statsGoldenComponent, and the extract block's key list) failed before the new keys were added to them, which is the same check by another name. CGO_ENABLED=1 go vet ./... clean; CGO_ENABLED=1 go test ./... green, 28 packages. Assisted-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: DAVID AMID <DAVIDA@il.ibm.com>
amiddavid
left a comment
There was a problem hiding this comment.
Review
Reviewed the 11-file diff against origin/main, and independently re-ran the checks on the eval box (Go 1.26.4, CGO_ENABLED=1): go vet ./... clean, go test ./... fully green, gofmt -l . clean. Commit trailers are correct — DCO Signed-off-by, the exact Assisted-By line, conventional title, and the mutation table in the commit body rather than only in the PR description.
The core of the change holds up. Every metrics.RecordExtraction* / Extraction*LatencyMs call site is converted; rep.Component is set by components/pipeline.go:81 before Offload runs, so no recorder sees an empty key on the proxy path. Both reapplied_* sites in each component go through Report.Replay, with no third path missed. compStat.act is called on the same *compStat from both the enforced and observe loops and reverseDiscarded does not touch Acted, so acted == acted_fresh + acted_replay holds. In the per-call DEBUG record, every referenced variable is assigned before the log, and the single-flight follower's early return correctly emits nothing. xCounters locking, the per-component latency ring, and sortedReasons' nil-in/nil-out contract are sound, and ByComponent cannot recurse.
Four things below. Two are inline on the diff; two are not reachable inline.
The dashboard keeps the exact reading #176 describes
dash/event.go:527 still computes row.Acted = row.Mutated && row.SavedGross > 0, so a free frozen replay still counts as an act. components.Report.Replays is available on r at that point and is not read. /api/components's acted, acted_tokens and act_rate (dash/query.go:776-782) therefore keep conflating the 2,291 free replays with paid extractions — on the surface the dashboard actually renders. /stats is fixed; the dashboard is not, and this is not listed among the PR's known gaps. Whether it belongs in this PR or a follow-up is a scope call, but it should be stated either way rather than left to be rediscovered.
Docs still describe the old scoping
docs/reference/routes.md:84— the per-component field table is exhaustive by convention and now omitsacted_freshandacted_replay.extract.by_componentis documented nowhere.docs/components/extract_llm.md:678— this table still presentscalls,extraction_cost_usd,avg_latency_msandgross_saved_tokensas extract_llm's own figures. That is exactly the misreading the PR exists to correct: post-change those keys are the sum across components, and the doc is now the artifact that produces the #176 misread.statsGoldenComponentwas updated; the prose contract was not.
One claim in the PR body does not check out
The body and docs/components/extract_llm.md:677 both justify key stability with "deploy/harbor/*.py parses it". I grepped deploy/ for gross_saved_tokens, calls_avoided, extraction_cost_usd and avg_latency_ms — no harbor script reads any of them. Keeping the keys stable is still the right call for operators and for /metrics, but the stated reason is not the real one, and it is load-bearing in the design rationale.
Also noting, since it bears on finding 1: /metrics staying aggregate is called out as deliberate, but cg_extract_cost_usd will now inherit whatever extraction_cost_usd computes, including the dropped fallback spend.
| // /stats derived extraction cost from cheapmodel's process totals through the cheap-model | ||
| // rate card, so this component's frontier-model asks were priced at haiku rates and pooled | ||
| // with extract_llm's, summarize's and agentdiet's. See metrics.RecordExtractionSpend. | ||
| metrics.RecordExtractionSpend(rep.Component, r.rec.CostUSD) |
There was a problem hiding this comment.
MAJOR: the sweep's fallback-ask spend and latency are dropped from extraction_cost_usd entirely.
RecordExtractionSpend(rep.Component, r.rec.CostUSD) sits immediately after r.rec is built from the prefix ask's usage, and r.rec is assigned exactly once (line 630) — never recomputed. But fallbackAsk makes a real second model call on c.Model.For("incoming"), the request's own frontier model, on three live paths:
c.PrefixAsk == nil(any non-Anthropic route) —usageis never assigned here at all, soCostUSD == 0andRecordExtractionSpendis skipped by itsusd > 0guard;ErrNoPrefix— every session's first turn;usage.CacheRead == 0— a mistimed window.
fallbackAsk returns (string, error): no usage, no cost. Before this PR that spend still reached /stats, because model.Complete lands in cheapmodel's process totals (internal/cheapmodel/anthropic.go:161 calls recordUsageCache) and was priced into the cost argument. Now, as soon as any component records spend (anySpend == true, metrics/extract.go:346), the host fallback is discarded and the fallback ask's cost is reported as $0.
Concrete scenario: extract_llm + extract_llm_sweep behind an OpenAI upstream. The sweep always falls back, pays frontier rates for a full sampled transcript on every firing, and /stats shows extract_llm_sweep.extraction_cost_usd: 0 with a purely positive net_value_usd — a component whose entire justification is cost, reported as free. That is the same class of defect as #176, in the component this PR just re-scoped.
The ordering also excludes the fallback's wall time from RecordExtractionCall (line 613, before the fallback) on the latter two paths, so avg_latency_ms under-reports as well.
There was a problem hiding this comment.
Confirmed and fixed in e95e90c — the diagnosis was exactly right, including that this PR is what made it reachable: before, the fallback's tokens still landed in /stats through cheapmodel's process totals via the cost argument, and making components price their own spend removed that accident.
What changed:
fallbackAsknow returns(string, components.PrefixUsage, float64, error).model.Completereports no usage, so it is read from a per-callcheapmodel.WithCallSinknested inside whatever scope already wraps ctx — the construction extract_llm already uses, and it still reaches every ancestor so the request's own bill keeps the tokens. The sink is read whether or not the call errored: a completion that failed after the provider billed it still cost money, and returning zeros there is how spend goes missing.- Each leg books itself, through one
recordLegclosure reached from all three fallback sites viarunFallback, so a fourth site cannot be added without the accounting coming with it. Two model calls now count as two, and the fallback's wall time is its own sample rather than being folded into a figure measured before it ran. foldFallbackgrows the ledger row to cover both legs — tokens, dollars, wall time — and names the strategy for what actually ran:"fallback"on the no-asker route,"prefix_ask+fallback"otherwise, rather than a row claiming a prefix-ask leg that never happened.
One deliberate exception, which is a small behaviour change: an ErrNoPrefix refusal is not booked as a call. It is refused locally before any request leaves the process, so counting it would inflate calls with work that by definition did not happen and put a 0 ms sample into the mean tooSlowToExplore reads. Say the word if you would rather keep it counted for continuity with the old calls series.
Two new tests drive this through the real recording path — a cheapmodel.Anthropic against an httptest server that reports usage, because recordingModel bills nothing and a fake that bills nothing would let the assertion pass against a fix that plumbs nothing:
TestSweepFallbackAskPricesItsOwnCall— the no-asker path, your OpenAI-upstream scenario.TestSweepCountsBothLegsWhenItFallsBackAfterAsking— the zero-cache-read path, where the fold matters because the row already exists.
Vacuity: three mutations, all killed. Zeroing the returned usage → ledger row $0, row tokens 0/0 against 31000/420, /stats delta $0, cost_source: "unpriced". Removing the leg booking → 0 calls where 1 is due, 1 where 2 are due. Removing the fold → row shows prompt 40 / completion 90 of 31040/510 and the wrong Strategy.
| } | ||
| // The components' own priced spend where any of them recorded some; the host's | ||
| // process-global figure only as a fallback. See xCounters.spendNano. | ||
| if !anySpend { |
There was a problem hiding this comment.
The host-fallback cost is applied only to the aggregate, so by_component rows can contradict the block that encloses them.
spend = cost is all-or-nothing on the total; xCounters.snapshot never sees cost, so a component that recorded no spend gets ExtractionCostUSD: 0 and NetValueUSD: +grossValue.
This PR's own test pins that shape: TestRecordedSpendBeatsTheHostsGlobalFigure — after RecordExtractionCall("extract_llm", 100) with no spend, top-level extraction_cost_usd == 9.99 while the only by_component row reads 0. Scenario: a library embedding or /compact, where ModelCall.CostUSD is never filled — the operator reads by_component.extract_llm.net_value_usd as comfortably positive while the block directly above says the component is underwater. Two figures for the same quantity disagreeing by the whole spend is precisely the failure mode this change exists to remove.
Separately, partial recording silently under-reports the aggregate. anySpend is one boolean across all components. If extract_llm prices its calls (Haiku card, always non-zero) but extract_llm_sweep records nothing — via the fallback-ask path above, or c.SelfRates zero with zero usage — the total becomes extract_llm's spend alone and the sweep's real dollars vanish rather than falling back to the host figure.
Both point the same way: the fallback wants to be per component, not per snapshot. Where a component genuinely has no priced spend, marking the row "spend not recorded" would beat printing 0, which is indistinguishable from "spent nothing".
There was a problem hiding this comment.
Both halves confirmed and fixed in e95e90c. And yes — TestRecordedSpendBeatsTheHostsGlobalFigure pinned the bad shape, which is a fair hit: the test asserted the behaviour rather than questioning it.
I did not make the host figure per-component, because I do not think it can be made per-component honestly: cost is one process-global number that also carries summarize and agentdiet, and splitting it by call count would be an invented number published at the same precision as a measured one. So the fix is to make the unknown visible instead of guessing at it:
net_value_usdis now*float64, rendered as JSONnullwhen the spend behind it is not known. A row that made calls and priced none of them no longer publishes+grossValue. The aggregate is never null — it always has a determined spend — so thecg_extract_net_value_usdgauge is unaffected in practice;promexportreads it through aNet() (float64, bool)accessor and omits the series rather than publishing an unknown as0, which on that gauge reads as exactly break-even.cost_sourcenames the case, which is your "spend not recorded" made machine-readable:component(every call priced itself),host_total(the host's superset figure),partial(some calls unpriced, so the total is a floor),unpriced(this row made calls and priced none — nothing is known),none(no calls, so0is the true figure).- Partial recording no longer under-reports.
unpricedCallsreplaces the singleanySpendboolean: when any calls are unpriced the aggregate publishes the larger of the recorded floor and the host's superset figure, and labels which one it chose. A total that quietly omits real dollars is the defect; a loud one is not.
Note the two findings interlock — with finding 1 fixed, the sweep prices every leg, so unpriced is no longer reachable through the fallback path. It stays reachable for a host that never fills ModelCall.CostUSD at all (a library embedding, /compact), which is the case the label is for.
Two new tests, TestAnUnpricedRowSaysSoInsteadOfClaimingZero and TestPartialPricingDoesNotSilentlyUnderReportTheTotal, and the old one now asserts the corrected contract instead of the shape you flagged.
One thing worth flagging about my own vacuity run. The cost_source mutant (json:"-") survived the first pass, because my assertions read the Go struct field rather than the encoded payload — the exact "computed correctly and dropped by the handler" failure the rendered-output rule exists for, committed in the same change that cites the rule. TestByComponentSurvivesJSON and TestStatsRendersPerComponentExtractionAttribution now assert cost_source and the null net on the marshalled payload and on the /stats body, and the mutant then fails on both surfaces. Recorded in the PR body rather than quietly fixed, since a mutant that survives and then dies is the only evidence the test change did anything.
One limitation I did not solve: cost_source: partial cannot say which component is unpriced. Finding the culprit still means scanning the rows for cost_source: unpriced. Adequate, not ideal — noted in the PR's known gaps.
There was a problem hiding this comment.
Following up on the one limitation I flagged when closing this thread — that cost_source: partial could not say which component was unpriced, so finding the culprit meant scanning the rows. That is fixed in 6e01798 rather than left as "adequate, not ideal".
ExtractStats.UnpricedComponents (unpriced_components) names them, sorted, on the aggregate only, omitted when every call priced itself. The argument for doing it: !recorded && s.Calls > 0 is the same test that sets the aggregate's label, so the snapshot already knew the answer and was making the reader re-derive it — and a reader who has to re-derive will read the label and stop, at which point the floor gets quoted as the bill.
Published under both incomplete regimes rather than only partial. Under partial the list says what the floor is short of; under host_total it says what forced the fallback. Same reason in both cases.
Vacuity: three mutations, all killed on both surfaces — the list never populated, computed-but-not-attached, and dropped by the encoder (json:"-"). That last one is the M13 shape, so both new assertions read the marshalled payload: TestTheAggregateNamesWhichComponentIsUnpriced through json.Marshal and TestStatsNamesTheUnpricedComponent on the /stats body. Each asserts the precondition that the total really is incomplete before asserting the list, and each asserts the field is omitted when nothing is unpriced.
The other two limitations from this area became issues rather than staying prose: #180 (cg_extract_cost_usd inherits the cost_source regime with no way to express it) and #181 (cheapmodel.Usage() scoping, plus its comment still asserting the premise that produced #176 — with the reason deferring is safe recorded there). Full summary in the PR body and in the top-level comment.
…ack per component Addresses the four findings in review of #178. 1. MAJOR (introduced by this PR) — THE SWEEP'S FALLBACK ASK REPORTED $0 AND 0 MS. `fallbackAsk` is a second model call, on the request's own frontier model, carrying a sampled copy of every candidate. It returned only (string, error) — no usage — while `r.rec` was built from the PREFIX ask's usage and assigned exactly once, and RecordExtractionCall ran before two of the three fallback points. So on every non-Anthropic route (no prefix asker, so the fallback is the ONLY call), every session's first turn (ErrNoPrefix) and every mistimed window (CacheRead == 0), the component's real spend and its seconds were dropped. Before this PR that spend still reached /stats by accident, through cheapmodel's process totals which the host passed in as `cost`. Making components price their own spend removed the accident, so it had to be fixed properly rather than left. `fallbackAsk` now returns its own usage and wall time, read from a per-call cheapmodel sink (the construction extract_llm already uses), and each LEG books itself through one `recordLeg` closure reached from all three call sites. `foldFallback` grows the ledger row to cover both legs, and names the strategy for what actually ran ("fallback" on the no-asker route, "prefix_ask+fallback" otherwise). An ErrNoPrefix refusal is deliberately NOT booked as a call: it is refused locally, so no request leaves the process, and counting it would put a 0 ms sample into the mean the exploration brake reads. 2. MAJOR (introduced by this PR) — THE COST FALLBACK WAS AGGREGATE-ONLY. `spend = cost` was all-or-nothing on the total and `xCounters.snapshot` never saw `cost`, so a component that priced nothing got `extraction_cost_usd: 0` and a positive `net_value_usd` while the block enclosing it reported the host's figure. Two figures for one quantity disagreeing by the whole spend. Separately, `anySpend` was a single boolean: if extract_llm priced its calls and the sweep priced none, the total silently became extract_llm's spend alone. The host's figure cannot be split across rows — it is one process-global number that also carries `summarize` and `agentdiet` — and splitting it by call count would be an invented number at the same precision as a measured one. So a row that priced nothing now SAYS SO and leaves the net UNKNOWN: - NetValueUSD is *float64, rendered as JSON null when the spend is not known. The aggregate is never null. - CostSource names the case: component / host_total / partial / unpriced / none. $0 spent and $0 of evidence are the same number and the opposite claim. - The aggregate publishes the larger of the recorded floor and the host's superset figure when any calls are unpriced, and labels which — a total that quietly omits real dollars is the defect, not the loud one. 3. THE DOCS DESCRIBED THE OLD SCOPING. docs/reference/routes.md gains acted_fresh / acted_replay and a section documenting extract.by_component and cost_source. docs/components/extract_llm.md presented `calls`, `extraction_cost_usd`, `avg_latency_ms` and `gross_saved_tokens` as this component's own figures when they are sums across components — the artifact that produces the #176 misread — and now says so, with the measured numbers. 4. A FALSE RATIONALE, REMOVED. "deploy/harbor/*.py parses it" justified freezing the extract block's key names, here and in the docs, and it is not true: grepping deploy/ for gross_saved_tokens, calls_avoided, extraction_cost_usd or avg_latency_ms returns nothing. Harbor reads `runs`, `acted` and `saved_tokens` off the per-COMPONENT objects (measure.py by direct index, so a removal is a KeyError) and nothing out of this block. The real reason is /metrics: promexport publishes these as cg_extract_* series that off-repo alert rules query, where a rename breaks monitoring silently — a worse failure than breaking the harness, which would at least crash. Corrected in both places, with the distinction stated. Also raised: /api/components keeps the exact conflation #176 describes (dash/event.go:527). Pre-existing on main, so filed as its own issue (#179) per the rule that a main defect unrelated to the change under test ships separately. Listed in this PR's known gaps. VACUITY — six new single-point mutations, all six killed: M8 fallbackAsk reports no usage -> ledger row $0, /stats delta $0, cost_source "unpriced", Strategy unchanged M9 the fallback books no leg -> 0 calls recorded where 1 is due; 1 where 2 M10 the ledger fold removed -> row shows prompt 40 / completion 90 of 31040/510 M11 an unpriced row claims a known net -> net_value_usd 0.05 where null is due M12 back to the anySpend boolean -> total $0.02 against a host figure of $4.00, and "component" where "partial" is due M13 cost_source dropped from JSON -> caught only AFTER strengthening the two rendered-output tests; it SURVIVED first, because the assertions read the Go field rather than the encoded payload. Recorded because that is the failure mode the repo's rule about rendered output exists for. M6's redundant-guard situation (the DEBUG gate, killable only by a combined mutant) is unchanged and still documented in the test. gofmt -l clean; CGO_ENABLED=1 go vet ./... clean; CGO_ENABLED=1 go test ./... green, 28 packages. Assisted-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: DAVID AMID <DAVIDA@il.ibm.com>
|
Thanks — all four findings hold up, and two of them were mine to answer for. Fixed in e95e90c; the PR body is rewritten with a Review round 2 section. The two inline threads have detailed replies; this covers the rest. Docs (finding 3)You are right that the doc had become the artifact producing the misread, which is worse than it being merely stale.
The harbor claim (finding 4)Verified, and you are right. Grepping What harbor does read is The real reason those names are frozen is The dashboard (
|
…d, and the -$1.162 is neither component's The earlier text guessed the extract nested map "is not scoped to one component" and concluded the 59s latency and the -$1.162 were probably the SWEEP's figures. #178 root-caused it and the guess was too kind. The map was process-GLOBAL: one set of package-level atomics that both extract_llm and extract_sweep wrote every field of, so calls, avg_latency_ms, calls_avoided and the whole net-value block were two components with opposite economics summed under a name that reads as one of them. extraction_cost_usd was wider still, derived from cheapmodel.Usage(), which catches every cheap-model call in the process including summarize and agentdiet, priced through the haiku card even though the sweep asks the request's own frontier model. So the -$1.162 is two components' savings against three components' spend at one component's rates -- neither the sweep's figure nor the tail pass's. Pooling happened at write time, so no re-reading of these logs can repair it. Two corrections to the analysis this file carried. cands: 0 was NOT the wrong side -- a frozen replay continues before its candidate is appended, so cands: 0 on all 692 records and acted: 239 are consistent and both true, and extract_llm acted 239 times without one fresh call. And the 31.58x overcount is not a defect at all; it is the designed cumulative-versus-unique contrast, correctly left alone. One side finding recorded because it has behavioural teeth rather than merely display: tooSlowToExplore read the GLOBAL p50, so the sweep's ~59s asks were braking extract_llm's cheap-model exploration. The tail pass's firing behaviour in this iteration was influenced by the sweep's latency through a channel nobody was watching. Signed-off-by: David Amid <david.amid@il.ibm.com> Assisted-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: DAVID AMID <DAVIDA@il.ibm.com>
…at the total is short of
The last review item that could be fixed in this PR rather than tracked. The other three
became issues; nothing is left as a prose known gap.
`cost_source: partial` told a reader the total was a FLOOR without saying what it was short
OF, so finding the culprit meant scanning every by_component row for `cost_source: unpriced`
— re-deriving an answer the snapshot had already computed, since it is the same test that
sets the aggregate's label. An operator who has to re-derive it will read the label and stop,
and then the floor gets quoted as the bill.
ExtractStats.UnpricedComponents names them, sorted (the iteration order already is), on the
aggregate only, omitted when every call priced itself. Published under both incomplete
regimes, because they are incomplete for the same reason: under `partial` it names what the
floor is short of, under `host_total` it names what forced the fallback. Documented in
docs/reference/routes.md and docs/components/extract_llm.md.
VACUITY — three mutations, all three killed, and each on BOTH surfaces:
M14 the list is never populated -> the rendered block names nothing while
cost_source still says `partial`
M15 computed but never attached to the snapshot
M16 dropped by the ENCODER (`json:"-"`) -> the M13 shape, and the reason both
assertions read the marshalled payload
rather than the Go field
TestTheAggregateNamesWhichComponentIsUnpriced asserts on json.Marshal output;
TestStatsNamesTheUnpricedComponent asserts on the /stats HTTP body. Both check the
PRECONDITION that the total is actually incomplete first, so neither can pass vacuously on a
snapshot with nothing to report, and both check the field is OMITTED when everything priced
itself — an empty list on a complete total would read as a warning where there is none.
The proxy test uses a component name of its own rather than a real one: these counters are
process-global for the package run, and TestStatsRendersPerComponentExtractionAttribution
asserts ABSOLUTE values on extract_llm and extract_llm_sweep. Making either unpriced there
would break that test through shared state for a reason unrelated to either test's subject.
FILED RATHER THAN FIXED HERE, cross-referenced from the PR body by number:
#180 cg_extract_* has no component label, and now inherits cost_source without being able
to express it — a gauge reading -0.71 may be priced arithmetic, a floor, or the
host's superset figure, and the series is identical in all three. Cannot ship here:
a label changes series shape that off-repo alert rules are written against.
#181 cheapmodel.Usage() is still process-global and its comment still asserts the premise
that produced #176. Records why deferring is safe: /stats depends on it only as a
LABELLED fallback now (`cost_source: host_total`), so the wrongness is declared at
the point of use rather than silently inherited.
#182 whether a locally-refused ErrNoPrefix ask should count as a call. Assigned to
@OsherElhadad for a second opinion. States the position taken, names the continuity
cost (a published counter steps down with no code change an operator can point to),
gives the concrete alternative (count it under `refusals`), and says what would
change my mind.
Dropped from the known gaps: docs/experiments/loca/iter023/results.md lives on
feat/coref-recut, not main, so this PR cannot touch it. The general point — that
per-component claims made before this change need re-measuring — stays, without implying a
fix was owed here.
gofmt -l clean; CGO_ENABLED=1 go vet ./... clean; CGO_ENABLED=1 go test ./... green, 28
packages.
Assisted-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: DAVID AMID <DAVIDA@il.ibm.com>
|
Round 3 ( Moved into the PR
Two details worth flagging:
Documented in Vacuity: three mutations, all three killed, each on both surfaces. M14 the list never populated; M15 computed but never attached to the snapshot; M16 dropped by the encoder ( Became issues
#179 was already filed after round 2 and is referenced in the gaps table. Dropped
State
Running total across the three rounds: 15 mutations, 15 killed — two of them (M6's redundant DEBUG guard, M13's |
amiddavid
left a comment
There was a problem hiding this comment.
Re-review
Both regressions are genuinely fixed, and I verified the mechanisms rather than the claims.
Finding 1 (the sweep's fallback ask reported $0 and 0 ms) — fixed, and correctly. fallbackAsk now returns its own usage and wall time from a nested cheapmodel sink, and recordLeg books each leg from a single closure reached by all three call sites. I checked the two things the design rests on: WithCallSink chains through parent (internal/cheapmodel/usage.go:113, add walking cur = cur.parent), so the request's own bill does not lose these tokens; and recordUsageCache feeds SinkFrom(ctx) on both backends, so the OpenAI route is covered too, which matters because that route is precisely where the fallback is the only call. The !fellBack guards mean exactly one fallback runs per adjudication, so foldFallback's idempotency claim holds. Resolving pricing before the ask is right — both legs address c.Model.For("incoming"), so one card is correct for both.
Not booking a locally-refused ErrNoPrefix as a call is the right call for the reason given (no request leaves the process, and a 0 ms sample would pollute the mean the exploration brake reads), and filing #182 for a second opinion rather than deciding it unilaterally is the better handling of a published counter stepping down.
Finding 2 (aggregate-only cost fallback) — fixed, and the fix is better than what I asked for. I suggested a per-component fallback or an explicit marker; refusing to split the host's process-global figure across rows is the more honest answer, since apportioning it by call count would manufacture a number at the same precision as a measured one. NetValueUSD *float64 rendering null, with CostSource naming which of the five cases a row is in, makes the unknown legible instead of arithmetically laundered. unpricedCalls replacing the anySpend boolean closes the silent under-report, and publishing max(floor, host) under a partial/host_total label is the right direction to fail in.
I checked for the hazard the pointer introduces: NetValueUSD has exactly one non-test consumer, proxy/promexport.go:618, and it reads through Net() rather than dereferencing, so an unknown omits the series instead of publishing 0 — which on that gauge would read as exactly break-even. No unguarded dereference anywhere in the tree.
Findings 3 and 4 — handled. The docs no longer produce the misread: extract_llm.md now leads with a danger admonition naming the sum, and routes.md documents acted_fresh/acted_replay, by_component, cost_source and unpriced_components. And the corrected rationale is verifiably the right one — I re-grepped: measure.py:140 reads runs, acted and saved_tokens off the per-component objects by direct index, and nothing under deploy/ touches any key in the extract block. Worth noting that the surviving harness claim on cheapmodel.Usage() (usage.go:159) is accurate — measure.py:138 does index llm_calls, llm_input_tokens and llm_output_tokens — so that one is correctly left alone.
All four deferred items carry numbers (#179, #180, #181, #182) and I confirmed each is open and says what the commit claims it says.
Checks, re-run independently on the eval box (Go 1.26.4, CGO_ENABLED=1)
gofmt -l . clean · go vet ./... clean · go test ./... green, no failures.
I also ran my own revert-verify of the headline fix rather than taking M8 on trust. Neutralizing the sink wiring (ctx, sink := → _, sink :=, so the fallback's usage is never captured) and asserting the mutation landed, both new tests die with exactly the claimed output:
89: the ledger row prices the fallback at $0 — the defect this test exists for
93: the fallback's tokens did not reach the row: prompt=0 completion=0, want 31000/420
107: extract_llm_sweep.extraction_cost_usd moved by $0: the fallback's spend is still missing from /stats
111: cost_source = "unpriced", want "component"
151: Strategy = "prefix_ask", want "prefix_ask+fallback"
155: row tokens = prompt 40 / completion 90, want 31040/510 — the row still shows one leg
Restored, green again. The tests assert their preconditions (the no-asker path was taken, the fallback ran, a ModelCall exists) before their subject, so they cannot pass vacuously on a fixture that silently declined.
One minor item inline — a leftover of the same class as finding 1, latency-only. Nothing blocking.
| // Idempotent by construction — at most one fallback runs per adjudication and this reads the | ||
| // accumulators rather than adding to them — so calling it on every path that can reach a | ||
| // fallback is safe. | ||
| foldFallback := func() { |
There was a problem hiding this comment.
Minor, same class as the bug this closure fixes: foldFallback() is skipped on all three fallback error paths, so a failed fallback's wall time never reaches the ledger row.
All three sites are if reply, err = runFallback(); err != nil { return nil, r } (lines 681, 727, 758) — the foldFallback() call sits after the early return. runFallback has already booked the leg into metrics via recordLeg, so /stats counts the call and its latency, while r.rec keeps only the prefix ask's LatencyMs and a Strategy of "prefix_ask" naming a leg that is no longer the only one that ran.
Scope, having checked both backends: on an error the sink is empty, because recordUsageCache is only reached after a successful decode on both paths (anthropic.go:161, openai.go:120) and neither returns an error after billing — an empty content list yields "", nil, not an error. So this is latency-only, not dollars, which is why it is minor rather than a repeat of the original finding. It still matters because the fallback is the slow leg by construction: a failed one contributes tens of seconds to avg_latency_ms while the per-call row the dashboard renders shows only the ask's milliseconds, and the row misnames what ran.
Site 681 is a slightly different shape — r.rec does not exist yet, so rec.Component is "" and the row is dropped by the call.rec.Component != "" guard at line 473 entirely. /stats has a call the ledger has no row for. Not a regression (that path never built a row), but the spend recording is new, so the divergence is.
defer foldFallback() immediately after the accumulators are declared would cover all three: it is already documented as idempotent, it reads the accumulators rather than adding to them, and at site 681 it would populate the row that currently vanishes. The one thing to check if you take that route is that the deferred call must not run before r.rec is assigned on the happy path — it won't, since the defer fires at function exit.
There was a problem hiding this comment.
Fixed in 7fed0d0. Correct as diagnosed, including the latency-not-dollars reasoning — I re-checked and agree: the sink is empty on an error because recordUsageCache sits after a successful decode on both backends, and an empty content list yields ("", nil) rather than an error, so there is no path that bills and then errors.
I took defer foldFallback(), but it needed one correction that turns out to be the whole fix.
It does not work against a local. Every early return in adjudicate is return nil, r on var r sweepResult, and a deferred mutation of a local happens after the return value has been copied — so the fold would compile, run, and be silently discarded on exactly the three error paths it exists to cover. The sweepResult is a named result now; the other result stays blank-named ((_ []int, r sweepResult)), because only this one needs the treatment and saying so beats leaving a reader to wonder what a second name is for.
Your check — "the deferred call must not run before r.rec is assigned on the happy path" — holds, and there is a second half to it worth stating: the happy path's r.rec = components.ModelCall{…} overwrites the deferred fold's work-in-progress, which is why the explicit call after that assignment stays. Re-folding is free, since foldFallback reads the accumulators rather than adding to them.
Site 681's vanishing row is covered, and it needed more than the fold. Deferring alone would have populated latency and tokens on a row whose Component was still "" — so Offload would have dropped it on the call.rec.Component != "" guard exactly as before, and the fix would have run and changed nothing observable. foldFallback now establishes the identity fields (Component, Model, CandidateTokens, GateReason) when the row does not exist yet. That has its own mutant (M18) precisely because it was the half most available to leave half-done.
Vacuity: three mutations, all three killed.
- M17 — revert to the per-site fold. No-asker: "/stats counted a call and the ledger carries 0 rows". Ask-then-fail:
Strategy "prefix_ask"andLatencyMs 0against ~8 ms. - M18 — revert the identity establishment. The no-asker row vanishes on the guard.
- M19 — revert the named result. Fails identically to M17, with
defer foldFallback()still sitting there running and doing nothing. This is the one I'd point at: had I applied the suggested shape literally, the diff would have looked like a fix, passed a casual read, and been inert on every path it targeted.
On the assertion surface — I diverged, and here is why. You asked for the rendered surface, and there isn't one for a ModelCall inside /stats: ledger rows travel to the dash Event (dash/event.go → ExtractionRow), not this payload, so a JSON-tag assertion would be testing dash's converter rather than this fix. Instead I pinned what actually broke, which is that two surfaces disagreed: if /stats counts the call, the ledger must carry a row for it. Both tests assert /stats booked the leg and that rep.Calls has the row, so neither can pass while they diverge. And the assertion reads rep.Calls after Offload — past the guard that was doing the dropping — which is the same discipline as asserting on rendered output, by a different route. If you'd rather have the dash-side JSON assertion as well, say so and I'll add it in dash, but it would be pinning a different component's behaviour.
Both tests also assert the precondition that the fallback genuinely errored (sweep_fallback_failed == 1, plus the model was actually called) before asserting the row, so neither can pass on a fixture that silently declined. Fixturing the error was not awkward — an 8 ms sleep then ("", err) gives a measurable failed leg.
gofmt -l . clean, CGO_ENABLED=1 go vet ./... clean, CGO_ENABLED=1 go test ./... green at 28 packages, on the eval box against the committed tree. No benchmark. Gaps table unchanged — no new issues; #179–#182 still the full set.
…he ledger row
Round-4 review finding, inline on extract_sweep.go:654. All three fallback sites are
`if reply, err = runFallback(); err != nil { return nil, r }`, and every foldFallback() call
sat AFTER those early returns — so a fallback that failed was never folded. runFallback has
already booked the leg into metrics via recordLeg, so /stats counted the call and its seconds
while r.rec kept only the prefix ask's LatencyMs and a Strategy naming a leg that was no
longer the only one that ran.
LATENCY, NOT DOLLARS, and the reason is worth recording: on an error the sink is empty.
recordUsageCache is reached only after a successful decode on both backends
(anthropic.go:161, openai.go:120) and neither returns an error after billing — an empty
content list yields ("", nil), not an error. Same class as the earlier fallback-pricing
finding, not a repeat of its severity. It still matters because the fallback is the SLOW leg
by construction: a failed one contributes tens of seconds to avg_latency_ms against a per-call
row showing milliseconds.
THE NO-ASKER PATH IS THE SEVERE ONE. There r.rec does not exist yet when the fallback runs, so
on an error the row was never built at all: Component stayed "" and Offload dropped the whole
row on its `call.rec.Component != ""` guard, leaving /stats reporting a call the ledger had no
row for. That path never built a row before either, so the row is not a regression — the
recorded spend and latency are new, so the DIVERGENCE is. foldFallback now establishes the
identity fields (Component, Model, CandidateTokens, GateReason) when the row does not exist
yet, which is the half of this that a fold-only fix would have left undone.
TOOK THE SUGGESTED SHAPE, WITH ONE CORRECTION THAT IS THE WHOLE FIX. `defer foldFallback()`
does not work against a local: every early return here is `return nil, r` on `var r
sweepResult`, and a deferred mutation of a local happens after the return value has been
copied — so the fold would compile, run, and be silently discarded on exactly the error paths
it exists to cover. The sweepResult is therefore a NAMED result now. The other result stays
blank-named, because only this one needs the treatment and saying so beats leaving a reader to
wonder. One arming point covers all four exits that can carry a fallback; the explicit call
after r.rec is assigned stays, because that assignment overwrites the deferred fold's
work-in-progress and re-folding is free.
VACUITY — three mutations, all three killed:
M17 revert to the per-site fold -> no-asker: ledger carries 0 rows against a call
counted in /stats; ask-then-fail: Strategy
"prefix_ask" and LatencyMs 0 against ~8ms
M18 revert the identity establishment -> the no-asker row vanishes on the
Component != "" guard
M19 revert the NAMED result -> both tests fail identically to M17. This is the
one that matters: `defer foldFallback()` is
still there and still runs, and does nothing.
A fix that looks present and is inert.
ON THE ASSERTION SURFACE. There is no marshalled surface for a ModelCall inside /stats — the
ledger rows travel to the dash Event, not this payload — so a JSON-tag assertion would test
dash's converter rather than this fix. What actually broke is that two surfaces DISAGREED, so
that is what is pinned: if /stats counts the call, the ledger must carry a row for it. The
assertion reads rep.Calls after Offload, i.e. past the guard that was doing the dropping,
which is the same discipline as asserting on rendered output. Both tests assert the
precondition that the fallback genuinely ERRORED (sweep_fallback_failed) before asserting the
row, so neither can pass on a fixture that silently declined.
gofmt -l clean; CGO_ENABLED=1 go vet ./... clean; CGO_ENABLED=1 go test ./... green, 28
packages.
Assisted-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Signed-off-by: DAVID AMID <DAVIDA@il.ibm.com>
…ttribution The branch needed #178 before iteration 024 could run: a binary built from this branch carried the OLD pooled extraction counters, so the run would have reproduced exactly the unattributable cost and latency numbers iteration 023 spent a day root-causing. components/offload/extract_sweep.go changed on both sides and git auto-merged it. The resolution was verified rather than trusted, because a clean auto-merge of one function can compile and still be wrong. Both sides' work is present and reachable: from main defer foldFallback() with the NAMED result (_ []int, r sweepResult) -- the named result is load-bearing, since a deferred mutation of a local is discarded after the return value is copied, which is what made the obvious version of that fix inert; recordLeg / runFallback booking each fallback leg. from here selectAffordableDrops still called on the econ path only, at the same point between adjudicate() and the freeze/splice loop; evidence and econ_trigger still read; coref.Index still filling the evidence seam. gofmt clean, CGO_ENABLED=1 go vet clean, go test ./... green across 28 packages on the eval box against the merged tree. Signed-off-by: David Amid <david.amid@il.ibm.com> Assisted-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: DAVID AMID <DAVIDA@il.ibm.com>
…sured for the first time Written after launch but before any number is read, and committed with the frozen inputs and the reading table before the first arm-seed completes. Anything read earlier than this commit is inadmissible. Iterations 022 and 023 established that the mechanism works -- coverage 99.8% at batch 6.7, 96 asks, 426,638 tokens removed, the affordability rule firing. Cost and latency were never measured, because two defects made them unattributable. The extract counters were process-global and both components wrote every field, so latency and net value were two components with opposite economics summed under one name (#178, merged here as be79553). And cheap_model_price_unconfigured fired ONCE PER REQUEST in every arm of 023 -- 333/389/413 -- because the gate reads CHEAP_MODEL_PRICE_*, which the rig never set, so every allow/suppress decision in both iterations was taken against list rates rather than the operator's card. Now exported; a probe confirms the gate at 0 over 6 requests. Two arms, five seeds, 150 runs. The coref cutter arm is dropped -- 5.00/15 twice and no cost story pending makes it the least informative dollar in a run about cost. extract_llm stays IN, reversing 023's plan to remove it. Its 0/239/0 split is not a confound: it runs through the shared extraction result cache, where the sweep's putResult populates entries the tail pass then replays (2,291 replays, 2,291 calls_avoided, 66.8% hit rate, arm B only). That is the treatment's own decisions persisting. With the accounting fixed, acted_fresh vs acted_replay can measure that interaction instead of designing around it. Five seeds is the point rather than a luxury: at n=15 the Clopper-Pearson floor is 21.8% with ZERO worsened pairs, so no single-seed design can clear the 25% harm gate -- both prior iterations were blocked by arithmetic, not evidence. The reading table includes a failure row the earlier iterations lacked: if cost_source reads anything but `component`, the primary endpoint has FAILED and no cost conclusion may be drawn. That is to be checked on the first completed arm-seed, not at the end. Signed-off-by: David Amid <david.amid@il.ibm.com> Assisted-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: DAVID AMID <DAVIDA@il.ibm.com>
…t, and cost measured honestly 150 runs, 2 arms x 15 tasks x 5 seeds at 64k. REWARD: significant on the governing test with zero tasks regressed. Clustered over 15 tasks, net +2.00, 8 better and 0 worse, p = 0.0078. Per-pair over 75 pairs, net +10, 13 improved against 3 worsened, p = 0.0213. Arm A 36.00/75, arm B 46.00/75. Iteration 021's equivalent was p = 1.0000. The harm gate cleared for a structural reason rather than a lucky one: at n=15 the Clopper-Pearson floor is 21.8% WITH ZERO worsened pairs, so 022 and 023 were blocked by arithmetic, not evidence. Five seeds put n at 75 and the bound at 11.2%. That is what the seeds bought. COST: cost_source reads `component` on every arm-seed, so the pre-registered primary endpoint passed and these are the first attributable figures. The sweep spends $20.26 and books $0.72 of gross value -- 2.4M removed tokens bank at cache-read rates -- for a net of -$19.53. extract_llm earns $11.58 at zero cost. Combined -$7.95, about -$0.11/run or 9% on LOCA's $1.13/run. The mechanism's return does not appear in its own token ledger; it appears in reward. -$19.53 of measured loss bought +10 solves. And two caches turn out to be one: the sweep's putResult writes into the extraction result cache keyed by content id, extract_llm reads that same cache for its own reason, so the sweep's paid decisions become the tail pass's free hits -- 4,749 calls avoided at a 99.2% hit rate, 364 acts, zero fresh calls. That recovers 57% of the spend. Stated carefully: the sharing is measurable, nothing shows the economic consequence was intended, and it was invisible before #178 pooled counters were split. LATENCY: the hypothesis is REFUTED, not merely unsupported. Paired turns are 24.1 vs 29.4, and on the 33 pairs where BOTH arms solved, still 29.3 vs 33.2 -- 13% more turns on comparable work. Composition explains about half the gap and not the rest. The mechanism buys accuracy by letting the agent work longer on a managed context. The pre-registered reading table's row for this outcome is half right and is amended in the file: it treated reward as a harm gate rather than a possible finding, and the honest statement is that the mechanism does not pay in tokens and does pay in reward. Not a claim about the shipped configuration: the arms run min_inventory 3 and sweep min_tokens 100 against shipped 10 and 1000. Not a claim about coref-the-component, which was in neither arm. Signed-off-by: David Amid <david.amid@il.ibm.com> Assisted-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: DAVID AMID <DAVIDA@il.ibm.com>
Closes #176. Closes #177.
Both issues are one subsystem and one fix: #176 is counters disagreeing, #177 is that there was no record to arbitrate them with.
What the counters were actually scoped to
Established from the code that writes them, not from the names.
The
extractnested map was process-global.metrics/extract.goheld one set of package-level atomics —xCalls,xLatencyMs,xCacheHits,xSuppressed,xGrossSaved,xLookups,xValueNano,xReasons— and bothcomponents/offload/extract_llm.goandcomponents/offload/extract_sweep.gowrote every one of them. Socalls,avg_latency_ms,calls_avoided,calls_suppressed,gross_saved_tokens,reasonsand the entire net-value block were the sum of extract_llm and extract_llm_sweep, presented under a name that reads as one of them.The file said so as a design statement ("These are process-global counters, matching cheapmodel.Usage's existing scope"), and
internal/cheapmodel/usage.gostates the premise it rested on: "per-component attribution would need the Model interface to carry a label, a deferred refinement — today the LLM component in a config is extract, so the global total is that component's cost." That premise stopped being true when the cold-transcript sweep became its own component, and nothing re-examined the comment. #176's hypothesis was right.extraction_cost_usdwas scoped wider still — not to extraction at all. The proxy derived it fromcheapmodel.Usage()/CacheUsage(), the process-global token totals, priced through one rate card. Every cheap-model call in the process lands in those totals, includingsummarizeandagentdiet(both callmodel.Complete). The same figure also mispriced the half of extraction it did cover: the sweep's asks go to the request's own frontier model while the rate card is haiku's. So−$1.162was two components' savings against three components' token spend, priced at one component's rates.components.extract_llm.acteddoes count frozen replays as acts. It is correctly scoped to the component (metrics.Aggregator.Componentkeys onReport.Component), and it isSaved() > 0 && !Reverted && !Skipped. A same-session replay splices previously frozen bytes and therefore saves tokens, landing in the same counter as the call that derived them.acted: 239besidereapplied_same_session: 2,291was read as 239 paid extractions.cands: 0was not the wrong side. A replaycontinues before its candidate is appended tocands, socands: 0with a nonzeroreappliedis exactly what a request that only replayed looks like.cands: 0on all 692 records andacted: 239are consistent and both true: extract_llm acted 239 times without making a single fresh call in that arm. The number that was wrong iscalls, and it was wrong because it was pooled — the 101 are very nearly the sweep's 96 asks, and the 59,009 ms mean is the sweep's frontier-model ask latency.saved_tokens6,077,421 vssaved_tokens_unique597,764 is not a defect.Savedis documented as cumulative-per-turn andSavedUniquededups by content key;overcount_ratio: 31.58is the designed signal that this workload re-sends history verbatim, andreapplied_same_session: 2,291is its cause. Deliberately left alone — changing it would break the one honest pair /stats already had.What changed
metrics/extract.go: the counters are keyed by component. Every recorder takes the name; the aggregate is derived by summing rather than maintained alongside, because two totals kept in parallel is how the second drifts.ExtractStatsgainsby_component; the enclosing block keeps its keys and its meaning as the sum.RecordExtractionSpend: each component records what its own call cost, priced with the rates of the model it actually addressed (ModelCall.CostUSD, which both components already computed and neither reported to /stats). Per-component net value is now that component's own arithmetic.offload.tooSlowToExploreread the global p50, so the sweep's ~59-second frontier asks braked extract_llm's cheap-model exploration on evidence from a different component and a different model. Called out because it is a decision path, not a display.components.ReportgainsReplays, set throughReport.Replay(name)so the count and the descriptive Event (reapplied_same_session/reapplied_cross_session) cannot drift apart when a third replay path is added.metricssplitsactedintoacted_freshandacted_replayvia onecompStat.actcalled from both the enforced and observe loops.actedkeeps its name, its meaning and its value; a deterministic component reports all-fresh.cg.extract_llm.call(fix(extract_llm): no log record when an extraction call is made, so its 59s latency and negative net value have no per-request trace #177): one DEBUG record per call at the call site, carryingsession,content_key,candidate_tokens,model,latency_ms,input_tokens,output_tokens,cache_read,cache_write,cost_usd,accepted,saved_tokens,rejection,gate,strategy,timed_out. Guarded by thedbgflag already resolved once per request.acceptedis read off the sameModelCallthe splice used, so the log cannot claim an acceptance the request did not get.Vacuity — round 1
Six single-point mutations, applied on the eval box, test run, mutation restored. Five killed, one survived.
xForreturns one shared bucket for every name — i.e. introducing the original bug, since the fix makes it unrepresentableTestExtractStatsAreScopedPerComponentreports "extract_llm credited with 2 calls; it made none", "avg_latency_ms = 59009", "net = −1.162";TestLatencyAccessorsAreScopedPerComponentfails; the rendered /stats test fails with "credits extract_llm with 1 calls (baseline 0)" and "charged $1.2 it did not spend"extraction_cost_usd = 9.99, want 0.32ByComponentnever attached to the snapshotact()ignoresReplaysacted_fresh 4 / acted_replay 0against 1/3, in the package test and in the rendered /stats bodyif dbg→if false)Debug(→Info(on the per-call recordM1 is the equivalent-mutant case: keying the counters makes the pooled bug unrepresentable, so reverting proves nothing and the bug had to be introduced instead. Stated because that is the only honest way to read that row.
M6 survived, and the reason is a genuinely redundant defence rather than a weak test: the property "no record at INFO" is held by both the
if dbgguard (which exists so the payload is not built) and the slog level onDebug()(which exists so it is not printed). Remove either and the other still holds. The combined mutant —if dbg→if trueandDebug→Info— does fail it (verified; the INFO line appears in the buffer).TestExtractLLMCallRecordIsDebugGatedtherefore pins the outcome, not either mechanism, and that is written into the test's own doc comment so nobody reads its passing as evidence the guard is present.TestExtractLLMLogsOneRecordPerCall(M5) is the one that dies when the record itself goes away.Both new tests in
components/offloadalso assert their preconditions before their subject (model.calls != 0,len(rep.Calls) != 0, and the fixture logger actually being at DEBUG), because an extract_llm fixture that silently declines is how this kind of test passes vacuously —extract_llm_timeout_test.gocarries the same warning from the last time it happened.Assertions are on rendered output wherever the handler could drop a field:
proxy/extract_attribution_test.godrivesh.stats(w, req)and unmarshals the body, andmetrics.TestByComponentSurvivesJSONgoes throughjson.Marshal. The proxy test states its assertions against a baseline read of the counters rather than against zero, since they are process-global by construction.Review round 2
1. MAJOR (introduced by this PR) — the sweep's fallback-ask spend and latency reported as $0
Correct, and the mechanism is exactly as described.
fallbackAskreturned only(string, error);r.recwas built from the prefix ask's usage and assigned once;RecordExtractionCallran before two of the three fallback points. So on all three live paths — no prefix asker (any non-Anthropic route, where the fallback is the only call),ErrNoPrefix(every session's first turn), andusage.CacheRead == 0(a mistimed window) — a real frontier-model call on a full sampled transcript was booked at $0.00, and on the latter two its seconds were dropped fromavg_latency_mstoo. And the reviewer is right that this PR is what made it visible: before, the tokens still reached /stats through cheapmodel's process totals via thecostargument, and making components price their own spend removed that accident.Fixed:
fallbackAskreturns(string, components.PrefixUsage, float64, error).model.Completereports no usage, so it is read from a per-callcheapmodel.WithCallSinknested inside whatever scope already wraps ctx — the same constructionextract_llmuses, and it still reaches every ancestor so the request's own bill keeps the tokens. The sink is read whether or not the call errored: a completion that failed after the provider billed it still cost money.recordLegclosure, reached from all three fallback sites viarunFallback, so a fourth site cannot be added without the accounting coming with it. Two model calls now count as two.foldFallbackgrows the ledger row to cover both legs (tokens, dollars, wall time) and names the strategy for what actually ran —"fallback"on the no-asker route,"prefix_ask+fallback"otherwise, rather than claiming a prefix-ask leg that never happened.ErrNoPrefixrefusal is not booked as a call. It is refused locally, before any request leaves the process, so counting it would inflatecallswith work that by definition did not happen and put a 0 ms sample into the mean the exploration brake reads.2. MAJOR (introduced by this PR) — the host-fallback cost was aggregate-only
Also correct, on both halves, and
TestRecordedSpendBeatsTheHostsGlobalFiguredid pin the bad shape. The host'scostcannot be split across rows — it is one process-global number that also carriessummarizeandagentdiet— and splitting it by call count would be an invented number published at the same precision as a measured one. So the fix is to make the unknown visible rather than to guess:net_value_usdis now*float64, rendered as JSONnullwhen the spend behind it is not known. A row that made calls and priced none of them no longer publishes+grossValueon no cost evidence. The aggregate is never null — it always has a determined spend — so/metricsis unaffected in practice, thoughpromexportnow reads it through aNet() (float64, bool)accessor and omits the series rather than publishing an unknown as0, which on that gauge reads as exactly break-even.cost_sourcenames the case, because$0 spentand$0 of evidenceare the same number and the opposite claim:component(every call priced itself — trust it),host_total(the host's superset figure),partial(some calls unpriced, so the total is a floor),unpriced(this row made calls and priced none — nothing is known),none(no calls;0is true).unpricedCallsreplaces the singleanySpendboolean: when any calls are unpriced the aggregate publishes the larger of the recorded floor and the host's superset figure, and labels which one it chose. A total that quietly omits real dollars is the defect, not the loud one.3. The docs described the old scoping
docs/reference/routes.md—acted_fresh/acted_replayadded to the per-component table, withactednow flagged as including free replays; a new Extraction economics section documentsby_component,cost_sourceand the nullable net, and carries a warning that the enclosing block is a sum.docs/components/extract_llm.md— the table that presentedcalls,extraction_cost_usd,avg_latency_msandgross_saved_tokensas this component's own figures now opens with a danger admonition stating they are sums across components, with the measured numbers (101 calls / 59,009 ms / −$1.162 againstcands: 0on 374 requests) as the worked example, and directs every per-component claim toby_component. Theacted-counts-replays note is there too.4. The false claim in this body
Verified and removed. Grepping
deploy/forgross_saved_tokens,calls_avoided,extraction_cost_usdandavg_latency_msreturns nothing — no harbor script reads any key in this block. What harbor does read isruns,actedandsaved_tokensoff the per-component objects, andmeasure.pyreads them by direct index (v["acted"]), so removing one is aKeyErrorrather than a silent zero. That part of the rationale was sound; it was attached to the wrong table.The real reason the extract block's names are frozen is
/metrics:proxy/promexport.gopublishes them ascg_extract_calls_total,cg_extract_cost_usd,cg_extract_net_value_usdandcg_extract_latency_ms, anddash/metrics_export.godocuments the last as the endpoint's only dollar figure. Those are queried by off-repo, unversioned alert rules and dashboards, where a rename breaks monitoring silently — a worse failure than breaking the harness, which would at least crash. Corrected inmetrics/extract.go,docs/reference/routes.mdanddocs/components/extract_llm.md, with the distinction between the two consumers stated rather than blurred.The dashboard finding → #179
dash/event.go:527does keep the exact reading #176 describes (row.Acted = row.Mutated && row.SavedGross > 0, withr.Replaysavailable and unread), and/api/components'acted,acted_tokens,act_rateandact_rate_structuralall inherit it. Pre-existing onmainrather than introduced here, so per the standing rule it is filed as its own issue with the evidence — #179 — and left out of this PR so it can ship without waiting. It is in the known gaps below. Theact_rate_structuralderivation (mutated − acted) will want re-checking against whatever shape the split takes there.Vacuity — round 2
Six new single-point mutations. All six killed — but one only after the tests were strengthened, and that is worth reading.
fallbackAskreports no usage/statsdelta $0;cost_source"unpriced"where"component"is dueStrategy"prefix_ask"where"fallback"is duenet_value_usd = 0.05wherenullis dueanySpendboolean"component"where"partial"is duecost_sourcetaggedjson:"-"M13 is the one to read. It survived the first run, because the
cost_sourceassertions I had written read the Go struct field rather than the encoded payload — precisely the "a field can be computed correctly and dropped by the handler" failure this repo's rendered-output rule exists for, committed in the same change that cites the rule.TestByComponentSurvivesJSONandTestStatsRendersPerComponentExtractionAttributionnow assertcost_sourceand thenullnet on the marshalled payload and on the/statsbody, and M13 then fails on both surfaces (the encoded by_component row is missing "cost_source",/stats serves no extract.cost_source). Recorded here rather than quietly fixed, because a mutant that survives and then dies after a test change is the only evidence that the test change did anything.M6's redundant-guard situation is unchanged and still documented in the test.
Round 3 — every remaining gap is now either fixed here or tracked
Per the rule that anything doable inside this PR is done inside it and everything else gets a number, the four items left as prose gaps after round 2 are resolved. Commit
6e01798.Fixed here:
cost_source: partialnow names what the total is short of. The label said the total was a floor without saying what it was missing, so finding the culprit meant scanning everyby_componentrow forcost_source: unpriced— re-deriving an answer the snapshot had already computed, since it is the same test that sets the aggregate's label. A reader who has to re-derive it will read the label and stop, and then the floor gets quoted as the bill.extract.unpriced_componentsnames them, sorted, on the aggregate only, omitted when every call priced itself. Published under both incomplete regimes: underpartialit names what the floor is short of, underhost_totalit names what forced the fallback. Documented inroutes.mdandextract_llm.md.Tracked, with the reasoning in the issue rather than only here:
/api/componentscounts free frozen replays as acts (dash/event.go:527), soacted/acted_tokens/act_ratekeep the exact conflation #176 reports — on the surface an operator actually looks atmain, unrelated to what this PR tests. Own issue, own PR, so it can ship without waitingcg_extract_*has nocomponentlabel — and after round 2 it inherits thecost_sourceregime without being able to express it, so a gauge reading−0.71may be priced arithmetic, a floor, or the host's superset figure, identicallycheapmodel.Usage()is still process-global, and its comment still asserts the premise that produced #176 ("today the LLM component in a config is extract")cost_source: host_total, documented as a superset), so the wrongness is declared at the point of use rather than silently inheritedErrNoPrefixask should count as a call. Assigned to @OsherElhadadOn #182: I took the correct accounting — keep it uncounted. An
ErrNoPrefixis refused insideproxy/prefixask.gobefore any request leaves the process, so it is not a call; it contributes a ~0 ms sample to the p50 the exploration brake reads, and it inflates the denominator ofavg_latency_msand cost-per-call. A counter namedcallsthat includes calls never made is how #176 happened. But the continuity cost is real and named in the issue:extract.callsandcg_extract_calls_total{outcome="made"}will read lower for the same traffic, roughly one per session, and "the component stopped working" and "the counter got honest" look identical from outside. The issue gives the concrete alternative — count it under a distinct name likerefusals, which I think is better than what I shipped and which I skipped only to avoid widening this PR further — and says explicitly what would change my mind.Dropped from the gaps:
docs/experiments/loca/iter023/results.mdlives onfeat/coref-recut, notmain, so this PR cannot touch it; @amiddavid is correcting it. The general point stands below without implying a fix was owed here.Vacuity — round 3
Three mutations on the new field, all three killed, each on both surfaces:
partialnaming nothing)partialstill leaves the reader to scan every row"; "/stats serves an incomplete total with no unpriced_components"json:"-")M16 is the M13 shape, and it is why both assertions read the marshalled payload rather than the Go field:
TestTheAggregateNamesWhichComponentIsUnpricedgoes throughjson.Marshal,TestStatsNamesTheUnpricedComponentreads the/statsHTTP body. Both assert the precondition that the total is actually incomplete before asserting the list, so neither can pass vacuously on a snapshot with nothing to report, and both assert the field is omitted when everything priced itself — an empty list on a complete total would read as a warning where there is none.The proxy test uses a component name of its own rather than a real one: these counters are process-global for the package run, and
TestStatsRendersPerComponentExtractionAttributionasserts absolute values onextract_llmandextract_llm_sweep. Making either unpriced there would break that test through shared state for a reason unrelated to either test's subject.Running total across three rounds: 15 mutations, 15 killed — two of them (M6, M13) only after being reported as survivors first.
Round 4 — a failed fallback's wall time never reached the ledger row
The one item from re-review, fixed in
7fed0d0. Non-blocking as filed, and correct as diagnosed.All three fallback sites are
if reply, err = runFallback(); err != nil { return nil, r }, and everyfoldFallback()call sat after those early returns — so a fallback that failed was never folded.runFallbackhas already booked the leg into metrics viarecordLeg, so/statscounted the call and its seconds whiler.reckept only the prefix ask'sLatencyMsand aStrategynaming a leg that was no longer the only one that ran.Latency, not dollars, and your reasoning for that holds: on an error the sink is empty, because
recordUsageCacheis reached only after a successful decode on both backends and neither errors after billing. Same class as the round-2 finding, not a repeat of its severity — but the fallback is the slow leg by construction, so a failed one puts tens of seconds intoavg_latency_msagainst a per-call row showing milliseconds.Site 681's vanishing row is covered.
foldFallbacknow establishes the identity fields —Component,Model,CandidateTokens,GateReason— when the row does not exist yet. Without that, deferring the fold alone would have populated latency and tokens on a row whoseComponentwas still"", soOffloadwould have dropped it exactly as before: a fold that ran and changed nothing observable. That was the half most available to leave undone, and it has its own mutant (M18).I took
defer foldFallback(), with one correction that turns out to be the whole fix. It does not work against a local: every early return here isreturn nil, ronvar r sweepResult, and a deferred mutation of a local happens after the return value has been copied — so the fold would compile, run, and be silently discarded on exactly the error paths it exists to cover. ThesweepResultis a named result now; the other result stays blank-named, because only this one needs the treatment. One arming point covers all four exits that can carry a fallback. The explicit call afterr.recis assigned stays: that assignment overwrites the deferred fold's work-in-progress, and re-folding is free sincefoldFallbackreads the accumulators rather than adding to them.Vacuity — round 4
/stats. Ask-then-fail:Strategy "prefix_ask"andLatencyMs 0against ~8 msComponent != ""guarddefer foldFallback()is still present and still runs, and does nothing. A fix that looks present and is inertOn the assertion surface, since the instruction was to assert on the rendered one: there isn't a marshalled surface for a
ModelCallinside/stats— ledger rows travel to the dashEvent, not this payload — so a JSON-tag assertion would testdash's converter rather than this fix. What actually broke is that two surfaces disagreed, so that is what is pinned: if/statscounts the call, the ledger must carry a row for it. The assertion readsrep.CallsafterOffload, i.e. past the guard that was doing the dropping, which is the same discipline by a different route. Both tests assert the precondition that the fallback genuinely errored (sweep_fallback_failed) before asserting the row, so neither can pass on a fixture that silently declined.Running total across four rounds: 18 mutations, 18 killed — three of them (M6, M13, and M19's named-result trap) only after the shape was corrected or reported as a survivor first.
Checks
gofmt -l .— clean.CGO_ENABLED=1 go vet ./...— clean, exit 0.CGO_ENABLED=1 go test ./...— green, exit 0, 28 packages ok. Run on the eval box (Go 1.26.4) against the committed tree.No benchmark was run.
Open, and tracked
/metricsper-component labels, and the cost gauges' inability to expresscost_source.cheapmodel.Usage()scoping and its stale comment.ErrNoPrefixaccounting decision, awaiting @OsherElhadad.Two things that are not fixable by code and so have no issue:
Assisted-By: Claude Opus 5 (1M context) <noreply@anthropic.com>