From 3b2af075099438bcca98b1c8e2582d83f89506ab Mon Sep 17 00:00:00 2001 From: reference-week Date: Sun, 6 Sep 2026 07:46:55 +0200 Subject: [PATCH] fix(telemetry): a counter says what was measured MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two tools declared a limit that was true when it was written and is not any more. Both are now measured, and the captures that settle them ship as fixtures. Copilot. `copilot.ts` said the exclusivity of `input` against `cache_read` was unconfirmed, because the only capture held `cache_read: 0` — where an inclusive and an exclusive `input` produce the same number. It named what would close it: one session with a non-zero `cache_read`. Captured on 1.0.82: tokenDetails input 9 · cache_read 42038 · cache_write 21404 · output 408 usage.inputTokens 63451 9 + 42038 + 21404 = 63451, and Copilot's own terminal line for that run read `↑ 63.5k (42.0k cached, 21.4k written)`. An `input` that already counted the cached prompt would read 63451, not 9. The four counters are disjoint, so the report is right to add them; it would otherwise have over-counted that session by 42038 of 63451. OpenCode. `opencode-export.ts` said no capture ever put a large `cache.read` beside `input` for a non-Anthropic provider — the one comparison that shows `input` failing to shrink if it already counted the cached tokens. Captured from `opencode export --sanitize`, providerID "opencode", modelID "ling-3.0-flash-fin-free", three billed turns of one session: input 28242 → 269 → 196 read 640 → 28928 → 29184 total 29089 · 29356 · 29438, each == input + output + reasoning + cache `input` falls as `cache.read` climbs, and OpenCode's own `total` holds the identity on all three turns, which it could not if the counters overlapped. What each tool still cannot say is narrower, and both limitation strings now say that instead of the old one: for OpenCode, a provider reporting prompt tokens inclusive of the cached ones has still never been captured here. Both guards bite. Mutating `copilot-events.ts` to fold `cache_read` into `input` turns exactly the new case red — `expected 42047 to be 9`. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01VWNxk63AGKkqE8HRqHLjGp --- cli/src/domain/formats/copilot-events.ts | 7 +- cli/src/domain/formats/opencode-export.ts | 28 ++-- cli/src/domain/tools/ai/copilot.ts | 22 ++- cli/src/domain/tools/ai/opencode.ts | 6 +- .../formats/copilot-events.unit.test.ts | 22 +++ .../formats/opencode-export.unit.test.ts | 30 ++++ .../cli-owns-read/expected-envelope.json | 4 +- .../events.jsonl | 2 + .../opencode-export-non-anthropic-cache.json | 155 ++++++++++++++++++ 9 files changed, 248 insertions(+), 28 deletions(-) create mode 100644 cli/tests/fixtures/local-cost/.copilot/session-state/55555555-5555-4555-8555-555555555555/events.jsonl create mode 100644 cli/tests/fixtures/telemetry-sink/opencode-export-non-anthropic-cache.json diff --git a/cli/src/domain/formats/copilot-events.ts b/cli/src/domain/formats/copilot-events.ts index 85d6a6e8e..913d0f280 100644 --- a/cli/src/domain/formats/copilot-events.ts +++ b/cli/src/domain/formats/copilot-events.ts @@ -7,7 +7,12 @@ import type { LocalCostCandidateRecord } from "../ports/session-cost-reader.js"; // `tokenDetails.input.tokenCount` (10) + `tokenDetails.cache_write.tokenCount` (21070) = // `modelMetrics..usage.inputTokens` (21080) — the `usage` object is *inclusive* of // the cache-write figure, `tokenDetails` already exclusive, matching every other reader's -// convention here. `modelMetrics..requests.cost` (and its session-level twin, +// convention here. **Confirmed the same way for `cache_read` on 1.0.82, 2026-09-06** +// (tests/fixtures/local-cost/.copilot/session-state/55555555-.../events.jsonl): 9 + 42038 + +// 21404 = 63451 = `usage.inputTokens`, with Copilot's own terminal line reading +// `↑ 63.5k (42.0k cached, 21.4k written)`. That is the capture the earlier one could not +// give: at `cache_read: 0` an inclusive and an exclusive `input` produce the same number, +// at 42038 they do not — an inclusive one would read 63451, not 9. `modelMetrics..requests.cost` (and its session-level twin, // `totalPremiumRequests`) is a count times a per-model multiplier, invariant to // consumption — measured across fourteen local sessions, it read `0.33` for every // single-request `claude-haiku-4.5` session regardless of tokens spent — so neither is ever diff --git a/cli/src/domain/formats/opencode-export.ts b/cli/src/domain/formats/opencode-export.ts index 4c88be294..24772ce6c 100644 --- a/cli/src/domain/formats/opencode-export.ts +++ b/cli/src/domain/formats/opencode-export.ts @@ -17,17 +17,23 @@ import type { LocalCostCandidateRecord } from "../ports/session-cost-reader.js"; // machine — `opencode run --model opencode/big-pickle ...` (providerID "opencode", an // `@ai-sdk/openai-compatible` backend). Its `total == input + output + cache.read + // cache.write + reasoning` reconciled too (`14072 == 13926 + 13 + 128 + 0 + 5`), but that -// does not settle the question the way the "anthropic" capture does: a second, continued -// turn in the same session showed `cache.read: 0, cache.write: 0` throughout — this -// backend never exercised its cache — so no capture here ever put a large `cache.read` -// beside `input` for a non-Anthropic provider, which is the one comparison that would show -// `input` failing to shrink if it already counted the cached tokens. Anthropic's own -// exclusivity is independent of this reconciliation (it is the documented behaviour of its -// Messages API, corroborated elsewhere in this repo against Claude Code's own `/usage`) — -// so it alone is measured. Whether a provider that reports prompt tokens *inclusive* of -// cached ones (the way native OpenAI's Chat Completions usage does) would double-count -// through this same mapping remains open. See plugins/aidd-telemetry/README.md for the declaration -// this keeps beside the limit. +// did not settle the question then: a second, continued turn in that session showed +// `cache.read: 0, cache.write: 0` throughout — the backend never exercised its cache — so +// no capture put a large `cache.read` beside `input` for a non-Anthropic provider, which +// is the one comparison that shows `input` failing to shrink if it already counted the +// cached tokens. +// +// **Captured 2026-09-06** (providerID "opencode", modelID "ling-3.0-flash-fin-free" — +// tests/fixtures/telemetry-sink/opencode-export-non-anthropic-cache.json): three billed +// turns of one session with the cache genuinely exercised. `input` falls 28242 → 269 → 196 +// as `cache.read` climbs 640 → 28928 → 29184, and `total == input + output + reasoning + +// cache.read + cache.write` holds on all three (29089, 29356, 29438). An `input` inclusive +// of the cached tokens could neither shrink that way nor leave that identity standing, so +// the counters are disjoint for this provider too. Anthropic's own exclusivity is +// independent of this (the documented behaviour of its Messages API, corroborated elsewhere +// in this repo against Claude Code's own `/usage`). What stays open is narrower than it +// was: a provider that reports prompt tokens *inclusive* of cached ones, the way native +// OpenAI's Chat Completions usage does, has still never been captured here. // // That open question does not reopen the choice above to never read `info.providerID`: a // per-record check would need a provider field on the stored record to hang a per-provider diff --git a/cli/src/domain/tools/ai/copilot.ts b/cli/src/domain/tools/ai/copilot.ts index 4efce1502..4aa454acb 100644 --- a/cli/src/domain/tools/ai/copilot.ts +++ b/cli/src/domain/tools/ai/copilot.ts @@ -356,20 +356,18 @@ export const copilot: AiTool< telemetryLocalRead: { kind: "declared", supplies: { tokenCounters: true, amount: false, toolStatedStep: false, agentName: false }, - // The exclusivity of `input` against `cache_read` is NOT established. The only capture - // this repository holds (tests/fixtures/local-cost/.copilot/.../events.jsonl) reports - // `cache_read: 0`, so "input excludes the cached prompt" and "input already includes it" - // produce the same number and cannot be told apart from it. Exclusivity against - // `cache_write` is measured (10 + 21070), which is what makes only this one open. - // It matters because the report adds the four counters as disjoint: if `input` turns out - // to include `cache_read`, a Copilot session's total is over-counted by the cached share. - // Closing it takes one capture of a session with a non-zero `cache_read` — see #654's - // sibling work and plugins/aidd-telemetry/README.md. + // The exclusivity of `input` against `cache_read` is measured, on the capture the + // earlier comment here asked for by name: a session with a non-zero `cache_read` + // (1.0.82, 2026-09-06, tests/fixtures/local-cost/.copilot/session-state/55555555-…). + // 9 (`input`) + 42038 (`cache_read`) + 21404 (`cache_write`) = 63451, exactly + // `modelMetrics..usage.inputTokens`, so the four counters this reader stores are + // disjoint and the report is right to add them. It mattered because an `input` that + // included `cache_read` would have over-counted every Copilot session by its cached + // share — 42038 of 63451 in this one. limitation: "Its own file names outputTokens per turn, but session.shutdown carries all four " + - "counters for the whole session — a session total, never a sum of requests. Whether " + - "its input count excludes the cached prompt is unconfirmed: the only session captured " + - "read back zero cache, which cannot tell the two apart.", + "counters for the whole session — a session total, never a sum of requests. Its four " + + "counters are measured disjoint, cached prompt included.", }, // Copilot's canonical payload carries no tool_input, but a declaration reads its toolArgs // JSON string as plain text instead - the same tolerance that already lets a step be read diff --git a/cli/src/domain/tools/ai/opencode.ts b/cli/src/domain/tools/ai/opencode.ts index 17bf81c20..b70f08843 100644 --- a/cli/src/domain/tools/ai/opencode.ts +++ b/cli/src/domain/tools/ai/opencode.ts @@ -186,8 +186,10 @@ export const opencode: AiTool< // provider that reports prompt tokens inclusive of the cached ones, the way native // OpenAI's usage does, has never been captured here. See plugins/aidd-telemetry/README.md. limitation: - "Its four counters are measured correct for the anthropic provider — not " + - "independently confirmed for any other provider OpenCode can route to.", + "Its four counters are measured disjoint for the anthropic provider and for one " + + "OpenAI-compatible provider whose cache was exercised — not confirmed for a " + + "provider that reports prompt tokens inclusive of the cached ones, which none " + + "captured here does.", }, // The journal hook detects this host by a self-declared `tool: "opencode"` field, not by // a vendor payload shape — OpenCode has none. hooks/opencode-plugin.js builds that payload diff --git a/cli/tests/domain/formats/copilot-events.unit.test.ts b/cli/tests/domain/formats/copilot-events.unit.test.ts index aaa2bf4be..fcd13c4fb 100644 --- a/cli/tests/domain/formats/copilot-events.unit.test.ts +++ b/cli/tests/domain/formats/copilot-events.unit.test.ts @@ -5,6 +5,7 @@ import { mapCopilotEventsToSinkRecords } from "../../../src/domain/formats/copil const SESSION = "33333333-3333-4333-8333-333333333333"; const EMPTY_SESSION = "44444444-4444-4444-8444-444444444444"; +const CACHED_SESSION = "55555555-5555-4555-8555-555555555555"; // Both fixtures are real, redacted excerpts of a captured `@github/copilot@1.0.80` file — // system.message, user.message, assistant.message and every reasoning field stripped, per @@ -17,6 +18,7 @@ function loadFixture(relativePath: string): string { const FULL_PATH = `.copilot/session-state/${SESSION}/events.jsonl`; const EMPTY_PATH = `.copilot/session-state/${EMPTY_SESSION}/events.jsonl`; +const CACHED_PATH = `.copilot/session-state/${CACHED_SESSION}/events.jsonl`; describe("mapCopilotEventsToSinkRecords", () => { it("yields one kind: session record, from session.shutdown's own tokenDetails", () => { @@ -71,6 +73,26 @@ describe("mapCopilotEventsToSinkRecords", () => { expect(record?.input_tokens).not.toBe(21080); }); + it("reads the four counters disjoint when the cached prompt is large, the case left open", () => { + // Measured live, @github/copilot@1.0.82, 2026-09-06: 9 (tokenDetails.input) + 42038 + // (cache_read) + 21404 (cache_write) = 63451 = modelMetrics..usage.inputTokens, + // and Copilot's own terminal line for that run read `↑ 63.5k (42.0k cached, 21.4k + // written)`. This is the capture copilot.ts asked for by name: at cache_read 0, "input + // excludes the cached prompt" and "input already includes it" produce the same number + // and cannot be told apart. At 42038 they cannot be confused - an input that included + // the cached prompt would read 63451, not 9. + const [record] = mapCopilotEventsToSinkRecords(loadFixture(CACHED_PATH), CACHED_SESSION); + + expect(record?.input_tokens).toBe(9); + expect(record?.cache_read_tokens).toBe(42038); + expect(record?.cache_creation_tokens).toBe(21404); + expect( + (record?.input_tokens ?? 0) + + (record?.cache_read_tokens ?? 0) + + (record?.cache_creation_tokens ?? 0) + ).toBe(63451); + }); + it("never carries cost_usd — totalPremiumRequests is a multiplier, not a currency", () => { const [record] = mapCopilotEventsToSinkRecords(loadFixture(FULL_PATH), SESSION); diff --git a/cli/tests/domain/formats/opencode-export.unit.test.ts b/cli/tests/domain/formats/opencode-export.unit.test.ts index 3f5a1d159..f32bf0e49 100644 --- a/cli/tests/domain/formats/opencode-export.unit.test.ts +++ b/cli/tests/domain/formats/opencode-export.unit.test.ts @@ -15,6 +15,36 @@ function loadFixture(name: string): unknown { } describe("mapOpencodeExportToSinkRecords", () => { + // The comparison opencode-export.ts's own header named as missing: a large `cache.read` + // beside `input`, for a provider that is not Anthropic. Captured live 2026-09-06 from + // `opencode export --sanitize`, opencode 1.14.20, providerID "opencode", modelID + // "ling-3.0-flash-fin-free" - three billed turns of one session, cache genuinely + // exercised across them. `input` falls from 28242 to 269 as `cache.read` climbs from + // 640 to 28928: an `input` that already counted the cached tokens could not shrink that + // way. OpenCode's own `total` confirms it by arithmetic on every turn - + // `total == input + output + reasoning + cache.read + cache.write` - which only holds if + // the counters are disjoint. + it("reads a non-Anthropic provider's counters as disjoint, the comparison no capture held", () => { + const records = mapOpencodeExportToSinkRecords( + loadFixture("opencode-export-non-anthropic-cache.json"), + "ses_test_non_anthropic" + ); + + expect( + records.map((record) => ({ + input: record.input_tokens, + output: record.output_tokens, + cacheRead: record.cache_read_tokens, + cacheCreation: record.cache_creation_tokens, + })) + ).toEqual([ + { input: 28242, output: 193, cacheRead: 640, cacheCreation: 0 }, + { input: 269, output: 137, cacheRead: 28928, cacheCreation: 0 }, + { input: 196, output: 56, cacheRead: 29184, cacheCreation: 0 }, + ]); + expect(records.every((record) => record.model === "ling-3.0-flash-fin-free")).toBe(true); + }); + it("yields one record per billed message, by value, under the stored field names", () => { const records = mapOpencodeExportToSinkRecords(loadFixture("opencode-export.json"), SESSION_ID); diff --git a/cli/tests/fixtures/cli-owns-read/expected-envelope.json b/cli/tests/fixtures/cli-owns-read/expected-envelope.json index 65a85f7cf..dd6ee3795 100644 --- a/cli/tests/fixtures/cli-owns-read/expected-envelope.json +++ b/cli/tests/fixtures/cli-owns-read/expected-envelope.json @@ -165,7 +165,7 @@ { "tool": "copilot", "coverage": "covered", - "reason": "Its own file names outputTokens per turn, but session.shutdown carries all four counters for the whole session \u2014 a session total, never a sum of requests. Whether its input count excludes the cached prompt is unconfirmed: the only session captured read back zero cache, which cannot tell the two apart.", + "reason": "Its own file names outputTokens per turn, but session.shutdown carries all four counters for the whole session \u2014 a session total, never a sum of requests. Its four counters are measured disjoint, cached prompt included.", "capability": { "local_read": { "token_counters": true, @@ -191,7 +191,7 @@ { "tool": "opencode", "coverage": "covered", - "reason": "Its four counters are measured correct for the anthropic provider \u2014 not independently confirmed for any other provider OpenCode can route to.", + "reason": "Its four counters are measured disjoint for the anthropic provider and for one OpenAI-compatible provider whose cache was exercised \u2014 not confirmed for a provider that reports prompt tokens inclusive of the cached ones, which none captured here does.", "capability": { "local_read": { "token_counters": true, diff --git a/cli/tests/fixtures/local-cost/.copilot/session-state/55555555-5555-4555-8555-555555555555/events.jsonl b/cli/tests/fixtures/local-cost/.copilot/session-state/55555555-5555-4555-8555-555555555555/events.jsonl new file mode 100644 index 000000000..8fe3cec0d --- /dev/null +++ b/cli/tests/fixtures/local-cost/.copilot/session-state/55555555-5555-4555-8555-555555555555/events.jsonl @@ -0,0 +1,2 @@ +{"type":"session.start","data":{"sessionId":"55555555-5555-4555-8555-555555555555","producer":"copilot-agent","copilotVersion":"1.0.82","startTime":"2026-09-06T05:38:13.535Z","contextTier":null,"alreadyInUse":false,"remoteSteerable":false},"id":"11111111-1111-4111-8111-111111111111","timestamp":"2026-09-06T05:38:13.560Z","parentId":null} +{"type":"session.shutdown","data":{"shutdownType":"routine","totalPremiumRequests":1,"totalNanoAiu":668316000,"tokenDetails":{"input":{"tokenCount":9},"cache_read":{"tokenCount":42038},"cache_write":{"tokenCount":21404},"output":{"tokenCount":408}},"totalApiDurationMs":8147,"sessionStartTime":1788673093535,"eventsFileSizeBytes":104412,"codeChanges":{"linesAdded":3,"linesRemoved":0,"filesModified":["docs/note.md"]},"modelMetrics":{"gpt-5.6-luna":{"requests":{"count":3,"cost":1},"usage":{"inputTokens":63451,"outputTokens":408,"cacheReadTokens":42038,"cacheWriteTokens":21404,"reasoningTokens":55},"totalNanoAiu":668316000,"tokenDetails":{"input":{"tokenCount":9},"cache_read":{"tokenCount":42038},"cache_write":{"tokenCount":21404},"output":{"tokenCount":408}}}},"currentModel":"gpt-5.6-luna","currentTokens":22282,"systemTokens":13260,"conversationTokens":691,"toolDefinitionsTokens":8328},"id":"22222222-2222-4222-8222-222222222222","timestamp":"2026-09-06T05:38:32.658Z","parentId":"11111111-1111-4111-8111-111111111111"} diff --git a/cli/tests/fixtures/telemetry-sink/opencode-export-non-anthropic-cache.json b/cli/tests/fixtures/telemetry-sink/opencode-export-non-anthropic-cache.json new file mode 100644 index 000000000..39e79e5c9 --- /dev/null +++ b/cli/tests/fixtures/telemetry-sink/opencode-export-non-anthropic-cache.json @@ -0,0 +1,155 @@ +{ + "info": { + "id": "ses_test_non_anthropic", + "slug": "quick-circuit", + "projectID": "0000000000000000000000000000000000000000", + "directory": "[redacted:session-directory]", + "title": "[redacted:session-title]", + "version": "1.14.20", + "permission": [ + { + "permission": "question", + "pattern": "*", + "action": "deny" + }, + { + "permission": "plan_enter", + "pattern": "*", + "action": "deny" + }, + { + "permission": "plan_exit", + "pattern": "*", + "action": "deny" + } + ], + "time": { + "created": 1788672555178, + "updated": 1788672567780 + } + }, + "messages": [ + { + "info": { + "role": "user", + "time": { + "created": 1788672555378 + }, + "agent": "build", + "model": { + "providerID": "opencode", + "modelID": "ling-3.0-flash-fin-free" + }, + "summary": { + "diffs": [ + { + "file": "[redacted:message-diff-file:0]", + "patch": "[redacted:message-diff-patch:0]", + "additions": 1, + "deletions": 0, + "status": "added" + } + ] + }, + "id": "msg_075313972001oFmFIrMP8QKaMI", + "sessionID": "ses_test_non_anthropic" + } + }, + { + "info": { + "parentID": "msg_075313972001oFmFIrMP8QKaMI", + "role": "assistant", + "mode": "build", + "agent": "build", + "path": { + "cwd": "[redacted:cwd:msg_07531399f001zRIlCAkqvcdz38]", + "root": "[redacted:root:msg_07531399f001zRIlCAkqvcdz38]" + }, + "cost": 0, + "tokens": { + "total": 29089, + "input": 28242, + "output": 193, + "reasoning": 14, + "cache": { + "write": 0, + "read": 640 + } + }, + "modelID": "ling-3.0-flash-fin-free", + "providerID": "opencode", + "time": { + "created": 1788672555423, + "completed": 1788672565911 + }, + "finish": "tool-calls", + "id": "msg_07531399f001zRIlCAkqvcdz38", + "sessionID": "ses_test_non_anthropic" + } + }, + { + "info": { + "parentID": "msg_075313972001oFmFIrMP8QKaMI", + "role": "assistant", + "mode": "build", + "agent": "build", + "path": { + "cwd": "[redacted:cwd:msg_075316299001VsJLAfQn01vDdX]", + "root": "[redacted:root:msg_075316299001VsJLAfQn01vDdX]" + }, + "cost": 0, + "tokens": { + "total": 29356, + "input": 269, + "output": 137, + "reasoning": 22, + "cache": { + "write": 0, + "read": 28928 + } + }, + "modelID": "ling-3.0-flash-fin-free", + "providerID": "opencode", + "time": { + "created": 1788672565913, + "completed": 1788672567732 + }, + "finish": "tool-calls", + "id": "msg_075316299001VsJLAfQn01vDdX", + "sessionID": "ses_test_non_anthropic" + } + }, + { + "info": { + "parentID": "msg_075313972001oFmFIrMP8QKaMI", + "role": "assistant", + "mode": "build", + "agent": "build", + "path": { + "cwd": "[redacted:cwd:msg_0753169b5001dX3zYvM2u0UyHn]", + "root": "[redacted:root:msg_0753169b5001dX3zYvM2u0UyHn]" + }, + "cost": 0, + "tokens": { + "total": 29438, + "input": 196, + "output": 56, + "reasoning": 2, + "cache": { + "write": 0, + "read": 29184 + } + }, + "modelID": "ling-3.0-flash-fin-free", + "providerID": "opencode", + "time": { + "created": 1788672567733, + "completed": 1788672569281 + }, + "finish": "stop", + "id": "msg_0753169b5001dX3zYvM2u0UyHn", + "sessionID": "ses_test_non_anthropic" + } + } + ] +}