codeburn/tests/grok-parser-pipeline.test.ts
Resham Joshi 3c186491c3
fix(grok): read per-request usage from logs/unified.jsonl (#1677)
* fix(grok): read per-inference usage from logs/unified.jsonl

Grok Build keeps logging every inference to ~/.grok/logs/unified.jsonl after
its session dirs are gone, so CodeBurn showed $0 for that usage. Read
shell.turn.inference_done records (prompt includes cached, completion includes
reasoning), with the model from the session's model changed event and the
project from session created. Sessions that still have a session dir are
skipped so they are not counted twice. DAILY_CACHE_VERSION 65.

* fix(grok): prefer the unified log over session-dir rollups

A session with inference records in logs/unified.jsonl is now read from the
log, one call per request, and its session dir is skipped. Session dirs only
count for sessions the log no longer holds. This keeps history when session
dirs are deleted after the log was cached, and prices grok-4.6's long-context
tier per request instead of on a session total. Logged calls can move to an
earlier day than the rollup, so grok joins PENDING_REDERIVE at 65.

* fix(grok): re-read skipped session dirs after log rotation, keep their tools

A session dir the unified log holds parses to nothing, and its fingerprint
does not track the log, so a rotated or truncated log left that empty
result cached. Empty grok session-dir entries now re-parse.

The skipped dir's summary, tools, bash commands and subagents now ride on
that session's first logged call, and its model and cwd fill in when the
log names neither. A call whose model nothing names is priced as
grok-build and marked estimated.
2026-10-08 00:14:53 +02:00

310 lines
12 KiB
TypeScript

import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'
import { appendFile, mkdir, rm, writeFile } from 'fs/promises'
import { join } from 'path'
import { calculateCost } from '../src/models.js'
import { clearSessionCache, parseAllSessions } from '../src/parser.js'
// `chooseAuthoritativeModel` branches on whether a modelUsage id resolves to a
// price, so pin the reporter's real id from #998 as unpriced here rather than
// letting the bundled LiteLLM snapshot decide it: xAI pricing landing upstream
// would otherwise silently flip these assertions. Only this lookup is stubbed,
// so `calculateCost` still prices off the real tables.
vi.mock('../src/models.js', async (importOriginal) => {
const actual = await importOriginal<typeof import('../src/models.js')>()
return {
...actual,
getModelCosts: (model: string) => (model === 'grok-4.6-build' ? null : actual.getModelCosts(model)),
}
})
// The exported Grok provider resolves GROK_HOME when its singleton is created,
// before the test body runs. Set the root during module hoisting, then re-assert
// the call-time cache/env values in beforeEach after env-isolation runs.
const testRoot = vi.hoisted(() => {
const root = `${process.env['TMPDIR'] || '/tmp'}/grok-pipeline-${process.pid}-${Date.now()}`
process.env['GROK_HOME'] = `${root}/grok`
return root
})
const GROK_HOME = join(testRoot, 'grok')
const CACHE_DIR = join(testRoot, 'cache')
type UsageOptions = {
input: number
output: number
cacheRead?: number
cacheCreation?: number
reasoning?: number
model?: string
modelUsage?: Record<string, Record<string, unknown>>
}
type StreamingTurn = {
promptId: string
totals: number[]
}
type CompletedTurn = {
promptId?: string
usage: Record<string, unknown>
}
function usage(opts: UsageOptions): Record<string, unknown> {
const cacheRead = opts.cacheRead ?? 0
const cacheCreation = opts.cacheCreation ?? 0
const reasoning = opts.reasoning ?? 0
const model = opts.model ?? 'grok-build'
const singleModel = {
inputTokens: opts.input,
outputTokens: opts.output,
cachedReadTokens: cacheRead,
cacheCreationTokens: cacheCreation,
reasoningTokens: reasoning,
}
return {
inputTokens: opts.input,
outputTokens: opts.output,
cachedReadTokens: cacheRead,
cacheCreationTokens: cacheCreation,
reasoningTokens: reasoning,
modelUsage: opts.modelUsage ?? { [model]: singleModel },
}
}
async function writeSession(
record: Record<string, unknown>,
uuid = '019edf9c-0000-7000-8000-000000000101',
options: { turns?: StreamingTurn[]; completedTurns?: CompletedTurn[] } = {},
): Promise<void> {
const cwd = '/Users/test/grok-pipeline'
const dir = join(GROK_HOME, 'sessions', '%2FUsers%2Ftest%2Fgrok-pipeline', uuid)
await mkdir(dir, { recursive: true })
await writeFile(join(dir, 'summary.json'), JSON.stringify({
info: { id: uuid, cwd },
created_at: '2026-08-17T09:00:00.000Z',
updated_at: '2026-08-17T09:05:00.000Z',
current_model_id: 'grok-build',
session_summary: 'pipeline regression',
}))
await writeFile(join(dir, 'signals.json'), JSON.stringify({
primaryModelId: 'grok-build',
modelsUsed: ['grok-build'],
}))
const completedTurns = options.completedTurns ?? [{ promptId: 'pipeline-turn', usage: record }]
const lines: Record<string, unknown>[] = []
for (const turn of options.turns ?? []) {
for (const totalTokens of turn.totals) {
lines.push({
method: 'session/update',
params: {
sessionId: uuid,
_meta: { eventId: `stream-${turn.promptId}-${totalTokens}`, totalTokens, promptId: turn.promptId },
},
})
}
}
for (const [index, completed] of completedTurns.entries()) {
lines.push({
method: 'session/update',
params: {
sessionId: uuid,
update: {
sessionUpdate: 'turn_completed',
...(completed.promptId !== undefined ? { prompt_id: completed.promptId } : {}),
usage: completed.usage,
},
_meta: { eventId: `completed-${index}` },
},
})
}
await writeFile(join(dir, 'updates.jsonl'), lines.map(line => JSON.stringify(line)).join('\n') + '\n')
}
async function parseGrokSessions() {
const projects = await parseAllSessions(undefined, 'grok')
return projects.flatMap(project => project.sessions)
}
beforeEach(async () => {
clearSessionCache()
await rm(testRoot, { recursive: true, force: true })
process.env['GROK_HOME'] = GROK_HOME
process.env['CODEBURN_CACHE_DIR'] = CACHE_DIR
})
afterEach(async () => {
clearSessionCache()
await rm(testRoot, { recursive: true, force: true })
})
describe('Grok parser through the session-cache pipeline', () => {
it('keeps reasoning inside output pricing on both cold and warm parses', async () => {
await writeSession(usage({ input: 1000, output: 200, cacheRead: 500, cacheCreation: 100, reasoning: 150 }))
const cold = (await parseGrokSessions())[0]!
const coldCall = cold.turns[0]!.assistantCalls[0]!
clearSessionCache()
const warm = (await parseGrokSessions())[0]!
const warmCall = warm.turns[0]!.assistantCalls[0]!
const expected = calculateCost('grok-build', 400, 200, 100, 500, 0)
expect(cold.apiCalls).toBe(1)
expect(coldCall.costUSD).toBeCloseTo(expected, 12)
expect(warm.apiCalls).toBe(1)
expect(warmCall.costUSD).toBeCloseTo(expected, 12)
expect(warmCall.costUSD).not.toBeCloseTo(calculateCost('grok-build', 400, 350, 100, 500, 0), 12)
// Cost is only half of it: `models` and the audit report sum
// outputTokens + reasoningTokens for the token column. Emitting the
// provider's cache-inclusive output verbatim inflated that column by the
// reasoning tokens even once the cost was right, so pin the split and the
// sum the reports actually render.
const breakdown = Object.values(cold.modelBreakdown)[0]!
expect(breakdown.tokens.outputTokens).toBe(50) // 200 reported - 150 reasoning
expect(breakdown.tokens.reasoningTokens).toBe(150)
expect(breakdown.tokens.outputTokens + breakdown.tokens.reasoningTokens).toBe(200)
})
it('keeps one session call and uses top-level totals for a multi-model record', async () => {
await writeSession(usage({
input: 3000,
output: 300,
cacheRead: 600,
cacheCreation: 100,
reasoning: 30,
modelUsage: {
'grok-4.6-build': {
inputTokens: 2000,
outputTokens: 200,
cachedReadTokens: 500,
cacheCreationTokens: 100,
reasoningTokens: 20,
},
'grok-latest': {
inputTokens: 1000,
outputTokens: 100,
cachedReadTokens: 100,
cacheCreationTokens: 0,
reasoningTokens: 10,
},
},
}), '019edf9c-0000-7000-8000-000000000102')
const cold = (await parseGrokSessions())[0]!
const coldCalls = cold.turns.flatMap(turn => turn.assistantCalls)
const expected = calculateCost('grok-latest', 2300, 300, 100, 600, 0)
expect(cold.turns).toHaveLength(1)
expect(cold.apiCalls).toBe(1)
expect(coldCalls.map(call => call.model)).toEqual(['grok-latest'])
expect(coldCalls.map(call => call.usage.inputTokens)).toEqual([2300])
expect(coldCalls[0]!.usage.outputTokens + coldCalls[0]!.usage.reasoningTokens).toBe(300)
expect(cold.totalCostUSD).toBeCloseTo(expected, 12)
clearSessionCache()
const warm = (await parseGrokSessions())[0]!
expect(warm.turns).toHaveLength(1)
expect(warm.apiCalls).toBe(1)
expect(warm.totalCostUSD).toBeCloseTo(expected, 12)
})
it('falls back to the streaming estimate when usage exists only under modelUsage', async () => {
await writeSession({
modelUsage: {
'grok-4.6-build': {
inputTokens: 1000,
outputTokens: 100,
},
},
}, '019edf9c-0000-7000-8000-000000000103', {
turns: [{ promptId: 'legacy-turn', totals: [1000, 1200] }],
})
const sessions = await parseGrokSessions()
expect(sessions).toHaveLength(1)
const call = sessions[0]!.turns[0]!.assistantCalls[0]!
expect(call.isEstimated).toBe(true)
expect(call.usage.outputTokens).toBe(200)
})
it('uses the final deduplicated record when deciding whether to estimate', async () => {
await writeSession({}, '019edf9c-0000-7000-8000-000000000104', {
turns: [{ promptId: 'superseded-turn', totals: [1000, 1200] }],
completedTurns: [
{ promptId: 'superseded-turn', usage: usage({ input: 1000, output: 100 }) },
{ promptId: 'superseded-turn', usage: {} },
],
})
const sessions = await parseGrokSessions()
expect(sessions).toHaveLength(1)
const call = sessions[0]!.turns[0]!.assistantCalls[0]!
expect(call.isEstimated).toBe(true)
expect(call.usage.outputTokens).toBe(200)
})
it('marks a mixed authoritative session estimated when a streamed turn has no record', async () => {
await writeSession(usage({ input: 1000, output: 100 }), '019edf9c-0000-7000-8000-000000000105', {
turns: [
{ promptId: 'pre-upgrade-turn', totals: [1000, 1400] },
{ promptId: 'authoritative-turn', totals: [1400, 1600] },
],
completedTurns: [{ promptId: 'authoritative-turn', usage: usage({ input: 800, output: 80 }) }],
})
const sessions = await parseGrokSessions()
expect(sessions).toHaveLength(1)
const call = sessions[0]!.turns[0]!.assistantCalls[0]!
expect(call.isEstimated).toBe(true)
expect(call.usage.inputTokens).toBe(800)
expect(call.usage.outputTokens + call.usage.reasoningTokens).toBe(80)
})
it('clamps reasoning to reported output before the real pipeline prices the call', async () => {
await writeSession(usage({ input: 1000, output: 100, cacheRead: 500, cacheCreation: 100, reasoning: 250 }), '019edf9c-0000-7000-8000-000000000106')
const sessions = await parseGrokSessions()
const call = sessions[0]!.turns[0]!.assistantCalls[0]!
const expected = calculateCost('grok-build', 400, 100, 100, 500, 0)
expect(call.usage.outputTokens).toBe(0)
expect(call.usage.reasoningTokens).toBe(100)
expect(call.usage.outputTokens + call.usage.reasoningTokens).toBe(100)
expect(call.costUSD).toBeCloseTo(expected, 12)
clearSessionCache()
const warmCall = (await parseGrokSessions())[0]!.turns[0]!.assistantCalls[0]!
expect(warmCall.costUSD).toBeCloseTo(expected, 12)
})
it('reads a logged session from the log, then from its dir once the log no longer holds it', async () => {
const uuid = '019edf9c-0000-7000-8000-000000000107'
await writeSession(usage({ input: 1000, output: 100 }), uuid)
const dir = join(GROK_HOME, 'sessions', '%2FUsers%2Ftest%2Fgrok-pipeline', uuid)
await appendFile(join(dir, 'updates.jsonl'), JSON.stringify({
method: 'session/update',
params: { sessionId: uuid, update: { sessionUpdate: 'tool_call', title: 'run_terminal_command', rawInput: { command: 'git status' } } },
}) + '\n')
const logPath = join(GROK_HOME, 'logs', 'unified.jsonl')
await mkdir(join(GROK_HOME, 'logs'), { recursive: true })
const inference = (ts: string) => JSON.stringify({
ts, pid: 1, msg: 'shell.turn.inference_done', sid: uuid,
ctx: { loop_index: 1, prompt_tokens: 500, cached_prompt_tokens: 0, completion_tokens: 50, reasoning_tokens: 0 },
})
await writeFile(logPath, [inference('2026-08-17T09:01:00.000Z'), inference('2026-08-17T09:02:00.000Z')].join('\n') + '\n')
const logged = (await parseGrokSessions())[0]!
const calls = logged.turns.flatMap(turn => turn.assistantCalls)
expect(calls.map(call => call.deduplicationKey.startsWith('grok:unified:'))).toEqual([true, true])
expect(logged.turns[0]!.userMessage).toBe('pipeline regression')
expect(calls[0]!.bashCommands).toEqual(['git'])
expect(calls[1]!.tools).toEqual([])
expect(calls[0]!.isEstimated).toBeFalsy()
await writeFile(logPath, JSON.stringify({ ts: '2026-08-18T00:00:00.000Z', pid: 2, msg: 'AuthManager::new' }) + '\n')
clearSessionCache()
const rotated = (await parseGrokSessions())[0]!
expect(rotated.apiCalls).toBe(1)
expect(rotated.turns[0]!.assistantCalls[0]!.deduplicationKey).not.toContain('unified')
})
})