From ab3294a3e2dd544412810de4110eb11654102680 Mon Sep 17 00:00:00 2001 From: iamtoruk Date: Fri, 21 Aug 2026 14:03:19 -0700 Subject: [PATCH 1/2] fix(cli): report cline-cli web-search requests, bill zero of them MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review correction. Upstream zeroes only the PRICING argument — it passes a literal 0 as calculateCost's sixth parameter (main src/providers/cline-cli.ts :299) while ALWAYS emitting the real count on a per-message call; only the session-rollup path emits 0 (:349), because that path has no tool blocks to count. The rehome zeroed the EMITTED metric on every estimated call instead, which prices correctly but destroys the analytics field. The count now always rides on the call, and the suppression moves to where the billing actually happens: the pricing pass passes 0 web-search requests for cline-cli, whose `fetch_web_content` is a page fetch rather than a billable provider-side search. The pass is the single place estimated calls are priced (parser.ts prices every provider call there before anything is cached), and cline-cli's costUSD is persisted, so the cache read path cannot re-bill it either. The test asserted toBe(0) where main yields 1 — it certified the regression. It now proves both halves at once: the count is emitted on the estimated AND the metered call, and the estimated cost equals that of an identical session with no fetch. Reverting either half fails it (count -> 0, or cost +$0.01). --- packages/cli/src/pricing-pass.ts | 6 +++- packages/cli/src/providers/cline-cli.ts | 6 +--- .../cli/tests/providers/cline-cli.test.ts | 29 +++++++++++++------ 3 files changed, 26 insertions(+), 15 deletions(-) diff --git a/packages/cli/src/pricing-pass.ts b/packages/cli/src/pricing-pass.ts index c611c97b9..46bce774b 100644 --- a/packages/cli/src/pricing-pass.ts +++ b/packages/cli/src/pricing-pass.ts @@ -34,7 +34,11 @@ export function priceProviderCall(call: ParsedProviderCall): ParsedProviderCall outputForCost, call.cacheCreationInputTokens, call.cacheReadInputTokens, - call.webSearchRequests, + // cline-cli's `webSearchRequests` counts `fetch_web_content` page fetches, + // not billable provider-side searches: upstream reports the count on the + // call but passes a hardcoded 0 to the price table. Billing it here would + // add $0.01 per fetch on top of tokens. + call.provider === 'cline-cli' ? 0 : call.webSearchRequests, call.speed, ) // Seam extension: some decoders prefer the table price but fall back to a diff --git a/packages/cli/src/providers/cline-cli.ts b/packages/cli/src/providers/cline-cli.ts index aa09bf228..831117fe9 100644 --- a/packages/cli/src/providers/cline-cli.ts +++ b/packages/cli/src/providers/cline-cli.ts @@ -73,11 +73,7 @@ function toProviderCall(rich: ClineCliDecodedCall): ParsedProviderCall { cacheReadInputTokens: rich.cacheReadInputTokens, cachedInputTokens: rich.cachedInputTokens, reasoningTokens: rich.reasoningTokens, - // Upstream prices the estimated path with a hardcoded 0 web-search requests, - // so the decoded count must not reach the pricing pass (which bills - // $0.01 each). A metered call carries the CLI's own dollar figure, so its - // real count rides along without touching cost. - webSearchRequests: measured ? rich.webSearchRequests : 0, + webSearchRequests: rich.webSearchRequests, ...(measured ? { costUSD: rich.reportedCost, costBasis: 'measured' as const } : { costBasis: 'estimated' as const }), diff --git a/packages/cli/tests/providers/cline-cli.test.ts b/packages/cli/tests/providers/cline-cli.test.ts index 1d197f85a..ba082a25c 100644 --- a/packages/cli/tests/providers/cline-cli.test.ts +++ b/packages/cli/tests/providers/cline-cli.test.ts @@ -509,30 +509,41 @@ describe('cline-cli provider - rollup fallback', () => { expect(calls[0]?.costUSD).toBeGreaterThan(0) }) - it('keeps web-search requests out of the estimated-cost path', async () => { + it('reports web-search requests but never bills them, on either cost path', async () => { const fetchTool = { name: 'fetch_web_content', input: { url: 'https://example.com' } } + const metrics = { inputTokens: 1000, outputTokens: 100 } await writeSession(tmpDir, 'sess-a', { messages: [ { role: 'user', text: 'go' }, - { role: 'assistant', text: 'ok', metrics: { inputTokens: 1000, outputTokens: 100 }, toolUse: fetchTool }, + { role: 'assistant', text: 'ok', metrics, toolUse: fetchTool }, ], }) + // Same tokens, no fetch: the estimated cost must not move between the two. await writeSession(tmpDir, 'sess-b', { messages: [ { role: 'user', text: 'go' }, - { role: 'assistant', text: 'ok', metrics: { inputTokens: 1000, outputTokens: 100, cost: 0.02 }, toolUse: fetchTool }, + { role: 'assistant', text: 'ok', metrics }, + ], + }) + await writeSession(tmpDir, 'sess-c', { + messages: [ + { role: 'user', text: 'go' }, + { role: 'assistant', text: 'ok', metrics: { ...metrics, cost: 0.02 }, toolUse: fetchTool }, ], }) const calls = await collect(tmpDir) - const estimated = calls.find(c => c.costIsEstimated) - const metered = calls.find(c => !c.costIsEstimated) + const [withFetch, withoutFetch, metered] = calls - expect(estimated?.tools).toContain('WebFetch') - // Upstream prices this path with a hardcoded 0 requests; routing the real - // count into the pricing pass would bill $0.01 per fetch on top of tokens. - expect(estimated?.webSearchRequests).toBe(0) + // Upstream reports the count on every per-message call (it is an analytics + // field, not a billing input). + expect(withFetch?.tools).toContain('WebFetch') + expect(withFetch?.webSearchRequests).toBe(1) expect(metered?.webSearchRequests).toBe(1) + // ...and prices it with a hardcoded 0 requests: routing the count into the + // pricing pass would add $0.01 per fetch on top of the token cost. + expect(withFetch?.costUSD).toBe(withoutFetch?.costUSD) + expect(metered?.costUSD).toBe(0.02) }) it('emits nothing for a session with neither message metrics nor a rollup', async () => { From 81a6718add09d38f202682565924f5a30216358e Mon Sep 17 00:00:00 2001 From: iamtoruk Date: Fri, 21 Aug 2026 14:03:19 -0700 Subject: [PATCH 2/2] fix(core): cover the codex timing gate and the custom-tool transport MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two gaps the adversarial pass found in the throughput rehome. The `taskOpen` gate had no behavioral coverage: deleting it left all 613 core tests green, because the existing cases pin the flag's VALUE and never its consequence — their resumed pass holds no pending calls, so an earlier condition already blocks attribution. The new case splits a task with two token_counts, so the resumed pass holds a real call and real generated tokens but never saw the task_started. Without the gate its task_complete takes the whole 6s window for the one call it happens to hold — double that call's share, with the first call left unattributed. With it, nothing is attributed. The timing branches spoke only function_call / function_call_output, while main and the ported codex-throughput.ts also count Codex Desktop's custom-tool transport. On the real corpus that is 11,390 tool pairs across 134 rollouts, whose wait time was being counted as active: GPT-5.5 drops from 506,373 to 490,337 active seconds (36.5 -> 37.7 Tok/s), gpt-5.6-sol from 66,194 to 54,120 (35.3 -> 43.2). Tool NAMING for custom_tool_call stays unported, so the start is captured in its own timing-only branch. Cost, calls and tokens are unchanged: codex totals are still byte-identical to the base branch over the 1326-session corpus. Also lands the adversarial append-split fixture as a permanent regression test: cold parse == warm append parse at EVERY line split point of a rollout with two complete tasks and a third left open at EOF, plus a three-pass variant and an idempotence check. It kills both ways of getting the resume point wrong — replaying past the boundary (callCount not truncated) and resuming at end-of-file (the open task's window lost). The validator's full O(n^2) three- pass sweep is trimmed to the boundary-crossing pairs; it adds ~90 parses and no extra mutation coverage. --- .../cli/tests/codex-checkpoint-resume.test.ts | 155 ++++++++++++++++++ packages/core/src/providers/codex/decode.ts | 17 +- .../core/tests/providers/codex-decode.test.ts | 49 ++++++ 3 files changed, 217 insertions(+), 4 deletions(-) create mode 100644 packages/cli/tests/codex-checkpoint-resume.test.ts diff --git a/packages/cli/tests/codex-checkpoint-resume.test.ts b/packages/cli/tests/codex-checkpoint-resume.test.ts new file mode 100644 index 000000000..f5f67f57d --- /dev/null +++ b/packages/cli/tests/codex-checkpoint-resume.test.ts @@ -0,0 +1,155 @@ +// Cold-vs-warm equivalence for the codex task_started checkpoint resume, at +// EVERY line split point of a rollout carrying two complete tasks (one with a +// function_call wait, one with an mcp_tool_call_end wait and two token_counts +// to split proportionally) plus a third task left OPEN at end of file. +// +// This is the gate the checkpoint design has to clear: an incremental parse of +// a growing rollout must produce exactly what a cold parse of the finished file +// produces — cost, tokens, turns AND timing. It mutation-kills both ways of +// getting the resume point wrong: replaying past the boundary (`callCount` not +// truncated, so the open task's calls are served stale and never re-derived) +// and resuming at end of file (the open task's window is lost, so its +// task_complete attributes nothing). +import { describe, it, expect, beforeEach, afterAll, vi } from 'vitest' +import { mkdir, rm, writeFile, appendFile, stat, utimes } from 'fs/promises' +import { join } from 'path' +import { clearSessionCache, parseAllSessions } from '../src/parser.js' + +const testRoot = vi.hoisted(() => { + const root = `${process.env['TMPDIR'] || '/tmp'}/codex-ckpt-${process.pid}-${Date.now()}` + process.env['HOME'] = `${root}/home` + process.env['USERPROFILE'] = `${root}/home` + process.env['CODEX_HOME'] = `${root}/codex` + return root +}) +const CODEX_HOME = join(testRoot, 'codex') +beforeEach(() => { + process.env['HOME'] = join(testRoot, 'home') + process.env['USERPROFILE'] = join(testRoot, 'home') + process.env['CODEX_HOME'] = CODEX_HOME + process.env['CODEBURN_CACHE_DIR'] = join(testRoot, 'cache') +}) + +afterAll(async () => { await rm(testRoot, { recursive: true, force: true }) }) + +const ts = (n: number) => new Date(Date.UTC(2026, 3, 14, 10, 0, 0) + n * 1000).toISOString() + +// A rollout with: 2 complete tasks (one with a function_call tool wait, one +// with an mcp_tool_call_end wait) + a 3rd task left OPEN at EOF. +function buildLines(): string[] { + const L: unknown[] = [] + L.push({ type: 'session_meta', timestamp: ts(0), payload: { session_id: 'sess-adv', model: 'gpt-5.5', cwd: '/Users/test/proj', originator: 'codex-cli' } }) + // --- task 1: 10s total, 3s function_call wait + L.push({ type: 'event_msg', timestamp: ts(10), payload: { type: 'task_started' } }) + L.push({ type: 'response_item', timestamp: ts(11), payload: { type: 'function_call', call_id: 'c1', name: 'shell' } }) + L.push({ type: 'response_item', timestamp: ts(14), payload: { type: 'function_call_output', call_id: 'c1' } }) + L.push({ type: 'event_msg', timestamp: ts(15), payload: { type: 'token_count', info: { last_token_usage: { input_tokens: 10, output_tokens: 100, reasoning_output_tokens: 20, total_tokens: 130 }, total_token_usage: { input_tokens: 10, output_tokens: 100, reasoning_output_tokens: 20, total_tokens: 130 } } } }) + L.push({ type: 'event_msg', timestamp: ts(20), payload: { type: 'task_complete', duration_ms: 10000 } }) + // --- task 2: 8s total, 2s mcp wait, TWO token_counts (proportional split) + L.push({ type: 'event_msg', timestamp: ts(30), payload: { type: 'task_started' } }) + L.push({ type: 'event_msg', timestamp: ts(33), payload: { type: 'mcp_tool_call_end', duration_ms: 2000, invocation: { server: 's', tool: 't' } } }) + L.push({ type: 'event_msg', timestamp: ts(34), payload: { type: 'token_count', info: { last_token_usage: { input_tokens: 5, output_tokens: 40, reasoning_output_tokens: 10, total_tokens: 55 }, total_token_usage: { input_tokens: 15, output_tokens: 140, reasoning_output_tokens: 30, total_tokens: 185 } } } }) + L.push({ type: 'event_msg', timestamp: ts(36), payload: { type: 'token_count', info: { last_token_usage: { input_tokens: 5, output_tokens: 60, reasoning_output_tokens: 0, total_tokens: 65 }, total_token_usage: { input_tokens: 20, output_tokens: 200, reasoning_output_tokens: 30, total_tokens: 250 } } } }) + L.push({ type: 'event_msg', timestamp: ts(38), payload: { type: 'task_complete', duration_ms: 8000 } }) + // --- task 3: OPEN at EOF (task_started + tokens, no task_complete) + L.push({ type: 'event_msg', timestamp: ts(50), payload: { type: 'task_started' } }) + L.push({ type: 'event_msg', timestamp: ts(52), payload: { type: 'token_count', info: { last_token_usage: { input_tokens: 7, output_tokens: 70, reasoning_output_tokens: 5, total_tokens: 82 }, total_token_usage: { input_tokens: 27, output_tokens: 270, reasoning_output_tokens: 35, total_tokens: 332 } } } }) + return L.map(o => JSON.stringify(o)) +} + +type Shot = Record + +async function snapshot(): Promise { + clearSessionCache() + const projects = await parseAllSessions() + const mb: Record = {} + let turns = 0, cost = 0, outTok = 0, inTok = 0 + for (const p of projects) for (const s of p.sessions) { + turns += (s.turns ?? []).length + for (const [model, d] of Object.entries(s.modelBreakdown)) { + const prev = (mb[model] as any) ?? { calls: 0, costUSD: 0, out: 0, activeDurationMs: 0, activeGeneratedTokens: 0, toolWaitMs: 0 } + mb[model] = { + calls: prev.calls + d.calls, + costUSD: +(prev.costUSD + d.costUSD).toFixed(10), + out: prev.out + d.tokens.outputTokens, + activeDurationMs: +(prev.activeDurationMs + (d.activeDurationMs ?? 0)).toFixed(6), + activeGeneratedTokens: prev.activeGeneratedTokens + (d.activeGeneratedTokens ?? 0), + toolWaitMs: +(prev.toolWaitMs + (d.toolWaitMs ?? 0)).toFixed(6), + } + cost += d.costUSD; outTok += d.tokens.outputTokens; inTok += d.tokens.inputTokens + } + } + return { modelBreakdown: mb, turns, cost: +cost.toFixed(10), outTok, inTok } +} + +const SESSION_DIR = join(CODEX_HOME, 'sessions', '2026', '04', '14') +const CACHE_DIR = join(testRoot, 'cache') +const ROLLOUT = join(SESSION_DIR, 'rollout-2026-04-14T10-00-00-adv.jsonl') + +// CODEX_HOME / CODEBURN_CACHE_DIR resolve at import time, so the roots stay +// fixed and each scenario wipes their CONTENTS instead of repointing them. +async function freshEnv(_tag: string) { + await rm(SESSION_DIR, { recursive: true, force: true }) + await rm(CACHE_DIR, { recursive: true, force: true }) + await mkdir(SESSION_DIR, { recursive: true }) + await mkdir(CACHE_DIR, { recursive: true }) + return ROLLOUT +} + +async function bump(file: string, n: number) { + const t = new Date(Date.now() + n * 60_000) + await utimes(file, t, t) +} + +describe('codex checkpoint resume: warm append equals cold parse', () => { + const lines = buildLines() + + it('cold full parse equals warm append parse at EVERY line split point', async () => { + const f0 = await freshEnv('cold') + await writeFile(f0, lines.join('\n') + '\n') + const cold = await snapshot() + expect((cold as any).outTok).toBeGreaterThan(0) + // sanity: timing actually got attributed somewhere + expect(Object.values((cold as any).modelBreakdown).some((d: any) => d.activeDurationMs > 0)).toBe(true) + + for (let split = 1; split < lines.length; split++) { + const f = await freshEnv(`warm-${split}`) + await writeFile(f, lines.slice(0, split).join('\n') + '\n') + await snapshot() // pass 1: prefix + await appendFile(f, lines.slice(split).join('\n') + '\n') + await bump(f, split + 1) + const warm = await snapshot() // pass 2: appended tail + expect({ split, warm }).toEqual({ split, warm: cold }) + } + }, 300_000) + + it('cold full parse equals a THREE-pass incremental parse across both task boundaries', async () => { + const f0 = await freshEnv('cold3') + await writeFile(f0, lines.join('\n') + '\n') + const cold = await snapshot() + + // Cuts that land mid-task on both appends, so every pass has to rebuild a + // window it did not open. The full cross product adds ~90 more parses for + // no extra mutation coverage. + for (const [a, b] of [[4, 9], [3, 12], [9, 13]] as const) { + const f = await freshEnv(`w3-${a}-${b}`) + await writeFile(f, lines.slice(0, a).join('\n') + '\n') + await snapshot() + await appendFile(f, lines.slice(a, b).join('\n') + '\n'); await bump(f, 1) + await snapshot() + await appendFile(f, lines.slice(b).join('\n') + '\n'); await bump(f, 2) + const warm = await snapshot() + expect({ a, b, warm }).toEqual({ a, b, warm: cold }) + } + }, 300_000) + + it('re-running warm twice is stable (idempotent)', async () => { + const f = await freshEnv('stable') + await writeFile(f, lines.slice(0, 9).join('\n') + '\n') + await snapshot() + await appendFile(f, lines.slice(9).join('\n') + '\n'); await bump(f, 1) + const first = await snapshot() + const second = await snapshot() + expect(second).toEqual(first) + }, 120_000) +}) diff --git a/packages/core/src/providers/codex/decode.ts b/packages/core/src/providers/codex/decode.ts index 7cd064fb1..62f4e04a6 100644 --- a/packages/core/src/providers/codex/decode.ts +++ b/packages/core/src/providers/codex/decode.ts @@ -579,10 +579,19 @@ export function decodeCodex({ records, state: prevState, seenKeys: liveSeen, ses continue } - // Closes a tool-wait interval opened by the matching function_call. Tool - // names and files were already collected there, so this branch is timing - // only. - if (entry.type === 'response_item' && entry.payload?.type === 'function_call_output') { + // Opens a tool-wait interval for Codex Desktop's custom-tool transport, + // which the branch's tool-name collection above does not speak yet. Timing + // only, exactly as codex-throughput.ts counts it. + if (entry.type === 'response_item' && entry.payload?.type === 'custom_tool_call') { + const callId = entry.payload.call_id + const started = entry.timestamp ? Date.parse(entry.timestamp) : NaN + if (!isForkReplay && callId && Number.isFinite(started)) openToolStarts.set(callId, started) + continue + } + + // Closes a tool-wait interval opened by the matching call. Tool names and + // files were already collected there, so this branch is timing only. + if (entry.type === 'response_item' && (entry.payload?.type === 'function_call_output' || entry.payload?.type === 'custom_tool_call_output')) { if (isForkReplay) continue const callId = entry.payload.call_id const ended = entry.timestamp ? Date.parse(entry.timestamp) : NaN diff --git a/packages/core/tests/providers/codex-decode.test.ts b/packages/core/tests/providers/codex-decode.test.ts index 515e12152..86bfb90b4 100644 --- a/packages/core/tests/providers/codex-decode.test.ts +++ b/packages/core/tests/providers/codex-decode.test.ts @@ -418,3 +418,52 @@ describe('codex decoder — task-timing checkpoint', () => { expect(calls[1]!.toolWaitMs).toBeUndefined() }) }) + +// One task carrying TWO token_counts, so a pass that resumes INSIDE it holds +// only part of the task's generated tokens. +const SPLIT_TASK_CORPUS: string[] = [ + sessionMeta({ session_id: 'sess-split', timestamp: '2026-04-14T10:00:00Z' }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-04-14T10:00:00Z', payload: { type: 'task_started' } }), + userMessage('two checkpoints', '2026-04-14T10:00:01Z'), + tokenCount({ timestamp: '2026-04-14T10:00:02Z', last: { input: 100, output: 100 }, total: { input: 100, output: 100, total: 200 } }), + tokenCount({ timestamp: '2026-04-14T10:00:04Z', last: { input: 100, output: 100 }, total: { input: 200, output: 200, total: 400 } }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-04-14T10:00:06Z', payload: { type: 'task_complete', duration_ms: 6_000 } }), +] + +describe('codex decoder — timing never lands on a partial task window', () => { + it('attributes the whole window across both calls in one pass', () => { + const cold = decodeCold(SPLIT_TASK_CORPUS) + expect(cold).toHaveLength(2) + expect(cold[0]!.activeDurationMs).toBe(3000) + expect(cold[1]!.activeDurationMs).toBe(3000) + }) + + it('attributes nothing when the pass holding task_complete never opened the window', () => { + // Resume from an end-of-file state (taskOpen false) with the tail carrying + // the task's SECOND token_count and its task_complete. Without the gate the + // tail would take the full 6s window for the one call it happens to hold — + // double its real share, and the first call would stay unattributed. + const first = decodeCodex({ records: SPLIT_TASK_CORPUS.slice(0, 4), context }) + const serialized: CodexDecodeState = JSON.parse(JSON.stringify(first.state)) + expect(serialized.taskOpen).toBe(false) + const second = decodeCodex({ records: SPLIT_TASK_CORPUS.slice(4), context, state: serialized }) + expect(second.calls).toHaveLength(1) + expect(second.calls[0]!.activeDurationMs).toBeUndefined() + expect(second.calls[0]!.toolWaitMs).toBeUndefined() + }) + + it('excludes custom-tool wait from active time, like a function_call pair', () => { + const records = [ + sessionMeta({ session_id: 'sess-custom', timestamp: '2026-04-14T10:00:00Z' }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-04-14T10:00:00Z', payload: { type: 'task_started' } }), + userMessage('run the tool', '2026-04-14T10:00:01Z'), + JSON.stringify({ type: 'response_item', timestamp: '2026-04-14T10:00:02Z', payload: { type: 'custom_tool_call', call_id: 'c1', name: 'exec' } }), + JSON.stringify({ type: 'response_item', timestamp: '2026-04-14T10:00:05Z', payload: { type: 'custom_tool_call_output', call_id: 'c1', output: 'ok' } }), + tokenCount({ timestamp: '2026-04-14T10:00:08Z', last: { input: 300, output: 100 }, total: { input: 300, output: 100, total: 400 } }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-04-14T10:00:10Z', payload: { type: 'task_complete', duration_ms: 10_000 } }), + ] + const calls = decodeCold(records) + expect(calls).toHaveLength(1) + expect(calls[0]).toMatchObject({ activeDurationMs: 7000, toolWaitMs: 3000 }) + }) +})