From 98051b4263d5c19dbc7f0116b27e590de65e8676 Mon Sep 17 00:00:00 2001 From: Resham Joshi <65915470+iamtoruk@users.noreply.github.com> Date: Thu, 16 Jul 2026 10:37:58 -0700 Subject: [PATCH] fix(copilot): bill CLI input and cache tokens from session.shutdown (#684) * fix(copilot): bill CLI input and cache tokens from session.shutdown Copilot CLI sessions (~/.copilot/session-state/*/events.jsonl) recorded only outputTokens, because the parser read assistant.message events and ignored the session.shutdown rollup. That rollup is the sole on-disk source of a CLI session's input, cache-read and cache-write tokens, so cost was underreported (in the reported case 35k+ cache-read tokens were dropped entirely). Handle session.shutdown in the CLI (non-transcript) JSONL path and emit one supplementary call per model from modelMetrics..usage. The per-turn assistant.message events keep owning output tokens, tools and turn structure; the shutdown call contributes only the input and cache tokens they lack, with output excluded, so no dimension double-counts and the combined cost equals the full CLI-measured cost. usage.inputTokens is cache-inclusive (input + cache_read + cache_write), so the cache components are subtracted to recover the uncached input calculateCost expects. These are real counts written by the CLI, so costIsEstimated is false. Sessions without session.shutdown (crashed or still running) keep the exact previous output-only behavior, and the VS Code, JetBrains and OTel paths are untouched. Bump the copilot entry in PROVIDER_PARSE_VERSIONS so already-cached CLI sessions re-parse and pick up the corrected tokens and cost. * fix(copilot): never emit an empty-timestamp shutdown call A session.shutdown without its own timestamp and without sessionStartTime produced a call with an empty timestamp, which the date-range filters in parser.ts drop silently, erasing exactly the tokens this feature bills. Fall back to the last stamped event in the session. * fix(cache): durable orphans survive provider fingerprint changes Bumping a durable provider's PROVIDER_PARSE_VERSIONS changed its env fingerprint, and getOrCreateProviderSection replaced the whole section on mismatch. For copilot OTel orphans the discarded cache entry is the only remaining record of pruned spans, so the first post-upgrade run silently and permanently erased month-to-date history. Carry forward exactly the entries whose source no longer exists; present sources still drop and re-parse under the new fingerprint, which is the point of a bump. Regression test forges a pre-upgrade fingerprint on a pruned-source orphan and asserts it stays counted and cached across the transition. --- src/parser.ts | 15 ++- src/providers/copilot.ts | 96 ++++++++++++++ src/session-cache.ts | 2 +- tests/parser.test.ts | 43 ++++++ tests/providers/copilot.test.ts | 224 ++++++++++++++++++++++++++++++++ 5 files changed, 378 insertions(+), 2 deletions(-) diff --git a/src/parser.ts b/src/parser.ts index f8af6a6..47f8cc7 100644 --- a/src/parser.ts +++ b/src/parser.ts @@ -1,3 +1,4 @@ +import { existsSync } from 'fs' import { lstat, readFile, readdir, stat } from 'fs/promises' import { basename, dirname, join, resolve, sep } from 'path' import { readSessionLines } from './fs-utils.js' @@ -2040,7 +2041,19 @@ function getOrCreateProviderSection(cache: SessionCache, provider: string): Prov const envFp = computeEnvFingerprint(provider) const existing = cache.providers[provider] if (existing && existing.envFingerprint === envFp) return existing - const section = { envFingerprint: envFp, files: {} } + const section: ProviderSection = { envFingerprint: envFp, files: {} } + // A fingerprint change (env override or parse-version bump) must re-parse + // every present source, but for durable providers the cache is the ONLY + // remaining record of usage whose source rows were already pruned (OTel + // orphans). Discarding those with the section would permanently erase + // month-to-date history that cannot be re-derived, so carry forward exactly + // the entries whose source no longer exists; everything present on disk is + // dropped and re-parsed under the new fingerprint. + if (existing && DURABLE_PROVIDER_NAMES.has(provider)) { + for (const [path, file] of Object.entries(existing.files)) { + if (!existsSync(path)) section.files[path] = file + } + } cache.providers[provider] = section return section } diff --git a/src/providers/copilot.ts b/src/providers/copilot.ts index e756197..3dde3c2 100644 --- a/src/providers/copilot.ts +++ b/src/providers/copilot.ts @@ -195,12 +195,28 @@ type SubagentSelectedData = { tools?: string[] } +// Per-model usage rollup the CLI writes into session.shutdown. inputTokens is +// cache-INCLUSIVE (input + cache_read + cache_write); see the shutdown handler. +type ShutdownModelUsage = { + inputTokens?: number + outputTokens?: number + cacheReadTokens?: number + cacheWriteTokens?: number + reasoningTokens?: number +} + +type SessionShutdownData = { + modelMetrics?: Record + sessionStartTime?: number +} + type CopilotEvent = | { type: 'session.start'; data: SessionStartData; timestamp?: string } | { type: 'session.model_change'; data: ModelChangeData; timestamp?: string } | { type: 'user.message'; data: UserMessageData; timestamp?: string } | { type: 'assistant.message'; data: AssistantMessageData; timestamp?: string } | { type: 'subagent.selected'; data: SubagentSelectedData; timestamp?: string } + | { type: 'session.shutdown'; data: SessionShutdownData; timestamp?: string } type ChatJournalPathSegment = string | number type ChatSessionRequest = Record @@ -722,6 +738,11 @@ function createJsonlParser( if (!currentModel) return // no toolCallIds to infer model from } + // Shutdown rollups may lack their own timestamp; remember the last + // stamped event so the supplementary call is never left with an empty + // timestamp, which the date-range filters silently drop. + let lastEventTimestamp = '' + for (const line of lines) { let event: CopilotEvent try { @@ -729,6 +750,7 @@ function createJsonlParser( } catch { continue } + if (typeof event.timestamp === 'string' && event.timestamp) lastEventTimestamp = event.timestamp if (event.type === 'session.start') { if (!isTranscript) { @@ -752,6 +774,80 @@ function createJsonlParser( continue } + if (event.type === 'session.shutdown') { + // The Copilot CLI writes a per-model token/cost rollup here at + // shutdown: the only place a CLI session records input, cache-read + // and cache-write tokens (assistant.message events carry output + // only). VS Code transcripts never carry this rollup, so this path + // is gated to the CLI (non-transcript) format, leaving VS Code, + // JetBrains and OTel sources untouched. + // + // We emit one supplementary call per model carrying ONLY the + // input/cache tokens the per-turn events lack; output is excluded so + // the assistant.message output (and its cost) is not double-counted. + // Combined with the per-turn output cost, this yields the full, + // CLI-measured session cost. + if (isTranscript) continue + const shutdownData = event.data as SessionShutdownData + const modelMetrics = shutdownData.modelMetrics + if (!isRecord(modelMetrics)) continue + + const shutdownTimestamp = + (event.timestamp ?? '') || timestampToISO(shutdownData.sessionStartTime) || lastEventTimestamp + + for (const [model, metrics] of Object.entries(modelMetrics)) { + if (!model || !isRecord(metrics)) continue + const usage = metrics['usage'] + if (!isRecord(usage)) continue + + const cacheReadTokens = numberOrZero(usage['cacheReadTokens']) + const cacheWriteTokens = numberOrZero(usage['cacheWriteTokens']) + const reasoningTokens = numberOrZero(usage['reasoningTokens']) + // usage.inputTokens is cache-INCLUSIVE (input + cache_read + + // cache_write). calculateCost expects the uncached input alone with + // cache tokens billed separately, so subtract the cache components. + // Clamp at 0 in case a future schema reports input non-inclusively. + const inputTokens = Math.max( + 0, + numberOrZero(usage['inputTokens']) - cacheReadTokens - cacheWriteTokens + ) + + // Nothing this call would add over the per-turn events, so skip it + // to avoid an empty $0 row (output is intentionally excluded). + if (inputTokens === 0 && cacheReadTokens === 0 && cacheWriteTokens === 0) continue + + const dedupKey = `copilot:${sessionId}:shutdown:${model}` + if (seenKeys.has(dedupKey)) continue + seenKeys.add(dedupKey) + + // Tokens are real counts written by the CLI, so this cost is + // measured, not char-estimated: costIsEstimated is false. + const costUSD = calculateCost(model, inputTokens, 0, cacheWriteTokens, cacheReadTokens, 0) + + yield { + provider: 'copilot', + sessionId, + model, + inputTokens, + outputTokens: 0, + cacheCreationInputTokens: cacheWriteTokens, + cacheReadInputTokens: cacheReadTokens, + cachedInputTokens: 0, + reasoningTokens, + webSearchRequests: 0, + costUSD, + costIsEstimated: false, + tools: [], + bashCommands: [], + timestamp: shutdownTimestamp, + speed: 'standard' as const, + deduplicationKey: dedupKey, + userMessage: '', + } + } + continue + } + if (event.type === 'assistant.message') { const msgData = event.data as AssistantMessageData const { messageId, model: msgModel, outputTokens = 0 } = msgData diff --git a/src/session-cache.ts b/src/session-cache.ts index aa61d21..d5bfea8 100644 --- a/src/session-cache.ts +++ b/src/session-cache.ts @@ -124,7 +124,7 @@ const PROVIDER_PARSE_VERSIONS: Record = { codex: 'mcp-attribution-v2', cursor: 'composer-anchored-crediting-v1', 'cursor-agent': 'workspaceless-transcript-v1', - copilot: 'otel-durable-v1', + copilot: 'cli-shutdown-cost-v1', hermes: 'reasoning-output-accounting-v1', 'lingtai-tui': 'token-ledger-registry-activity-v3', 'ibm-bob': 'worktree-project-grouping-v1', diff --git a/tests/parser.test.ts b/tests/parser.test.ts index 1a2a4ec..6415764 100644 --- a/tests/parser.test.ts +++ b/tests/parser.test.ts @@ -412,3 +412,46 @@ describe('(e) 90-day age-out for durable providers', () => { expect(totalOutput(proj2)).toBe(7) }) }) + +// ═══════════════════════════════════════════════════════════════════════════ +// (f) Version-bump survival: a PROVIDER_PARSE_VERSIONS bump (or any env +// fingerprint change) must NOT erase durable orphans. The cache is the +// only remaining record of usage whose source was pruned; discarding the +// section wholesale on fingerprint mismatch permanently lost that history +// (caught in the #684 re-review). +// ═══════════════════════════════════════════════════════════════════════════ +describe('(f) durable orphans survive a parse-version bump', () => { + it('keeps counting a pruned-source orphan after the provider fingerprint changes', async () => { + const sessionStateDir = join(tmpHome, 'session-state') + await mkdir(sessionStateDir, { recursive: true }) + vi.stubEnv('CODEBURN_COPILOT_SESSION_STATE_DIR', sessionStateDir) + vi.stubEnv('CODEBURN_COPILOT_DISABLE_OTEL', '1') + vi.stubEnv('CODEBURN_COPILOT_WS_STORAGE_DIR', join(tmpHome, 'no-ws')) + + // Parse once so the session is cached, then prune the source: the cache + // entry becomes a durable orphan (its only record). + const eventsPath = await createJsonlSession(sessionStateDir, 'sess-bump', 200) + const before = totalOutput(await parseAllSessions(undefined, 'copilot')) + expect(before).toBe(200) + await unlink(eventsPath) + clearSessionCache() + + // Simulate the fingerprint a PREVIOUS release computed (any mismatching + // value takes the same code path as a real parse-version bump). + const { readFile, writeFile: writeFileFs } = await import('fs/promises') + const cachePath = join(tmpCache, 'session-cache.json') + const disk = JSON.parse(await readFile(cachePath, 'utf-8')) as { providers: Record } + expect(disk.providers['copilot']).toBeDefined() + disk.providers['copilot']!.envFingerprint = '0000000000000000' + await writeFileFs(cachePath, JSON.stringify(disk), 'utf-8') + + // First parse after the "upgrade": the orphan must still be counted and + // must survive in the rewritten cache, not be erased with the section. + const after = totalOutput(await parseAllSessions(undefined, 'copilot')) + expect(after).toBe(200) + + clearSessionCache() + const again = totalOutput(await parseAllSessions(undefined, 'copilot')) + expect(again).toBe(200) + }) +}) diff --git a/tests/providers/copilot.test.ts b/tests/providers/copilot.test.ts index 89586a5..a5d9551 100644 --- a/tests/providers/copilot.test.ts +++ b/tests/providers/copilot.test.ts @@ -6,6 +6,7 @@ import { createRequire } from 'node:module' import { copilot, createCopilotProvider, getVSCodeGlobalStorageDirs, getVSCodeWorkspaceStorageDirs } from '../../src/providers/copilot.js' import { isSqliteAvailable } from '../../src/sqlite.js' +import { calculateCost } from '../../src/models.js' import type { ParsedProviderCall } from '../../src/providers/types.js' let tmpDir: string @@ -39,6 +40,38 @@ function assistantMessage(opts: { messageId: string; outputTokens: number; tools }) } +// A CLI session.shutdown rollup. `usage.inputTokens` is written cache-inclusive +// by the real CLI (input + cache_read + cache_write), matching the issue sample. +function shutdownEvent(opts: { + modelMetrics: Record + timestamp?: string +}) { + const modelMetrics: Record = {} + for (const [model, u] of Object.entries(opts.modelMetrics)) { + modelMetrics[model] = { + requests: { count: 1, cost: 1 }, + usage: { + inputTokens: u.inputTokens, + outputTokens: u.outputTokens, + cacheReadTokens: u.cacheReadTokens, + cacheWriteTokens: u.cacheWriteTokens, + reasoningTokens: u.reasoningTokens ?? 0, + }, + } + } + return JSON.stringify({ + type: 'session.shutdown', + timestamp: opts.timestamp ?? '2026-04-15T10:05:00Z', + data: { shutdownType: 'routine', sessionStartTime: 1784102040274, modelMetrics }, + }) +} + function transcriptSessionStart(sessionId: string) { return JSON.stringify({ type: 'session.start', data: { sessionId, producer: 'copilot-agent' } }) } @@ -390,6 +423,197 @@ describe('copilot provider - JSONL parsing', () => { }) }) +describe('copilot provider - session.shutdown token/cost rollup', () => { + beforeEach(async () => { + tmpDir = await mkdtemp(join(tmpdir(), 'copilot-shutdown-test-')) + }) + + afterEach(async () => { + await rm(tmpDir, { recursive: true, force: true }) + }) + + it('reads input/cache tokens and measured cost from session.shutdown', async () => { + const eventsPath = await createSessionDir('sess-shutdown', [ + modelChange('claude-sonnet-4-5'), + userMessage('do the thing'), + assistantMessage({ messageId: 'msg-1', outputTokens: 345 }), + shutdownEvent({ + modelMetrics: { + // Real sample from issue #676: inputTokens is cache-inclusive + // (4 + 35495 + 35783 = 71282), so pure input is 4. + 'claude-sonnet-4-5': { + inputTokens: 71282, + outputTokens: 345, + cacheReadTokens: 35495, + cacheWriteTokens: 35783, + reasoningTokens: 31, + }, + }, + }), + ]) + + const source = { path: eventsPath, project: 'myproject', provider: 'copilot' } + const calls = await collectCalls(source) + + // One per-turn assistant.message call + one supplementary shutdown call. + expect(calls).toHaveLength(2) + + const shutdown = calls.find(c => c.deduplicationKey === 'copilot:sess-shutdown:shutdown:claude-sonnet-4-5') + expect(shutdown).toBeDefined() + expect(shutdown!.model).toBe('claude-sonnet-4-5') + expect(shutdown!.inputTokens).toBe(4) // 71282 - 35495 - 35783 + expect(shutdown!.cacheReadInputTokens).toBe(35495) + expect(shutdown!.cacheCreationInputTokens).toBe(35783) + expect(shutdown!.reasoningTokens).toBe(31) + expect(shutdown!.outputTokens).toBe(0) // owned by the per-turn event + expect(shutdown!.costIsEstimated).toBe(false) // measured, not char-estimated + + const expectedShutdownCost = calculateCost('claude-sonnet-4-5', 4, 0, 35783, 35495, 0) + expect(shutdown!.costUSD).toBeCloseTo(expectedShutdownCost, 12) + expect(shutdown!.costUSD).toBeGreaterThan(0) + + // No dimension double-counts: output stays with the per-turn event only, + // input/cache come only from the shutdown rollup. + const total = (k: keyof ParsedProviderCall) => + calls.reduce((s, c) => s + (c[k] as number), 0) + expect(total('outputTokens')).toBe(345) + expect(total('inputTokens')).toBe(4) + expect(total('cacheReadInputTokens')).toBe(35495) + expect(total('cacheCreationInputTokens')).toBe(35783) + + // Session cost = per-turn output cost + shutdown input/cache cost = full cost. + const perTurn = calls.find(c => c.deduplicationKey === 'copilot:sess-shutdown:msg-1') + expect(perTurn!.costUSD).toBeCloseTo(calculateCost('claude-sonnet-4-5', 0, 345, 0, 0, 0), 12) + const sessionCost = calls.reduce((s, c) => s + c.costUSD, 0) + const fullCost = calculateCost('claude-sonnet-4-5', 4, 345, 35783, 35495, 0) + expect(sessionCost).toBeCloseTo(fullCost, 12) + }) + + it('keeps output-only behavior when session.shutdown is absent', async () => { + const eventsPath = await createSessionDir('sess-no-shutdown', [ + modelChange('claude-sonnet-4-5'), + userMessage('no shutdown here'), + assistantMessage({ messageId: 'msg-1', outputTokens: 150 }), + ]) + + const source = { path: eventsPath, project: 'myproject', provider: 'copilot' } + const calls = await collectCalls(source) + + expect(calls).toHaveLength(1) + const call = calls[0]! + expect(call.outputTokens).toBe(150) + expect(call.inputTokens).toBe(0) + expect(call.cacheReadInputTokens).toBe(0) + expect(call.cacheCreationInputTokens).toBe(0) + expect(call.costIsEstimated).toBeUndefined() + expect(call.costUSD).toBeCloseTo(calculateCost('claude-sonnet-4-5', 0, 150, 0, 0, 0), 12) + }) + + it('attributes shutdown tokens and cost per model', async () => { + const eventsPath = await createSessionDir('sess-multi', [ + modelChange('claude-sonnet-4-5'), + userMessage('first'), + assistantMessage({ messageId: 'msg-1', outputTokens: 100 }), + modelChange('gpt-5', 'claude-sonnet-4-5'), + assistantMessage({ messageId: 'msg-2', outputTokens: 200 }), + shutdownEvent({ + modelMetrics: { + 'claude-sonnet-4-5': { inputTokens: 10100, outputTokens: 100, cacheReadTokens: 8000, cacheWriteTokens: 2000, reasoningTokens: 0 }, + 'gpt-5': { inputTokens: 5050, outputTokens: 200, cacheReadTokens: 5000, cacheWriteTokens: 0, reasoningTokens: 12 }, + }, + }), + ]) + + const source = { path: eventsPath, project: 'myproject', provider: 'copilot' } + const calls = await collectCalls(source) + + const shutdownCalls = calls.filter(c => c.deduplicationKey.includes(':shutdown:')) + expect(shutdownCalls).toHaveLength(2) + + const sonnet = shutdownCalls.find(c => c.model === 'claude-sonnet-4-5')! + expect(sonnet.inputTokens).toBe(100) // 10100 - 8000 - 2000 + expect(sonnet.cacheReadInputTokens).toBe(8000) + expect(sonnet.cacheCreationInputTokens).toBe(2000) + expect(sonnet.outputTokens).toBe(0) + expect(sonnet.costUSD).toBeCloseTo(calculateCost('claude-sonnet-4-5', 100, 0, 2000, 8000, 0), 12) + expect(sonnet.costUSD).toBeGreaterThan(0) + + const gpt = shutdownCalls.find(c => c.model === 'gpt-5')! + expect(gpt.inputTokens).toBe(50) // 5050 - 5000 - 0 + expect(gpt.cacheReadInputTokens).toBe(5000) + expect(gpt.cacheCreationInputTokens).toBe(0) + expect(gpt.reasoningTokens).toBe(12) + expect(gpt.costUSD).toBeCloseTo(calculateCost('gpt-5', 50, 0, 0, 5000, 0), 12) + }) + + it('keeps shutdown dedup keys stable across re-parses', async () => { + const eventsPath = await createSessionDir('sess-reparse', [ + modelChange('claude-sonnet-4-5'), + assistantMessage({ messageId: 'msg-1', outputTokens: 345 }), + shutdownEvent({ + modelMetrics: { + 'claude-sonnet-4-5': { inputTokens: 71282, outputTokens: 345, cacheReadTokens: 35495, cacheWriteTokens: 35783, reasoningTokens: 31 }, + }, + }), + ]) + const source = { path: eventsPath, project: 'myproject', provider: 'copilot' } + + const seen = new Set() + const first = await collectCalls(source, seen) + expect(first).toHaveLength(2) + // Durable provider: re-parsing with the same seenKeys re-emits nothing. + const second = await collectCalls(source, seen) + expect(second).toHaveLength(0) + }) + + it('falls back to the last stamped event when shutdown carries no timestamp at all', async () => { + // A shutdown with neither its own timestamp nor sessionStartTime must not + // yield an empty-timestamp call: the date-range filters in parser.ts drop + // those silently, which would erase exactly the tokens this fix bills. + const bareShutdown = JSON.stringify({ + type: 'session.shutdown', + data: { + shutdownType: 'routine', + modelMetrics: { + 'claude-sonnet-4-5': { + requests: { count: 1, cost: 1 }, + usage: { inputTokens: 9000, outputTokens: 300, cacheReadTokens: 4000, cacheWriteTokens: 1000, reasoningTokens: 0 }, + }, + }, + }, + }) + const eventsPath = await createSessionDir('sess-no-ts', [ + modelChange('claude-sonnet-4-5'), + assistantMessage({ messageId: 'msg-1', outputTokens: 300, timestamp: '2026-04-15T10:00:15Z' }), + bareShutdown, + ]) + const calls = await collectCalls({ path: eventsPath, project: 'myproject', provider: 'copilot' }) + const shutdown = calls.find(c => c.deduplicationKey.includes(':shutdown:')) + expect(shutdown).toBeDefined() + expect(shutdown!.timestamp).toBe('2026-04-15T10:00:15Z') + }) + + it('ignores session.shutdown for VS Code transcript sessions', async () => { + const eventsPath = await createSessionDir('sess-tr-shutdown', [ + transcriptSessionStart('sess-tr-shutdown'), + transcriptUserMessage('hi'), + transcriptAssistantMessage({ messageId: 'msg-1', content: 'done', toolCallIds: ['call_abc'] }), + shutdownEvent({ + modelMetrics: { + 'claude-sonnet-4-5': { inputTokens: 71282, outputTokens: 345, cacheReadTokens: 35495, cacheWriteTokens: 35783 }, + }, + }), + ]) + const source = { path: eventsPath, project: 'test', provider: 'copilot' } + const calls = await collectCalls(source) + + // Only the transcript assistant call; the shutdown rollup is CLI-only. + expect(calls).toHaveLength(1) + expect(calls.every(c => !c.deduplicationKey.includes(':shutdown:'))).toBe(true) + expect(calls[0]!.model).toBe('copilot-openai-auto') + }) +}) + describe('copilot provider - chatSessions parsing', () => { beforeEach(async () => { tmpDir = await mkdtemp(join(tmpdir(), 'copilot-chatsessions-test-'))