codeburn/tests/session-why.test.ts
2026-11-05 18:44:42 +01:00

521 lines
31 KiB
TypeScript
Raw Permalink Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

import { spawnSync } from 'node:child_process'
import { mkdir, mkdtemp, rm, writeFile } from 'node:fs/promises'
import { tmpdir } from 'node:os'
import { join } from 'node:path'
import { afterAll, beforeAll, describe, expect, it, vi } from 'vitest'
import { getModelCosts, loadPricing } from '../src/models.js'
import { buildSessionWhy, errorCause, findingText, fitWhyJson, redact, renderSessionWhyText, type SessionWhy, type WhyFinding } from '../src/session-why.js'
import { CLEARED, REDIRECTED } from './setup/env-isolation-vars.js'
const SID = '0c4f6c1e-5a7b-4e43-9d0e-2b1f7a6c9e10'
const FABLE = 'claude-fable-5-1'
const SONNET = 'claude-sonnet-5'
type Usage = { in?: number; out: number; cr: number; cw: number; cw1h?: number }
type Tool = { id: string; name: string; input: Record<string, unknown> }
// A tiny transcript writer: entries in time order, assistant messages streamed
// as one chunk per content block (same id, same usage) the way Claude Code writes them.
function transcript(start: string) {
let t = Date.parse(start)
let n = 0
const lines: string[] = []
const iso = () => new Date(t).toISOString()
const push = (e: Record<string, unknown>) => lines.push(JSON.stringify({ sessionId: SID, cwd: '/work/demo', timestamp: iso(), ...e }))
return {
lines,
wait: (ms: number) => { t += ms },
prompt: (text: string) => push({ type: 'user', message: { role: 'user', content: text } }),
note: (text: string) => push({ type: 'user', message: { role: 'user', content: [{ type: 'text', text }] } }),
call: (model: string, u: Usage, tools: Tool[] = [], streamMs = 2000) => {
const id = `msg_${++n}_${Math.random().toString(36).slice(2, 7)}`
const usage = { input_tokens: u.in ?? 2, output_tokens: u.out, cache_read_input_tokens: u.cr, cache_creation_input_tokens: u.cw, cache_creation: { ephemeral_5m_input_tokens: u.cw - (u.cw1h ?? 0), ephemeral_1h_input_tokens: u.cw1h ?? 0 } }
t += streamMs
push({ type: 'assistant', message: { id, role: 'assistant', model, content: [{ type: 'text', text: 'ok' }], usage } })
for (const tool of tools) push({ type: 'assistant', message: { id, role: 'assistant', model, content: [{ type: 'tool_use', ...tool }], usage } })
},
result: (id: string, text: string, ms: number, opts: { isError?: boolean; tur?: Record<string, unknown> } = {}) => {
t += ms
push({ type: 'user', message: { role: 'user', content: [{ type: 'tool_result', tool_use_id: id, content: text, is_error: opts.isError === true }] }, toolUseResult: opts.tur ?? {} })
},
raw: (e: Record<string, unknown>) => push(e),
}
}
const TRACEBACK = [
'Exit code 1',
'tests/test_parse.py F',
'error: something earlier looked wrong',
'Traceback (most recent call last):',
' File "/work/demo/tests/test_parse.py", line 9, in test_parse',
' parse("x")',
' File "/work/demo/src/parse.py", line 41, in parse',
' raise ValueError("bad token")',
'ValueError: bad token',
'1 failed in 0.20s',
].join('\n')
let home = ''
let why: SessionWhy
async function writeFixture(root: string): Promise<void> {
const dir = join(root, '.claude', 'projects', '-work-demo')
await mkdir(join(dir, SID, 'subagents'), { recursive: true })
const m = transcript('2026-09-10T10:00:00.000Z')
m.raw({ type: 'ai-title', aiTitle: 'Fix the parser' })
// Prompt 1: a failing test (traceback), an edit, the passing re-run.
m.prompt('Fix the parser bug and run the tests. token=sk-abcdefghijklmnop1234')
m.wait(1000)
m.call(FABLE, { out: 400, cr: 20_000, cw: 30_000, cw1h: 30_000 }, [{ id: 'b1', name: 'Bash', input: { command: 'cd /work/demo && pytest -q', description: 'Run the tests' } }])
m.result('b1', TRACEBACK, 3000, { isError: true })
m.call(FABLE, { out: 300, cr: 50_000, cw: 1_000, cw1h: 1_000 }, [{ id: 'e1', name: 'Edit', input: { file_path: '/work/demo/src/parse.py' } }])
m.result('e1', 'updated', 200, { tur: { structuredPatch: [{ oldStart: 40, oldLines: 1, newStart: 40, newLines: 1, lines: ['- raise ValueError("bad token")', '+ return None'] }] } })
m.call(FABLE, { out: 100, cr: 51_000, cw: 500, cw1h: 500 }, [{ id: 'b2', name: 'Bash', input: { command: 'pytest -q' } }])
m.result('b2', '1 passed', 2000)
m.call(FABLE, { out: 200, cr: 51_500, cw: 300, cw1h: 300 })
m.raw({ type: 'system', subtype: 'turn_duration', durationMs: 15_000 })
// Prompt 2: two helpers; helper 1 launches a nested helper. A background
// result arrives after 90s with nothing running, then a slow call.
m.wait(30_000)
m.prompt('Review both modules in parallel.')
m.wait(1000)
m.call(FABLE, { out: 600, cr: 51_800, cw: 900, cw1h: 900 }, [
{ id: 'a1', name: 'Agent', input: { description: 'Review module 1', prompt: 'p', subagent_type: 'general-purpose' } },
{ id: 'a2', name: 'Agent', input: { description: 'Review module 2', prompt: 'p', subagent_type: 'general-purpose' } },
])
m.result('a1', 'done', 20_000, { tur: { agentId: 'x1' } })
m.result('a2', 'done', 1000, { tur: { agentId: 'x2' } })
m.note('Another Claude session sent a message: review of module 2 is done')
m.call(FABLE, { out: 100, cr: 52_700, cw: 400, cw1h: 400 }, [{ id: 'b3', name: 'Bash', input: { command: 'sleep 1 &' } }])
m.result('b3', 'started', 1000)
m.result('bg', 'background job finished', 90_000)
m.call(FABLE, { out: 6_000, cr: 53_100, cw: 300, cw1h: 300 }, [], 70_000)
// Prompt 3: a large read rides along until the compaction.
m.wait(10_000)
m.prompt('Summarize the log.')
m.wait(1000)
m.call(FABLE, { out: 80, cr: 53_400, cw: 200, cw1h: 200 }, [{ id: 'r1', name: 'Read', input: { file_path: '/work/demo/app.log' } }])
m.result('r1', 'x'.repeat(60_000), 500, { tur: { file: { numLines: 1 } } })
m.call(FABLE, { out: 90, cr: 53_600, cw: 15_000, cw1h: 15_000 })
m.call(FABLE, { out: 90, cr: 68_600, cw: 100, cw1h: 100 })
m.wait(100)
m.raw({ type: 'system', subtype: 'compact_boundary' })
m.wait(1000)
m.call(FABLE, { out: 90, cr: 10_000, cw: 100, cw1h: 100 })
await writeFile(join(dir, `${SID}.jsonl`), m.lines.join('\n') + '\n')
const helper = async (agentId: string, toolUseId: string, description: string, calls: Array<{ u: Usage; tools?: Tool[] }>, start: string) => {
const h = transcript(start)
h.raw({ type: 'user', isSidechain: true, message: { role: 'user', content: 'review' } })
for (const c of calls) { h.wait(1000); h.call(SONNET, c.u, c.tools) }
await writeFile(join(dir, SID, 'subagents', `agent-${agentId}.jsonl`), h.lines.map(l => l.replace('"sessionId"', '"isSidechain":true,"sessionId"')).join('\n') + '\n')
await writeFile(join(dir, SID, 'subagents', `agent-${agentId}.meta.json`), JSON.stringify({ agentType: 'general-purpose', description, toolUseId }))
}
await helper('x1', 'a1', 'Review module 1', [
{ u: { out: 3_000, cr: 30_000, cw: 8_000, cw1h: 8_000 } },
{ u: { out: 2_000, cr: 38_000, cw: 4_000, cw1h: 4_000 }, tools: [{ id: 'n1', name: 'Agent', input: { description: 'Deep check' } }] },
{ u: { out: 1_000, cr: 42_000, cw: 1_000, cw1h: 1_000 } },
], '2026-09-10T10:00:50.000Z')
await helper('x2', 'a2', 'Review module 2', [
{ u: { out: 2_500, cr: 30_000, cw: 9_000, cw1h: 9_000 } },
{ u: { out: 1_500, cr: 39_000, cw: 2_000, cw1h: 2_000 } },
], '2026-09-10T10:00:51.000Z')
await helper('x3', 'n1', 'Deep check', [{ u: { out: 4_000, cr: 20_000, cw: 6_000, cw1h: 6_000 } }], '2026-09-10T10:00:58.000Z')
}
function cliEnv(): NodeJS.ProcessEnv {
const env = { ...process.env }
for (const key of CLEARED) delete env[key]
for (const key of REDIRECTED) env[key] = home
env.CLAUDE_CONFIG_DIR = join(home, '.claude')
env.CODEBURN_CACHE_DIR = join(home, '.cache', 'codeburn')
return env
}
const cli = (...args: string[]) => spawnSync(process.execPath, ['--import', 'tsx', 'src/cli.ts', ...args], { cwd: process.cwd(), env: cliEnv(), encoding: 'utf-8', timeout: 120_000 })
const find = <K extends WhyFinding['kind']>(kind: K) => why.findings.filter((f): f is Extract<WhyFinding, { kind: K }> => f.kind === kind)
beforeAll(async () => {
home = await mkdtemp(join(tmpdir(), 'codeburn-why-'))
await writeFixture(home)
await loadPricing()
why = await buildSessionWhy(join(home, '.claude', 'projects', '-work-demo', `${SID}.jsonl`))
})
afterAll(async () => { await rm(home, { recursive: true, force: true }) })
describe('session cost diagnosis: reconciliation', () => {
it('matches `codeburn sessions` for the session, its turns and its helpers', () => {
const run = cli('sessions', '--format', 'json', '--period', 'lifetime')
expect(run.status, run.stderr).toBe(0)
type Row = { sessionId: string; cost: number; calls: number; turns: number }
const rows = JSON.parse(run.stdout) as Array<Row & { subagents?: Row[] }>
const row = rows.find(r => r.sessionId === SID)!
expect(row).toBeDefined()
// The parent row folds its helpers in and lists them under `subagents`.
const helperRows = row.subagents ?? []
expect(helperRows).toHaveLength(3)
expect(rows.some(r => r.sessionId.startsWith('agent-'))).toBe(false)
const helpers = (pick: (r: Row) => number) => helperRows.reduce((s, r) => s + pick(r), 0)
const ownCost = row.cost - helpers(r => r.cost)
expect(Math.abs(why.cost - ownCost)).toBeLessThan(1e-9)
expect(Math.abs(why.turns.reduce((s, t) => s + t.cost, 0) - ownCost)).toBeLessThan(1e-9)
expect(why.calls).toBe(row.calls - helpers(r => r.calls))
// `sessions` counts the injected hand-back as its own turn; the view folds it into prompt 2.
expect(why.turns.length).toBe(row.turns - helpers(r => r.turns) - 1)
expect(Math.abs(why.helperCost - helpers(r => r.cost))).toBeLessThan(1e-9)
})
it('prints the same payload through `sessions --id <id> --why --format json`, and text by default', () => {
const json = cli('sessions', '--id', SID.slice(0, 8), '--why', '--format', 'json')
expect(json.status, json.stderr).toBe(0)
const payload = JSON.parse(json.stdout) as SessionWhy
expect(payload.cost).toBeCloseTo(why.cost, 12)
expect(payload.findings.map(f => f.kind)).toEqual(why.findings.map(f => f.kind))
const text = cli('sessions', '--id', SID, '--why')
expect(text.status, text.stderr).toBe(0)
expect(text.stdout).toContain('Worth a look, ranked by cost')
expect(cli('sessions', '--why').status).toBe(1)
})
})
describe('session cost diagnosis: independent recomputation', () => {
// Hand pricing from the rate table, not calculateCost: 1-hour cache writes at 1.6x.
const price = (model: string, u: Usage) => {
const c = getModelCosts(model)!
const cw1h = u.cw1h ?? 0
return { input: (u.in ?? 2) * c.inputCostPerToken, output: u.out * c.outputCostPerToken, cacheRead: u.cr * c.cacheReadCostPerToken, cacheWrite: (u.cw - cw1h) * c.cacheWriteCostPerToken + cw1h * c.cacheWriteCostPerToken * 1.6 }
}
const total = (p: ReturnType<typeof price>) => p.input + p.output + p.cacheRead + p.cacheWrite
const prompt1: Usage[] = [
{ out: 400, cr: 20_000, cw: 30_000, cw1h: 30_000 }, { out: 300, cr: 50_000, cw: 1_000, cw1h: 1_000 },
{ out: 100, cr: 51_000, cw: 500, cw1h: 500 }, { out: 200, cr: 51_500, cw: 300, cw1h: 300 },
]
it('turn cost and its parts', () => {
const parts = prompt1.map(u => price(FABLE, u))
const t1 = why.turns[0]!
expect(t1.cost).toBeCloseTo(parts.reduce((s, p) => s + total(p), 0), 12)
expect(t1.parts.cacheWrite).toBeCloseTo(parts.reduce((s, p) => s + p.cacheWrite, 0), 12)
expect(t1.parts.cacheRead).toBeCloseTo(parts.reduce((s, p) => s + p.cacheRead, 0), 12)
const sum = t1.parts.input + t1.parts.output + t1.parts.cacheRead + t1.parts.cacheWrite + t1.parts.webSearch
expect(Math.abs(sum - t1.cost)).toBeLessThan(1e-12)
})
it('helpers, nested ones counted under the prompt that launched their parent, repriced one tier down', () => {
const helperUsage: Usage[] = [
{ out: 3_000, cr: 30_000, cw: 8_000, cw1h: 8_000 }, { out: 2_000, cr: 38_000, cw: 4_000, cw1h: 4_000 }, { out: 1_000, cr: 42_000, cw: 1_000, cw1h: 1_000 },
{ out: 2_500, cr: 30_000, cw: 9_000, cw1h: 9_000 }, { out: 1_500, cr: 39_000, cw: 2_000, cw1h: 2_000 },
{ out: 4_000, cr: 20_000, cw: 6_000, cw1h: 6_000 },
]
const cost = helperUsage.reduce((s, u) => s + total(price(SONNET, u)), 0)
const haiku = helperUsage.reduce((s, u) => s + total(price('claude-haiku-4-5', u)), 0)
expect(why.turns[1]!.helperCost).toBeCloseTo(cost, 12)
const [f] = find('helpers')
expect(f).toMatchObject({ turn: 2, direct: 2, nested: 1, loose: 0, models: ['Sonnet 5'], descriptions: ['Review module 1', 'Review module 2'], calls: 6, minCalls: 1, maxCalls: 3 })
expect(f!.usd).toBeCloseTo(cost, 12)
expect(f!.share).toBeCloseTo(cost / (why.cost + cost), 12)
expect(f!.alt!.model).toBe('Haiku 4.5')
expect(f!.alt!.cost).toBeCloseTo(haiku, 12)
})
})
describe('session cost diagnosis: rules', () => {
it('flags the costly prompt with its median multiple and a one-tier-down repricing', () => {
const [f] = find('hotspot')
expect(f).toMatchObject({ turn: 1, calls: 4, toolCalls: 3, models: ['Fable 5.1'] })
expect(f!.share).toBeGreaterThanOrEqual(0.2)
expect(f!.alt!.model).toBe('Opus 5.5')
expect(f!.alt!.cost).toBeLessThan(f!.usd!)
})
it('names what ended a failed command and the calls up to the next successful Bash', () => {
const [f] = find('failed')
expect(f).toMatchObject({ turn: 1, tool: 'Bash', description: 'Run the tests', userStopped: false, afterCalls: 2 })
expect(f!.error).toMatchObject({ exitCode: 1, cause: 'ValueError: bad token', location: '/work/demo/src/parse.py, line 41' })
expect(f!.error.secondary).toContain('error: something earlier looked wrong')
const calls = why.turns[0]!.steps.filter(s => s.kind === 'model')
expect(f!.usd).toBeCloseTo(calls[1]!.cost + calls[2]!.cost, 12)
})
it('keeps time-only findings without dollars', () => {
const [idle] = find('idle')
expect(idle).toMatchObject({ turn: 2, usd: null, share: null, endedBy: 'tool' })
expect(renderSessionWhyText(why)).toContain('with nothing running')
expect(idle!.timeMs).toBe(90_000)
const [slow] = find('slowCall')
expect(slow).toMatchObject({ turn: 2, usd: null, model: 'Fable 5.1', outputTokens: 6_000 })
expect(slow!.timeMs).toBeGreaterThanOrEqual(70_000)
})
it('estimates a large result only until the next compaction', () => {
const [f] = find('carry')
expect(f).toMatchObject({ turn: 3, source: 'tool', tool: 'Read', chars: 60_000, tokens: 15_000, calls: 2, estimate: true })
const c = getModelCosts(FABLE)!
expect(f!.writeUsd).toBeCloseTo(15_000 * c.cacheWriteCostPerToken * 1.6, 12)
expect(f!.readUsd).toBeCloseTo(15_000 * c.cacheReadCostPerToken, 12)
expect(why.turns.map(x => x.compactions.length)).toEqual([0, 0, 1])
})
it('estimates the starting context from the first call and the later calls that read at least that much', () => {
const [f] = find('prefix')
const c = getModelCosts(FABLE)!
// Uncached input (2 tokens) is never re-read, so the threshold and re-read size are the cached 50,000.
expect(f).toMatchObject({ tokens: 50_002, cached: 50_000, uncached: 30_000, laterCalls: why.calls - 1, estimate: true })
const readers = why.turns.flatMap(t => t.steps).filter(s => s.kind === 'model' && s.tokens.cacheRead >= 50_000).length
expect(f!.readCalls).toBe(readers)
expect(f!.writeUsd).toBeCloseTo(30_000 * c.cacheWriteCostPerToken * 1.6, 12)
expect(f!.readUsd).toBeCloseTo(readers * 50_000 * c.cacheReadCostPerToken, 12)
})
it('flags re-reading when cache reads dominate', () => {
const share = why.parts.cacheRead / why.cost
expect(find('reread')).toHaveLength(share >= 0.5 ? 1 : 0)
})
it('ranks by dollars, time-only last, and the text output names every finding', () => {
const usd = why.findings.map(f => f.usd ?? -1)
expect(usd.slice(0, why.findings.filter(f => f.usd !== null).length)).toEqual([...usd.filter(x => x >= 0)].sort((a, b) => b - a))
const text = renderSessionWhyText(why)
expect(text).toContain('ValueError: bad token')
expect(text).toContain('If Haiku 4.5 can do these tasks')
})
})
describe('session cost diagnosis: request fields', () => {
type ModelStep = Extract<SessionWhy['turns'][number]['steps'][number], { kind: 'model' }>
type ToolStep = Extract<SessionWhy['turns'][number]['steps'][number], { kind: 'tool' }>
const models = (i: number) => why.turns[i]!.steps.filter((s): s is ModelStep => s.kind === 'model')
const tools = (i: number) => why.turns[i]!.steps.filter((s): s is ToolStep => s.kind === 'tool')
it('points each tool step at the model step that asked for it', () => {
expect(tools(0).map(s => [s.name, s.parent])).toEqual([['Bash', 0], ['Edit', 2], ['Bash', 4]])
expect(tools(1).map(s => [s.name, s.parent, why.turns[1]!.steps[s.parent]!.kind])).toEqual([['Agent', 0, 'model'], ['Agent', 0, 'model'], ['Bash', 3, 'model']])
})
it('marks tool calls that one message asked for together', () => {
expect(tools(1).map(s => s.parallel ?? null)).toEqual([{ index: 1, of: 2 }, { index: 2, of: 2 }, null])
expect(tools(0).every(s => s.parallel === undefined)).toBe(true)
expect(tools(2)[0]!.resultChars).toBe(60_000)
expect(tools(0)[1]!.resultChars).toBe('updated'.length)
})
it('gives each model step its cached share and role, and a cost basis only when not calculated', () => {
const m = models(0)
expect(m.map(s => [s.toolCalls, s.answer])).toEqual([[1, undefined], [1, undefined], [1, undefined], [0, true]])
expect(m[0]!.cachedPct).toBe(40)
expect(m.every(s => !('basis' in s))).toBe(true)
expect(models(1).map(s => s.toolCalls)).toEqual([2, 1, 0])
expect(models(1).at(-1)!.answer).toBe(true)
})
})
describe('session cost diagnosis: payload budget', () => {
const size = (w: SessionWhy) => Buffer.byteLength(JSON.stringify(w))
it('leaves a payload under budget alone and keeps the released tool step shape', () => {
expect(fitWhyJson(structuredClone(why))).toEqual(why)
const tools = why.turns.flatMap(t => [...t.steps, ...t.helpers.flatMap(h => h.steps)]).filter(s => s.kind === 'tool')
expect(tools.every(s => typeof s.isError === 'boolean' && 'detail' in s)).toBe(true)
})
it('drops whole step lists, cheapest helper first, then prompts, keeping totals and findings', () => {
const cheapest = why.turns.flatMap(t => t.helpers).filter(h => h.steps.length).sort((a, b) => a.cost - b.cost)[0]!
const fit = fitWhyJson(structuredClone(why), size(why) - 1)
expect(fit.turns.flatMap(t => t.helpers).find(h => h.id === cheapest.id)).toMatchObject({ steps: [], truncatedSteps: cheapest.steps.length })
expect(fit.turns.map(t => t.steps.length)).toEqual(why.turns.map(t => t.steps.length))
const all = fitWhyJson(structuredClone(why), 0)
expect(all.turns.every(t => t.steps.length === 0 && t.truncatedSteps && t.helpers.every(h => h.steps.length === 0))).toBe(true)
expect([all.cost, all.helperCost, all.findings]).toEqual([why.cost, why.helperCost, why.findings])
})
})
describe('session cost diagnosis: content', () => {
it('redacts secrets in prompts and output', () => {
expect(why.turns[0]!.prompt.text).not.toContain('sk-abcdefghijklmnop1234')
expect(redact('export API_KEY=abc123def456ghi')).toBe('export API_KEY=••••')
expect(redact('Authorization: Bearer eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiIxMjM0NTY3ODkwIn0.dozjgNryP4J3jVmNHl0w5N_XgL0n3I9PlFUP0THsR8U')).not.toContain('eyJzdWIi')
expect(redact('ghp_' + 'a'.repeat(36))).toBe('ghp_••••')
// Fake values assembled at runtime so secret scanners don't flag the fixture.
const fake = 'x'.repeat(24)
expect(redact(`key sk_${'live'}_${fake} and rk_${'test'}_${fake}`)).toBe('key sk_live_•••• and rk_test_••••')
expect(redact(`aws_secret_access_key = ${fake}/${fake}`)).toBe('aws_secret_access_key = ••••')
expect(redact('git clone https://deploy:hunter2secret@github.com/acme/app.git')).toBe('git clone https://deploy:••••@github.com/acme/app.git')
expect(redact('postgres://app:pa55w0rd@db.internal:5432/main')).toBe('postgres://app:••••@db.internal:5432/main')
})
it('keeps the edit diff and the command output for the steps', () => {
const steps = why.turns[0]!.steps.filter(s => s.kind === 'tool')
expect(steps.map(s => s.kind === 'tool' && s.name)).toEqual(['Bash', 'Edit', 'Bash'])
const edit = steps[1]!
expect(edit.kind === 'tool' && edit.detail?.diff).toContain('+ return None')
const bash = steps[0]!
expect(bash.kind === 'tool' && bash.detail?.output).toContain('ValueError: bad token')
})
it('errorCause skips trailing tallies and uses the last error line', () => {
expect(errorCause('Exit code 2\nsrc/a.ts(1,2): error TS2339: nope\nFound 1 error.').cause).toBe('src/a.ts(1,2): error TS2339: nope')
expect(errorCause('Exit code 1\nwarning: x\nfatal: not a git repository').exitCode).toBe(1)
})
})
describe('session cost diagnosis: prompt boundaries, helpers waiting, dates, rounding', () => {
const SID2 = '9a1d2c3b-0000-4e43-9d0e-2b1f7a6c9e11'
let why2: SessionWhy
beforeAll(async () => {
const dir = join(home, '.claude', 'projects', '-work-other')
await mkdir(join(dir, SID2, 'subagents'), { recursive: true })
const m = transcript('2026-09-10T10:00:00.000Z')
m.prompt('Run the build and review it.')
m.wait(1000)
m.call(FABLE, { out: 100, cr: 1_000, cw: 1_000 }, [{ id: 'f1', name: 'Bash', input: { command: 'npm run build' } }])
m.result('f1', 'Exit code 1\nerror TS2339: nope', 2000, { isError: true })
m.call(FABLE, { out: 100, cr: 2_000, cw: 100 }, [{ id: 'h1', name: 'Agent', input: { description: 'Review it' } }])
m.result('h1', 'started', 1000, { tur: { agentId: 'y1' } })
m.wait(90_000)
m.note('Another Claude session sent a message: review done')
m.call(FABLE, { out: 100, cr: 2_100, cw: 100 })
m.wait(26 * 3_600_000)
m.prompt('Try the build again tomorrow.')
m.wait(1000)
m.call(FABLE, { out: 100, cr: 2_200, cw: 100 }, [{ id: 'ok1', name: 'Bash', input: { command: 'npm run build' } }])
m.result('ok1', 'built', 2000)
m.call(FABLE, { out: 50, cr: 2_300, cw: 50 })
await writeFile(join(dir, `${SID2}.jsonl`), m.lines.join('\n') + '\n')
const h = transcript('2026-09-10T10:00:06.000Z')
h.call(SONNET, { out: 500, cr: 1_000, cw: 500 })
await writeFile(join(dir, SID2, 'subagents', 'agent-y1.jsonl'), h.lines.join('\n') + '\n')
await writeFile(join(dir, SID2, 'subagents', 'agent-y1.meta.json'), JSON.stringify({ agentType: 'general-purpose', description: 'Review it', toolUseId: 'h1' }))
why2 = await buildSessionWhy(join(dir, `${SID2}.jsonl`))
})
it('does not count calls in a later prompt as recovery from a failure', () => {
const f = why2.findings.find(x => x.kind === 'failed')
expect(f).toMatchObject({ turn: 1, usd: null, share: null, afterCalls: null })
expect(findingText(f!, why2).lines.join(' ')).not.toContain('After it')
})
it('calls a gap that ended with a helper reporting back waiting on helpers', () => {
const f = why2.findings.find(x => x.kind === 'idle')
expect(f).toMatchObject({ turn: 1, endedBy: 'helper' })
expect(findingText(f!, why2).title).toContain('waiting on helpers')
})
it('prints local dates and the end date when the session spans days', () => {
const local = (iso: string) => { const d = new Date(iso); return `${d.getFullYear()}-${String(d.getMonth() + 1).padStart(2, '0')}-${String(d.getDate()).padStart(2, '0')}` }
const header = renderSessionWhyText(why2).split('\n')[1]!
expect(header).toContain(local(why2.startedAt))
expect(header).toContain(local(why2.endedAt))
})
it('shows a saving that is the difference of the shown figures', () => {
const f = { id: 'x', kind: 'hotspot', turn: 1, usd: 1.006, share: 0.5, calls: 2, toolCalls: 0, models: ['Fable 5.1'], median: 0.4, parts: { input: 0, output: 1.006, cacheRead: 0, cacheWrite: 0, webSearch: 0 }, tokens: { input: 0, output: 1, cacheRead: 0, cacheWrite: 0 }, alt: { model: 'Opus 5.5', cost: 0.504 } } as WhyFinding
expect(findingText(f, why2).lines.join(' ')).toContain('the same tokens cost $0.50 (−$0.51)')
})
})
describe('session cost diagnosis: agents', () => {
const SID3 = '5e2b7c40-1111-4e43-9d0e-2b1f7a6c9e12'
const notice = (toolUseId: string, status: string, result: string) =>
`<task-notification>\n<task-id>t-${toolUseId}</task-id>\n<tool-use-id>${toolUseId}</tool-use-id>\n<output-file>/tmp/${toolUseId}.output</output-file>\n<status>${status}</status>\n<summary>Agent finished</summary>\n<result>${result}</result>\n<usage><subagent_tokens>1</subagent_tokens></usage>\n</task-notification>`
const launched = (agentId: string) => ({ tur: { isAsync: true, status: 'async_launched', agentId } })
let dir = ''
let why3: SessionWhy
type Agent = SessionWhy['turns'][number]['helpers'][number]
const agent = (w: SessionWhy, id: string) => w.turns[0]!.helpers.find(h => h.id === id) as Agent
beforeAll(async () => {
dir = join(home, '.claude', 'projects', '-work-agents')
await mkdir(join(dir, SID3, 'subagents'), { recursive: true })
const m = transcript('2026-09-10T10:00:00.000Z')
m.prompt('Scan and document the repo.')
m.wait(1000)
m.call(FABLE, { out: 200, cr: 40_000, cw: 2_000 }, [
{ id: 'q1', name: 'Agent', input: { description: 'Scan repo', prompt: 'Scan the repo for dead code.\n' + 'x'.repeat(3_970), subagent_type: 'Explore', run_in_background: true } },
{ id: 'q2', name: 'Agent', input: { description: 'Write docs', prompt: 'y'.repeat(800), subagent_type: 'general-purpose', run_in_background: true } },
{ id: 'q4', name: 'Agent', input: { description: 'Lint', prompt: 'lint', subagent_type: 'general-purpose', run_in_background: true } },
])
m.result('q1', 'Async agent launched successfully.', 5, launched('k1'))
m.result('q2', 'Async agent launched successfully.', 5, launched('k2'))
m.result('q4', 'Async agent launched successfully.', 5, launched('k4'))
m.call(FABLE, { out: 50, cr: 42_000, cw: 300 })
m.wait(20_000)
m.raw({ type: 'queue-operation', operation: 'enqueue', content: notice('q4', 'killed', '') })
m.wait(40_000)
m.raw({ type: 'queue-operation', operation: 'enqueue', content: notice('q1', 'completed', 'r'.repeat(2_000)) })
m.raw({ type: 'queue-operation', operation: 'dequeue' })
m.wait(3_000)
m.raw({ type: 'user', origin: { kind: 'task-notification' }, message: { role: 'user', content: notice('q1', 'completed', 'r'.repeat(2_000)) } })
m.call(FABLE, { out: 300, cr: 42_300, cw: 600 })
await writeFile(join(dir, `${SID3}.jsonl`), m.lines.join('\n') + '\n')
const helper = async (agentId: string, meta: Record<string, string>, start: string, write: (h: ReturnType<typeof transcript>) => void) => {
const h = transcript(start)
h.raw({ type: 'user', isSidechain: true, message: { role: 'user', content: 'task' } })
write(h)
await writeFile(join(dir, SID3, 'subagents', `agent-${agentId}.jsonl`), h.lines.join('\n') + '\n')
await writeFile(join(dir, SID3, 'subagents', `agent-${agentId}.meta.json`), JSON.stringify(meta))
}
await helper('k1', { agentType: 'Explore', description: 'Scan repo', toolUseId: 'q1' }, '2026-09-10T10:00:03.500Z', h => {
h.wait(1000); h.call(SONNET, { in: 3_000, out: 1_000, cr: 0, cw: 12_000 })
h.wait(1000); h.call(SONNET, { out: 400, cr: 15_000, cw: 1_000 }, [{ id: 'nn1', name: 'Agent', input: { description: 'Deep scan', prompt: 'z'.repeat(400), subagent_type: 'Explore', run_in_background: true } }])
h.result('nn1', 'Async agent launched successfully.', 5, launched('k3'))
h.wait(20_000)
h.raw({ type: 'user', origin: { kind: 'task-notification' }, message: { role: 'user', content: notice('nn1', 'completed', 'w'.repeat(1_200)) } })
h.wait(1000); h.call(SONNET, { out: 600, cr: 16_000, cw: 900 })
})
await helper('k3', { agentType: 'Explore', description: 'Deep scan', toolUseId: 'nn1' }, '2026-09-10T10:00:10.000Z', h => { h.wait(1000); h.call(SONNET, { out: 700, cr: 0, cw: 9_000 }) })
await helper('k2', { agentType: 'general-purpose', description: 'Write docs', toolUseId: 'q2' }, '2026-09-10T10:00:04.000Z', h => { h.wait(1000); h.call(SONNET, { out: 300, cr: 0, cw: 6_000 }) })
await helper('k4', { agentType: 'general-purpose', description: 'Lint', toolUseId: 'q4' }, '2026-09-10T10:00:04.000Z', h => { h.wait(1000); h.call(SONNET, { out: 100, cr: 0, cw: 5_000 }) })
why3 = await buildSessionWhy(join(dir, `${SID3}.jsonl`))
})
it('reads the hand-back from the queued notification and from the notification line, and ends the step there', () => {
const k1 = agent(why3, 'agent-k1')
expect(k1).toMatchObject({ parentId: null, agentType: 'Explore', background: true, state: 'done', task: 'Scan the repo for dead code.', taskTokensEst: 1_000, reportTokensEst: 500, handedBackIn: 3 })
expect([k1.delegatedAt, k1.handedBackAt]).toEqual(['2026-09-10T10:00:03.000Z', '2026-09-10T10:01:05.015Z'])
const k3 = agent(why3, 'agent-k3')
expect(k3).toMatchObject({ parentId: 'agent-k1', nested: true, state: 'done', reportTokensEst: 300, handedBackIn: 3, handedBackAt: '2026-09-10T10:00:29.505Z' })
const spawn = why3.turns[0]!.steps.find(s => s.kind === 'tool' && s.label === 'Scan repo')!
expect(spawn.end - spawn.start).toBe(62_015)
const nested = k1.steps.find(s => s.kind === 'tool')!
expect(nested.end - nested.start).toBe(20_005)
expect(k1.toolCalls).toBe(1)
})
it('marks helpers done, stopped by a kill or by the session ending, or still running', () => {
expect(['agent-k1', 'agent-k2', 'agent-k3', 'agent-k4'].map(id => agent(why3, id).state)).toEqual(['done', 'stopped', 'done', 'stopped'])
expect(agent(why3, 'agent-k4').handedBackAt).toBe('2026-09-10T10:00:25.015Z')
expect(agent(why3, 'agent-k2')).toMatchObject({ handedBackAt: null, handedBackIn: null, handBackCost: 0, reportTokensEst: 0 })
})
it('calls a helper with no hand-back running while it was active minutes ago', async () => {
vi.useFakeTimers({ toFake: ['Date'] })
vi.setSystemTime(new Date('2026-09-10T10:05:00.000Z'))
try {
const live = await buildSessionWhy(join(dir, `${SID3}.jsonl`))
expect(agent(live, 'agent-k2').state).toBe('running')
} finally { vi.useRealTimers() }
})
it('gives each request its usage row in order, and splits the cost by kind', () => {
const k1 = agent(why3, 'agent-k1')
const rows = k1.steps.filter(s => s.kind === 'model')
expect(rows.map(s => s.tokens)).toEqual([
{ input: 3_000, output: 1_000, cacheRead: 0, cacheWrite: 12_000 }, { input: 2, output: 400, cacheRead: 15_000, cacheWrite: 1_000 }, { input: 2, output: 600, cacheRead: 16_000, cacheWrite: 900 },
])
expect(rows.reduce((s, r) => s + r.cost, 0)).toBeCloseTo(k1.cost, 12)
expect(k1.requests).toBe(3)
expect(k1.firstCallAt).toBe('2026-09-10T10:00:03.500Z')
const p = k1.parts
expect(p.input + p.output + p.cacheRead + p.cacheWrite + p.webSearch).toBeCloseTo(k1.cost, 12)
const c = getModelCosts(SONNET)!
expect(k1.cacheSaving).toBeCloseTo(31_000 * (c.inputCostPerToken - c.cacheReadCostPerToken), 12)
expect(k1.handBackCost).toBeCloseTo(500 * getModelCosts(FABLE)!.cacheWriteCostPerToken, 12)
const t = why3.turns[0]!
expect(t.helperCost).toBeCloseTo(t.helpers.reduce((s, h) => s + h.cost, 0), 12)
})
})