From 12c8cb7790b3f6ed793ff90a33d380f40589da5a Mon Sep 17 00:00:00 2001 From: iamtoruk Date: Sat, 22 Aug 2026 02:26:35 -0700 Subject: [PATCH] fix(copilot): re-derive migrated copilot day slices, count the compaction row's output Two defects from @kelchm's two-machine validation of #946. 1. The daily-cache migration carried the copilot slice of every existing day entry verbatim instead of re-deriving it, so `overview` on a migrated cache kept serving pre-store numbers (2,980,804 tokens for a day whose fresh derivation is 74,811,412; 21,608 calls vs 16,326) while export/models/audit served the corrected ones off the same cache. Root cause is the partial-survival guard (e9d922ca), not the migration: it keeps a settled baseline slice whenever the fresh derivation reports FEWER calls, reading that as aged-out sources. This change's whole point is that copilot's supplementary accounting calls stop counting as api calls, so every store-era day shrinks in calls and got pinned to its pre-store value. The guard's own TRADE-OFF note predicted exactly this case. A migration from an older cache version now grants copilot ONE guarded-shrink-exempt re-derivation (`pendingRederive`), spent by the first COMPLETE parse. It fires only where that parse actually produced a slice for the (day, provider), so a day whose sources are gone still carries forward whole - never-lose is unchanged in both directions - and no other provider is exempt. The daily cache moves 21 -> 25: 21-24 landed on main during validation, and only a number the validators' own daily-cache.v21.json cannot claim gets their stale carried slices re-derived. 2. The `initiator='compaction'` store row was ingested with outputTokens 0. Its output has no assistant.message anywhere in events.jsonl, so that row is the only place those tokens exist - dropping them was the sole token discrepancy (-3,085) across a 30-session store-matched comparison. It is now read (on the same optional-select rung as `initiator`, which is what identifies the row), counted and priced; every other row keeps output 0 because a per-turn call owns it. The copilot parse version moves to session-store-v3 so cached v2 rows re-parse; the dedup key is deliberately unchanged. Settle window stays at 24 h - the three-machine evidence for tightening it is recorded next to the constant, but shortening it is a product call. --- scripts/upgrade-path/run.mjs | 2 +- src/daily-cache.ts | 84 ++++++++++++++++++++--- src/providers/copilot.ts | 34 ++++++++-- src/session-cache.ts | 7 +- src/sync/push.ts | 9 +++ tests/daily-cache-carry-forward.test.ts | 89 +++++++++++++++++++++++++ tests/parser.test.ts | 88 +++++++++++++++++++++++- 7 files changed, 291 insertions(+), 22 deletions(-) diff --git a/scripts/upgrade-path/run.mjs b/scripts/upgrade-path/run.mjs index 0ce7ed86..5ccde25e 100644 --- a/scripts/upgrade-path/run.mjs +++ b/scripts/upgrade-path/run.mjs @@ -33,7 +33,7 @@ const WORK = process.env['UPGRADE_PATH_WORK'] || join(tmpdir(), 'codeburn upgrad const OLD_SESSION_CACHE = 'session-cache.v7.json' const OLD_DAILY_CACHE = 'daily-cache.v17.json' const NEW_SESSION_CACHE_DIR = 'session-cache.v9' -const NEW_DAILY_CACHE = 'daily-cache.v21.json' +const NEW_DAILY_CACHE = 'daily-cache.v25.json' const HOME = join(WORK, 'user home') const PAYLOADS = join(WORK, 'payloads') diff --git a/src/daily-cache.ts b/src/daily-cache.ts index 4675824b..6f54ecac 100644 --- a/src/daily-cache.ts +++ b/src/daily-cache.ts @@ -6,7 +6,7 @@ import { join } from 'path' import { getCodeburnCacheDir } from './cache-dir.js' import type { DateRange, ProjectSummary } from './types.js' -// Bumped to 21: copilot input/cache tokens for sessions covered by the CLI's +// Bumped to 25: copilot input/cache tokens for sessions covered by the CLI's // session-store.db move from one shutdown-rollup lump (stamped at session end) // to per-request DB rows with real timestamps, supplementary accounting calls // (rollups, residuals, paired rows) stop counting as api/model calls, and @@ -15,12 +15,16 @@ import type { DateRange, ProjectSummary } from './types.js' // costs all move, so days finalized under an earlier version would disagree // with the live parse. // -// 20 is taken by #1040 (codex model attribution, now on main) and 18 was -// burned by an earlier public head of THIS change under different accounting -// (whole-session rollup suppression, no supplementary weight). -// isMigratableCache/adoptOlderDailyCaches carry a same-or-newer version -// forward as FINALIZED without re-deriving it, so a number can never mean two -// accountings. 21 is the first free number. +// Why 25 and not 21 (the number this change first claimed): 20 is #1040 (codex +// model attribution), 18 was burned by an earlier public head of THIS change +// under different accounting, and 21-24 landed on main while this branch was in +// validation. 25 is the first free number on main's ladder — and it is load +// bearing beyond the collision: the branch's own validators already hold +// daily-cache.v21.json files whose copilot slices were carried stale by the +// bug PENDING_REDERIVE_PROVIDERS fixes below, and only a number those files +// cannot claim gets them re-derived. isMigratableCache/adoptOlderDailyCaches +// carry a same-or-newer version forward as FINALIZED without re-deriving it, +// so a number can never mean two accountings. // Bumped to 20: the Codex fast-path read a nested // `base_instructions.provenance.model` out of `session_meta` as if it were // `payload.model` (#1040), so every call a rollout attributed from session @@ -125,8 +129,30 @@ import type { DateRange, ProjectSummary } from './types.js' // that older binaries skipped. v8 added local-model savings to the daily // rollup; the `savingsConfigHash` field is invalidated separately when the // user changes their `localModelSavings` mapping. -export const DAILY_CACHE_VERSION = 21 -const MIN_SUPPORTED_VERSION = 21 +export const DAILY_CACHE_VERSION = 25 +const MIN_SUPPORTED_VERSION = 25 + +/// Providers whose per-day CALL COUNT means something different at +/// DAILY_CACHE_VERSION 25 than it did before it. Copilot's supplementary +/// accounting calls (rollups, residuals, store rows paired with a per-turn +/// call) stopped counting as api calls here, so a settled day's re-derivation +/// legitimately reports FEWER calls than the cache holds — which is exactly +/// the shape `isPartialSurvival` reads as "the sources aged out" (see the +/// TRADE-OFF note there, which called this case out in advance). Left +/// unhandled the guard pins every store-era copilot slice to its pre-store +/// value: measured on a real 17 -> 21 upgrade, `overview` served 2,980,804 +/// tokens for a day whose fresh derivation is 74,811,412, while +/// `export`/`models`/`audit` (which never read this cache) served the +/// corrected figures off the same machine. +/// +/// The exemption is one-shot and provider-scoped, not a relaxation of the +/// guard: `pendingRederive` is set only when a cache is migrated FROM a +/// version below this one, it is spent by the first complete re-derivation, +/// and it only ever fires where that re-derivation actually produced a slice +/// for the (day, provider). A day whose copilot sources are gone yields no +/// fresh slice at all, so it still carries forward whole — the #1033 bar is +/// untouched, in both directions, and every other provider keeps the guard. +const PENDING_REDERIVE_PROVIDERS: readonly string[] = ['copilot'] // Version-suffixed so different binaries each own a distinct file and never // clobber an incompatible schema. Bumping the version mints a fresh filename; // adoptOlderDailyCaches then unions days out of every previous file (including @@ -226,6 +252,12 @@ export type DailyCache = { /// on caches written before this field: distrusted once (one healing /// pull-back), then stamped. watermarkTrusted?: boolean + /// Providers still owed the one re-derivation that a migration from a + /// pre-`DAILY_CACHE_VERSION` cache entitles them to, despite a shrinking + /// call count (see PENDING_REDERIVE_PROVIDERS). Set by the migration, + /// cleared by the first COMPLETE re-derive — persisted rather than computed + /// so a partial parse in between does not silently spend the entitlement. + pendingRederive?: string[] } /** IANA name of the current local timezone (respects the TZ env var). Days are @@ -372,8 +404,21 @@ function migrateDays(days: Record[]): DailyEntry[] { })) } +/// The providers a cache at `fromVersion` still owes a re-derivation, carrying +/// an unspent entitlement out of the parsed file so a same-version reload does +/// not drop it. +function pendingRederiveFor(fromVersion: number, parsed: unknown): string[] | undefined { + if (fromVersion < DAILY_CACHE_VERSION) return [...PENDING_REDERIVE_PROVIDERS] + const raw = (parsed as { pendingRederive?: unknown } | null)?.pendingRederive + if (!Array.isArray(raw)) return undefined + const kept = raw.filter((p): p is string => typeof p === 'string') + return kept.length > 0 ? kept : undefined +} + function migratedFrom(parsed: { version: number; lastComputedDate: string | null; savingsConfigHash?: string; tzKey?: string; days: Record[]; complete?: boolean; watermarkTrusted?: boolean }): DailyCache { + const pendingRederive = pendingRederiveFor(parsed.version, parsed) return { + ...(pendingRederive ? { pendingRederive } : {}), version: DAILY_CACHE_VERSION, savingsConfigHash: parsed.savingsConfigHash ?? '', tzKey: parsed.tzKey, @@ -486,6 +531,11 @@ async function adoptOlderDailyCaches(): Promise { ...base, lastComputedDate, days, + // Anything adopted out of an OLDER file was derived under an older + // accounting, so the providers whose call counts changed meaning get their + // one guarded-shrink-exempt re-derivation (see PENDING_REDERIVE_PROVIDERS). + pendingRederive: base.pendingRederive + ?? (rest.some(c => c.parsed.version < DAILY_CACHE_VERSION) ? [...PENDING_REDERIVE_PROVIDERS] : undefined), // An untrusted base means nothing here was derived under the current // accounting: leave complete unset so the next hydration re-derives every // day whose sources survive (the merge keeps the rest). @@ -994,6 +1044,13 @@ export function mergeDayEntries( /// leaves it off - both sides are cache generations there and the newer /// schema deliberately wins per (date, provider). guardPartialSurvival = false, + /// Providers whose baseline slices were recorded under an accounting where a + /// call meant something else, so a shrink is not evidence of source loss for + /// this one re-derivation (see PENDING_REDERIVE_PROVIDERS). Only consulted + /// where the fresh parse actually produced a slice for the (date, provider); + /// a slice it could not produce at all is carried by the branch above, + /// exactly as before. + pendingRederive?: ReadonlySet, ): DailyEntry[] { const byDate = new Map() const settleCutoff = settleCutoffDate(new Date()) @@ -1039,7 +1096,7 @@ export function mergeDayEntries( } } if (existingSlice && hasSliceData(existingSlice) && !residual) { - if (!guardPartialSurvival || !isPartialSurvival(day.date, slice, existingSlice, settleCutoff)) continue + if (!guardPartialSurvival || pendingRederive?.has(provider) || !isPartialSurvival(day.date, slice, existingSlice, settleCutoff)) continue // The baseline holds more evidence than the sources can still produce: // swap the fresh slice back out for it (inverse of addSliceIntoDay, so // the day's totals and nested maps stay reconciled with its slices). @@ -1206,13 +1263,18 @@ export async function ensureCacheHydrated( const wideProjects = await parseSessions({ start: backfillStart, end: now }) tzSubtraction = buildTzSubtraction(aggregateDaysInTz(wideProjects, c.tzKey)) } + const pendingRederive = c.pendingRederive?.length ? new Set(c.pendingRederive) : undefined const merged = parseWasComplete - ? mergeDayEntries(freshDays, baseline, true, tzSubtraction, true) + ? mergeDayEntries(freshDays, baseline, true, tzSubtraction, true, pendingRederive) : mergeDayEntries(baseline, freshDays, false) c = { version: DAILY_CACHE_VERSION, savingsConfigHash, tzKey, + // Spent: this re-derivation was the one the migration owed those + // providers. A PARTIAL parse never got to use it (its fresh data only + // filled gaps), so the entitlement is kept for the next complete run. + ...(parseWasComplete || !c.pendingRederive ? {} : { pendingRederive: c.pendingRederive }), // The watermark records how far history has actually been derived, so // only a COMPLETE parse may advance it. A partial one produced no data // for whatever it could not read; moving the watermark to yesterday diff --git a/src/providers/copilot.ts b/src/providers/copilot.ts index 6782ae4e..98a6e2d4 100644 --- a/src/providers/copilot.ts +++ b/src/providers/copilot.ts @@ -1987,7 +1987,14 @@ function createOtelParser( // The emitted calls mirror the shutdown-call contract exactly: input/cache/ // reasoning only, output 0 — per-turn output (and its tools/userMessage // metadata) stays owned by the events.jsonl assistant.message calls, so -// emitting output here would double-count it. The per-request billing +// emitting output here would double-count it. The ONE exception is the +// `initiator='compaction'` row: that request is the CLI summarizing its own +// context, it has no assistant.message anywhere in events.jsonl, and nothing +// else in the journal carries its output — so leaving it at 0 simply loses +// those tokens (measured: a matched 30-session corpus reconciled to the +// store's own row totals within -3,085 tokens, exactly one compaction row's +// output). It is counted here because here is the only place it exists. +// The per-request billing // metadata (total_nano_aiu, request_multiplier) is captured onto the cached // calls but not priced or displayed — that design is upstream #890; the // throughput/latency columns are deliberately not read yet. @@ -2026,9 +2033,14 @@ const SESSION_STORE_USAGE_SELECT = `SELECT ${SESSION_STORE_USAGE_COLUMNS}${SESSI // but not `initiator` keeps its billing metadata instead of falling all the // way back — the columns arrived in different CLI releases and a single // all-or-nothing enrichment would lose the older one. +// +// `output_tokens` rides on the SAME rung as `initiator` deliberately: it is +// only ever read for a row the label identifies as a compaction, so a store +// too old to have the label has no use for it either and must not be pushed +// down another fallback rung for it. const SESSION_STORE_USAGE_SELECTS = [ `SELECT ${SESSION_STORE_USAGE_COLUMNS}, - e.total_nano_aiu, e.request_multiplier, e.initiator${SESSION_STORE_USAGE_FROM}`, + e.total_nano_aiu, e.request_multiplier, e.initiator, e.output_tokens${SESSION_STORE_USAGE_FROM}`, `SELECT ${SESSION_STORE_USAGE_COLUMNS}, e.total_nano_aiu, e.request_multiplier${SESSION_STORE_USAGE_FROM}`, SESSION_STORE_USAGE_SELECT, @@ -2052,6 +2064,7 @@ type SessionStoreUsageRow = { total_nano_aiu?: number | null request_multiplier?: number | null initiator?: string | null + output_tokens?: number | null } // FNV-1a 64-bit over the row's identifying content, base36. Collisions only @@ -2185,9 +2198,14 @@ function createSessionStoreParser( numberOrZero(row.input_tokens) - cacheReadTokens - cacheWriteTokens ) - // Nothing this call would add over the per-turn events (output is - // intentionally excluded), so skip it to avoid an empty $0 row. - if (inputTokens === 0 && cacheReadTokens === 0 && cacheWriteTokens === 0 && reasoningTokens === 0) continue + // A compaction row's output has no assistant.message to own it, so + // this row is the only place it can be counted. Every other row's + // output IS owned by a per-turn call and stays excluded here. + const outputTokens = row.initiator === 'compaction' ? numberOrZero(row.output_tokens) : 0 + + // Nothing this call would add over the per-turn events, so skip it to + // avoid an empty $0 row. + if (inputTokens === 0 && cacheReadTokens === 0 && cacheWriteTokens === 0 && reasoningTokens === 0 && outputTokens === 0) continue // `id` is AUTOINCREMENT: stable across re-parses and never reused // WITHIN one database lifetime — but recreating the DB at the same @@ -2225,7 +2243,9 @@ function createSessionStoreParser( // input/cache_read/cache_write/output, no reasoning entry), and // output — reasoning included — is billed by the per-turn // assistant.message call. Pricing reasoning here would double-count. - const costUSD = calculateCost(model, inputTokens, 0, cacheWriteTokens, cacheReadTokens, 0) + // `outputTokens` is non-zero only for the compaction row, whose + // output no per-turn call bills, so it is priced exactly once. + const costUSD = calculateCost(model, inputTokens, outputTokens, cacheWriteTokens, cacheReadTokens, 0) yield { provider: 'copilot', @@ -2233,7 +2253,7 @@ function createSessionStoreParser( project, model, inputTokens, - outputTokens: 0, + outputTokens, cacheCreationInputTokens: cacheWriteTokens, cacheReadInputTokens: cacheReadTokens, cachedInputTokens: 0, diff --git a/src/session-cache.ts b/src/session-cache.ts index 7e17169b..cf70be29 100644 --- a/src/session-cache.ts +++ b/src/session-cache.ts @@ -312,7 +312,12 @@ export const PROVIDER_PARSE_VERSIONS: Record = { // reconciliation in parseProviderSources decides per (session, model) what // they still contribute. v2 (over the never-released v1): store dedup keys // grew a content discriminator so a same-path DB reset cannot alias rows. - copilot: 'cli-shutdown-cost-v1-skills-source-provenance-v1-session-store-v2', + // v3: the `initiator='compaction'` row now carries its own output tokens (no + // assistant.message owns them). The dedup key deliberately did NOT change - + // it identifies the request, and moving it would leave the cached output-0 + // copy beside the new row - so only this bump re-parses a v2 cache into the + // corrected shape. + copilot: 'cli-shutdown-cost-v1-skills-source-provenance-v1-session-store-v3', // authoritative-usage-v4: persist one Grok session call from top-level // authoritative totals, use modelUsage only for priced attribution, clamp // reasoning per record, and label mixed sessions estimated. diff --git a/src/sync/push.ts b/src/sync/push.ts index ef5ac49f..0c45d43b 100644 --- a/src/sync/push.ts +++ b/src/sync/push.ts @@ -56,6 +56,15 @@ export const MAX_PER_PUSH = 50_000 * i.e. the store was already complete when shutdown was written. That is one * machine and one CLI version (1.0.80), so this stays at a day until a second * machine agrees; the number to beat is seconds, not hours. + * + * Two more machines have now agreed (#946 validation): 6 sessions on CLI + * 1.0.79-8 and 30 sessions on 1.0.80, closest row 55 ms BEFORE shutdown, p95 + * -0.067 s. Three corpora, 127 sessions, zero positive deltas. That is enough + * evidence to tighten this to a seconds-scale window - deliberately NOT done + * here: shortening it changes what leaves the machine and how promptly, which + * is a product call for the maintainers, not a fix to a validated defect. The + * evidence is recorded so whoever makes that call does not have to re-gather + * it. */ export const RECONCILE_SETTLE_MS = 24 * 60 * 60 * 1000 diff --git a/tests/daily-cache-carry-forward.test.ts b/tests/daily-cache-carry-forward.test.ts index 78cfeab8..24f6f442 100644 --- a/tests/daily-cache-carry-forward.test.ts +++ b/tests/daily-cache-carry-forward.test.ts @@ -713,6 +713,95 @@ describe('adoption union across older cache files', () => { }) }) +// ═══════════════════════════════════════════════════════════════════════════ +// #946 validation round 5, item 2: the migration carried the copilot slice +// verbatim instead of re-deriving it. +// +// The v21 accounting stops counting copilot's supplementary accounting calls +// as api calls, so a settled store-era day re-derives with FEWER calls than +// the pre-store cache holds - the exact shape `isPartialSurvival` reads as +// "the sources aged out". The guard pinned every such slice to its pre-store +// value: `overview` served 2,980,804 tokens for 2026-08-06 where the fresh +// derivation is 74,811,412 (call count 21,608 vs 16,326 on 2026-08-12), while +// `export`/`models`/`audit` - which never read this cache - served the +// corrected figures off the same machine. +// +// Numbers below are kelchm's isolated machine-A day (2026-08-07): the v17 +// slice deep-equalled the migrated v21 one field-for-field, and a virgin-cache +// run of the same build derived the store-backed slice instead. +describe('#946: a migration re-derives copilot instead of carrying it', () => { + const settled = daysAgoStr(33) + const PRE_STORE = slice(0.630267, 37, { sessions: 6, cacheWriteTokens: 125987 }) + const STORE_BACKED = slice(0.692094, 27, { sessions: 6, cacheWriteTokens: 150716 }) + + /// Seeds an older-version daily cache (what a 0.9.20 install leaves behind) + /// so `loadDailyCache` takes the adoption path. + const seedOlderCache = async (days: DailyEntry[]) => { + await writeFile( + join(TMP_CACHE_ROOT, `daily-cache.v${DAILY_CACHE_VERSION - 4}.json`), + JSON.stringify({ + version: DAILY_CACHE_VERSION - 4, + savingsConfigHash: 'cfg-A', + tzKey: currentTzKey(), + lastComputedDate: daysAgoStr(1), + days, + complete: true, + watermarkTrusted: true, + }), + 'utf-8', + ) + } + + it('re-derives the copilot slice when the store still has the sources', async () => { + await seedOlderCache([day(settled, { copilot: PRE_STORE })]) + const out = await ensureCacheHydrated(noSessions, () => [day(settled, { copilot: STORE_BACKED })], 'cfg-A') + const got = out.days.find(d => d.date === settled)! + expect(got.providers['copilot']).toMatchObject({ cost: 0.692094, calls: 27, cacheWriteTokens: 150716 }) + expect(got.cost).toBeCloseTo(0.692094, 6) + expect(got.calls).toBe(27) + // Spent by this re-derivation, so the guard is back on for every later run. + expect(out.pendingRederive).toBeUndefined() + }) + + it('still carries the slice whole when the sources are gone (never-lose, #1033)', async () => { + await seedOlderCache([day(settled, { copilot: PRE_STORE })]) + // The re-derive finds nothing at all for that day: the store and the + // journals are both past their retention. + const out = await ensureCacheHydrated(noSessions, () => [], 'cfg-A') + const got = out.days.find(d => d.date === settled)! + expect(got.providers['copilot']).toMatchObject({ cost: 0.630267, calls: 37, cacheWriteTokens: 125987 }) + expect(got.carried).toBe(true) + }) + + it('does not lend the exemption to any other provider', async () => { + await seedOlderCache([day(settled, { claude: slice(1685.17, 12530, { sessions: 214 }) })]) + const truncated = [day(settled, { claude: slice(385.44, 560, { sessions: 0 }) })] + const out = await ensureCacheHydrated(noSessions, () => truncated, 'cfg-A') + expect(out.days.find(d => d.date === settled)!.providers['claude']) + .toMatchObject({ cost: 1685.17, calls: 12530 }) + }) + + it('is one-shot: a LATER copilot shrink on a settled day is guarded again', async () => { + await seedOlderCache([day(settled, { copilot: PRE_STORE })]) + await ensureCacheHydrated(noSessions, () => [day(settled, { copilot: STORE_BACKED })], 'cfg-A') + // Second run, savings config changed so the whole window re-derives again - + // this time the copilot sources have partly aged out. + const out = await ensureCacheHydrated(noSessions, () => [day(settled, { copilot: slice(0.1, 3) })], 'cfg-B') + expect(out.days.find(d => d.date === settled)!.providers['copilot']) + .toMatchObject({ cost: 0.692094, calls: 27 }) + }) + + it('a PARTIAL parse does not spend the entitlement', async () => { + await seedOlderCache([day(settled, { copilot: PRE_STORE })]) + const partial = await ensureCacheHydrated(noSessions, () => [], 'cfg-A', () => false) + expect(partial.pendingRederive).toEqual(['copilot']) + // The next COMPLETE run still gets to re-derive. + const out = await ensureCacheHydrated(noSessions, () => [day(settled, { copilot: STORE_BACKED })], 'cfg-A') + expect(out.days.find(d => d.date === settled)!.providers['copilot']) + .toMatchObject({ cost: 0.692094, calls: 27 }) + }) +}) + describe('partial survival: a truncated fresh slice cannot delete a settled baseline', () => { // The real 0.9.20 -> next upgrade loss: transcripts age out per FILE, so a // mostly-forgotten day still gets a handful of turns from surviving later diff --git a/tests/parser.test.ts b/tests/parser.test.ts index 530c2c81..c12dee94 100644 --- a/tests/parser.test.ts +++ b/tests/parser.test.ts @@ -1736,14 +1736,22 @@ describe.skipIf(!isSqliteAvailable())('(c5) compaction-initiated store rows', () `) db.close() } - const insertLabelled = (dbPath: string, sid: string, input: number, at: string, initiator: string | null): void => { + const insertLabelled = ( + dbPath: string, + sid: string, + input: number, + at: string, + initiator: string | null, + extra: { output?: number; cacheRead?: number } = {}, + ): void => { const { DatabaseSync } = requireForTest('node:sqlite') as { DatabaseSync: new (p: string) => TestDb } const db = new DatabaseSync(dbPath) db.prepare('INSERT OR IGNORE INTO sessions (id, cwd) VALUES (?, ?)').run(sid, '/home/user/testproj') db.prepare(`INSERT INTO assistant_usage_events (session_id, model, input_tokens, output_tokens, cache_read_tokens, cache_write_tokens, reasoning_tokens, created_at, total_nano_aiu, request_multiplier, initiator) - VALUES (?, 'claude-sonnet-4-5', ?, 0, 0, 0, 0, ?, 1000, 1, ?)`).run(sid, input, at, initiator) + VALUES (?, 'claude-sonnet-4-5', ?, ?, ?, 0, 0, ?, 1000, 1, ?)`) + .run(sid, input, extra.output ?? 0, extra.cacheRead ?? 0, at, initiator) db.close() } @@ -1835,6 +1843,82 @@ describe.skipIf(!isSqliteAvailable())('(c5) compaction-initiated store rows', () expect(storeCalls.filter(c => c.supplementaryAccounting)).toHaveLength(1) expect(supp('copilot:sess-ci:m1')).toBe(false) }) + + // Validation round 5, machine B, session f38d4326: the compaction row's + // prompt side was counted and priced while its 3,085 output tokens were + // dropped - the only token discrepancy across a 30-session store-matched + // comparison (540,158,021 served vs 540,161,106 in the store). Its output + // has no assistant.message anywhere in events.jsonl, so the store row is the + // only place it exists. + const totalOutput = (projects: Awaited>): number => + projects.flatMap(p => p.sessions).flatMap(s => s.turns).flatMap(t => t.assistantCalls) + .reduce((sum, c) => sum + c.usage.outputTokens, 0) + + it("counts the compaction row's own output, which no assistant.message owns", async () => { + const { sessionStateDir, dbPath, at } = await setup('compaction-output') + const dir = join(sessionStateDir, 'sess-ci') + await mkdir(dir, { recursive: true }) + await writeFile(join(dir, 'workspace.yaml'), 'id: sess-ci\ncwd: /home/user/testproj\n') + // The real geometry: created_at equals the compaction_complete stamp to + // the millisecond, and there is no assistant.message for this request. + await writeFile(join(dir, 'events.jsonl'), [ + JSON.stringify({ type: 'session.model_change', timestamp: at(0), data: { newModel: 'claude-sonnet-4-5' } }), + JSON.stringify({ type: 'session.compaction_complete', timestamp: at(10), data: { success: true, kind: 'background' } }), + ].join('\n') + '\n') + insertLabelled(dbPath, 'sess-ci', 273205, at(10), 'compaction', { output: 3085, cacheRead: 266933 }) + + const projects = await parseAllSessions(undefined, 'copilot') + const storeCalls = projects.flatMap(p => p.sessions).flatMap(s => s.turns) + .flatMap(t => t.assistantCalls).filter(c => c.deduplicationKey.startsWith('copilot-store:')) + expect(storeCalls).toHaveLength(1) + // input_tokens is cache-inclusive: 273,205 - 266,933 = 6,272 uncached. + expect(storeCalls[0]!.usage).toMatchObject({ + inputTokens: 6272, + cacheReadInputTokens: 266933, + outputTokens: 3085, + }) + expect(totalOutput(projects)).toBe(3085) + }) + + it('leaves an UNLABELLED row at output 0 (its per-turn call owns that output)', async () => { + const { sessionStateDir, dbPath, at } = await setup('unlabelled-output') + const dir = join(sessionStateDir, 'sess-ci') + await mkdir(dir, { recursive: true }) + await writeFile(join(dir, 'workspace.yaml'), 'id: sess-ci\ncwd: /home/user/testproj\n') + await writeFile(join(dir, 'events.jsonl'), [ + JSON.stringify({ type: 'session.model_change', timestamp: at(0), data: { newModel: 'claude-sonnet-4-5' } }), + JSON.stringify({ type: 'assistant.message', timestamp: at(11), data: { messageId: 'm1', outputTokens: 3085, toolRequests: [] } }), + ].join('\n') + '\n') + insertLabelled(dbPath, 'sess-ci', 273205, at(10), null, { output: 3085, cacheRead: 266933 }) + + // Counted once, by the per-turn call - never twice. + expect(totalOutput(await parseAllSessions(undefined, 'copilot'))).toBe(3085) + }) + + // The dedup hazard kelchm flagged: on the same turn index, 1.5 s apart, with + // near-identical token shapes. Nothing may collapse them - the store dedup + // key carries the row id, and the content discriminator differs too. + it('keeps the compaction row and its 1.5s-adjacent twin as two distinct calls', async () => { + const { sessionStateDir, dbPath, at } = await setup('adjacent-twin') + const dir = join(sessionStateDir, 'sess-ci') + await mkdir(dir, { recursive: true }) + await writeFile(join(dir, 'workspace.yaml'), 'id: sess-ci\ncwd: /home/user/testproj\n') + await writeFile(join(dir, 'events.jsonl'), [ + JSON.stringify({ type: 'session.model_change', timestamp: at(0), data: { newModel: 'claude-sonnet-4-5' } }), + JSON.stringify({ type: 'session.compaction_complete', timestamp: at(10), data: { success: true, kind: 'background' } }), + ].join('\n') + '\n') + insertLabelled(dbPath, 'sess-ci', 272139, at(8.5), null, { output: 400, cacheRead: 267005 }) + insertLabelled(dbPath, 'sess-ci', 273205, at(10), 'compaction', { output: 3085, cacheRead: 266933 }) + + const projects = await parseAllSessions(undefined, 'copilot') + const storeCalls = projects.flatMap(p => p.sessions).flatMap(s => s.turns) + .flatMap(t => t.assistantCalls).filter(c => c.deduplicationKey.startsWith('copilot-store:')) + expect(storeCalls).toHaveLength(2) + expect(new Set(storeCalls.map(c => c.deduplicationKey)).size).toBe(2) + // Both rows' prompt sides survive; only the labelled one contributes output. + expect(storeCalls.reduce((s, c) => s + c.usage.inputTokens, 0)).toBe((272139 - 267005) + 6272) + expect(totalOutput(projects)).toBe(3085) + }) }) // ═══════════════════════════════════════════════════════════════════════════