diff --git a/CHANGELOG.md b/CHANGELOG.md index b741c511..e27dced3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -40,6 +40,7 @@ ### Fixed - **Mixed-version installs no longer thrash the Codex / Cursor / Antigravity result caches.** Daily and session caches already own a version-suffixed file so an old desktop binary and a newer CLI cannot clobber each other. The three per-provider result caches still used one unsuffixed filename with an internal version field, so a v10 and a v11 binary rewrote the same `codex-results.json` (and the Cursor / Antigravity siblings) on every run and each re-parsed its whole corpus. They now write `*-results.v.json` the same way the daily cache does. The unsuffixed file is left for older binaries; a matching-version copy is adopted once and never overwritten. (#1082) - **Codex spend no longer counts reasoning tokens twice, and cache writes are priced only where OpenAI actually charges for them.** OpenAI bills reasoning tokens as *part of* `output_tokens`, not on top of it — on a 1,396-rollout corpus all 134,316 events carrying a total satisfy `input + output == total` — but CodeBurn added `reasoning_output_tokens` to output when pricing a Codex call and again in the models, audit and per-model displays. Every Codex number was therefore too high: on that corpus **cost by $166.03 (3.5%)** and **displayed Output tokens by 34.6%** ($4,713.12 -> $4,547.09; 22.6M -> 16.8M output tokens). The raw `reasoningTokens` figure is unchanged and still reported on its own; only the double-count is gone. Both places that price a Codex call — the parser and the cache-rehydration re-price — now go through one shared `billableOutputTokens` helper, so a cold run and a warm run can never disagree. Separately, Codex's `cache_write_input_tokens` (new in codex PR #33454) was never read and cache-creation tokens were hardcoded to 0; they are now carved out of the uncached-input bucket and clamped so they can never exceed it. That carve-out happens **only on models whose pricing source publishes a real cache-write rate** — gpt-5.6 and its terra/sol/luna variants charge 1.25x input for a cache write, everything before it charges nothing extra — because CodeBurn fabricates a 1.25x rate when a source omits one, and charging that would have invented a surcharge on gpt-5.5, gpt-5.4, gpt-5.3-codex and gpt-5. On models without an explicit rate the tokens stay in the plain input bucket and the price is unchanged to the cent. The field is new enough that today's impact is $0 on that corpus. Codex sessions re-parse once and the daily cache re-derives once off the warm session cache (a global re-derivation of every day and every provider, since it has no per-provider invalidation); no other provider's numbers move. Days whose Codex transcripts have since aged out are held by the same never-lose guard #1040 relies on: a re-derivation that finds fewer calls than the settled baseline keeps the older, pre-fix (double-counted) total rather than truncating it, so those days do not pick up the repricing until their sources are re-derived with equal or greater evidence. Long-context pricing tiers from the same report are tracked separately in #1076 and the missing `gpt-5.6-codex` snapshot rows in #1077. Thanks @chr-evensen. (#1075) +- **Codex Tok/s no longer counts reasoning tokens twice or credits harness startup as model time.** Two distortions in the same metric, found and fixed together because they share the same cache-invalidation and test surface. (1) #1075 fixed the reasoning-token double-count for cost, but `activeGeneratedTokens`/`taskGeneratedTokens` in the Codex parser and `generatedTokens` in the `codex-tps` live-throughput reader still summed `outputTokens + reasoningTokens`; both now go through the same `billableOutputTokens('codex', …)` helper #1075 introduced, so the numerator can never drift from the billed one. (2) Codex fires `task_started` before it assembles the request, so the gap up to the first request-context event (`turn_context`, `world_state`, `event_msg/user_message`, or a `response_item/message`) was pure CLI/harness startup counted as active model time — the active window now starts at that first event instead, which matters most for one-shot `codex exec` sessions that pay the gap on every task. The duplicated tool-interval clip/merge/cap logic in `providers/codex.ts` and `codex-throughput.ts` is now one function (`mergeToolIntervals`, exported from `codex-throughput.ts`), which also closes a live trap where `task_complete`'s duration only parsed a plain number and silently dropped the `{secs,nanos}`/string forms `mcp_tool_call_end` already tolerated. (A third suspected distortion — fork-replay dedup dropping a token_count event's tokens from the numerator without shrinking the window to match — was investigated and retracted: the earlier `prevCumulativeTotal` guard already discards a repeated running total before dedup is ever reached, so a real Codex writer never produces a partial drop; the dedup site now carries a comment recording this so the trip isn't repeated.) Display only, no cost or token-count impact — verified byte-identical on the same real corpus. Combined effect on a real Codex corpus (original bug -> all fixes): GPT-5.5 37.8 -> 28.2 tok/s (-25.5%), Codex Auto Review 23.3 -> 20.0 (-14.2%), GPT-5.6 Sol 43.2 -> 33.9 (-21.4%), GPT-5.6 Luna 53.5 -> 49.0 (-8.5%), GPT-5.4 68.0 -> 43.6 (-35.9%), GPT-5.4 Mini 54.9 -> 55.6 (**+1.1%**, the harness-startup correction outweighing the reasoning-count correction for this model on this corpus). `activeGeneratedTokens`/`activeDurationMs`/`toolWaitMs` are stored verbatim in both the Codex result cache and the session cache rather than re-derived on read, so none of this self-heals: Codex sessions re-parse once (one cache-version bump covers both fixes, since they touch the same fields). The dashboard's per-model column stays labelled `Tok/s` — a wider label had zero room at the standard three-column layout, verified by breaking a real width-budget test — but the legend beneath it now reads "Effective Tok/s: generated tokens ÷ time the agent spent waiting on the model, tool execution excluded. Includes prefill, request assembly and reasoning. Not comparable to vendor decode-speed figures." (#1079, #1088) - **Codex calls attributed from session metadata no longer carry a stale model.** The Buffer fast path scanned `session_meta` for the first `"model"` string anywhere in the payload, so a nested `base_instructions.provenance.model` was read as if it were `payload.model` — and since the model is last-writer-wins state, that wrong value was credited to every call before the rollout's first `turn_context` and to every call after any mid-file `session_meta` (29 of 1380 rollouts on one real corpus carry a late `session_meta`, and 57 record usage before any `turn_context`). Direct payload fields are now read depth-aware, which is what the non-fast `JSON.parse` path always did. Codex sessions re-parse once (~9s on a 4 GB rollout corpus) and the daily cache re-derives once off the warm session cache, a global re-derivation of every day and every provider since it has no per-provider invalidation; it moves per-model attribution, and clears any rollup an earlier parse change had left stale. Days whose transcripts have partly aged out are held by the never-lose guard: on a real 110-day cache no day lost value and none disappeared — 100 days came back identical and 9 grok days rose by $19.80 in total. Thanks @timdp. (#1040) - **Codex `session_meta` cwd / session id / originator follow the same depth-1 window as `model`.** #1040 fixed nested `provenance.model`; the compact Buffer path still took the first `cwd`, `session_id`, `originator`, `name`, `forked_from_id` or `model_provider` anywhere in the payload, so a `dynamic_tools[].name` (or any same-named nested key) could steal the top-level field. Those strings now use the existing payload-depth-1 scan. Function-call `name` on other event types is unchanged. Codex sessions re-parse once. (#1045) - **Plan rows for sticker-price presets read as a budget instead of live provider quota.** There is no Grok quota endpoint, so a SuperGrok row was parsed API-equivalent spend divided by the plan's sticker price on a monthly reset — but the TUI labelled that math "plan" and "reset", which next to a client showing xAI's real weekly window read as CodeBurn being wrong. The bars and the arithmetic are unchanged; the words are not. Both the dashboard and the desktop app now say the number is an API-equivalent monthly budget and not a live provider window, in the same wording on both surfaces, and for every preset rather than as a SuperGrok special case. The window is anniversary-based (`plan.resetDay`, settable with `codeburn plan set --reset-day`), so it is called a budget reset rather than a calendar one. The row was also shortened to fit 80 columns: at that width the percentage and the projected month were being truncated away, including on custom plans, whose label carries the provider. diff --git a/src/codex-cache.ts b/src/codex-cache.ts index 70cc8e2b..a8e93d9e 100644 --- a/src/codex-cache.ts +++ b/src/codex-cache.ts @@ -27,7 +27,14 @@ import type { ParsedProviderCall } from './providers/types.js' // output, and cache_write_input_tokens is carved out of the input bucket. This // file stores each call's costUSD and token buckets verbatim, so entries // written by v10 carry the old (overstated) cost and must be re-derived. -export const CODEX_CACHE_VERSION = 11 +// v13: codex throughput fix (#1079) - activeGeneratedTokens was summing +// output + reasoning, the same double-count Fix A removed from cost. This +// file stores activeGeneratedTokens/activeDurationMs/toolWaitMs verbatim (not +// re-derived on read), so v11 entries carry the overstated numerator and must +// re-parse. Not 12: v12 is claimed by feat/core-extraction's own port of this +// throughput feature (PR #1086), so reusing it would let two incompatible +// schemas share a filename. +export const CODEX_CACHE_VERSION = 13 export const CODEX_LEGACY_CACHE_FILE = 'codex-results.json' export function codexCacheFileName(version = CODEX_CACHE_VERSION): string { return `codex-results.v${version}.json` diff --git a/src/codex-throughput.ts b/src/codex-throughput.ts index 4796206d..6bdb1583 100644 --- a/src/codex-throughput.ts +++ b/src/codex-throughput.ts @@ -1,6 +1,8 @@ import { open, stat } from 'node:fs/promises' import { StringDecoder } from 'node:string_decoder' +import { billableOutputTokens } from './models.js' + export type CodexThroughputPoint = { timestamp: string model?: string @@ -105,7 +107,12 @@ function durationMs(payload: RolloutLine['payload']): number | undefined { return undefined } -function mergeToolIntervals(intervals: Array<[number, number]>, durationMs: number, taskStartedAt?: number, taskCompletedAt?: number): number { +// Shared with src/providers/codex.ts (#1088 BUG-8): both clip a task's tool +// intervals to its [taskStartedAt, taskStartedAt + durationMs] window, merge +// overlaps, and cap the sum at durationMs. Was copy-pasted inline in +// providers/codex.ts and had already drifted (duration parsing there accepted +// only a plain `duration_ms` number); one copy now, called from both. +export function mergeToolIntervals(intervals: Array<[number, number]>, durationMs: number, taskStartedAt?: number, taskCompletedAt?: number): number { const windowStart = taskStartedAt ?? (taskCompletedAt !== undefined ? taskCompletedAt - durationMs : undefined) const windowEnd = windowStart !== undefined ? windowStart + durationMs : undefined const clipped = intervals.map(([start, end]) => [ @@ -400,7 +407,9 @@ export class CodexThroughputReader { state.previousOutput = total?.output_tokens ?? state.previousOutput state.previousReasoning = total?.reasoning_output_tokens ?? state.previousReasoning } - const generatedTokens = outputTokens + reasoningTokens + // Reasoning is already inside output_tokens (#1075/#1078); same numerator + // as the cost path so live Tok/s can't drift from billed tokens (#1079). + const generatedTokens = billableOutputTokens('codex', outputTokens, reasoningTokens) if (generatedTokens <= 0) return const timestampMs = Date.parse(entry.timestamp) if (!Number.isFinite(timestampMs)) return diff --git a/src/dashboard.tsx b/src/dashboard.tsx index 531836f3..0d8bf32e 100644 --- a/src/dashboard.tsx +++ b/src/dashboard.tsx @@ -746,6 +746,11 @@ function ModelBreakdown({ projects, pw, bw }: { projects: ProjectSummary[]; pw: const anyEstimated = Object.values(modelTotals).some(d => d.estimatedCostUSD > 0) const sorted = Object.entries(modelTotals).sort(([, a], [, b]) => b.costUSD - a.costUSD) const costLabels = sorted.map(([, data]) => markEstimated(formatCost(data.costUSD), data.estimatedCostUSD > 0)) + // #1088: this column has zero width slack left at the standard 3-column + // breakpoint (verified: widening the header even one character clips + // 'cache'/'1-shot' and drops the value column entirely), so the header stays + // "Tok/s" -- the legend below carries the "Effective Tok/s" framing and the + // caveat that it is not a vendor decode-speed figure. const headers = ['cost', 'cache', 'calls', '1-shot', 'Tok/s'] const values = sorted.map(([model, data], index) => { const totalInput = data.freshInput + data.cacheRead + data.cacheWrite @@ -806,7 +811,7 @@ function ModelBreakdown({ projects, pw, bw }: { projects: ProjectSummary[]; pw: {anyEstimated && ( ~ estimated cost (priced from estimated tokens) )} - ~ Tok/s: generated tokens / active time; tool wait excluded + ~ Effective Tok/s: generated tokens ÷ time the agent spent waiting on the model, tool execution excluded. Includes prefill, request assembly and reasoning. Not comparable to vendor decode-speed figures. ) } diff --git a/src/parser.ts b/src/parser.ts index 43137d74..071bde68 100644 --- a/src/parser.ts +++ b/src/parser.ts @@ -1768,7 +1768,7 @@ function buildSessionSummary( modelBreakdown[modelKey].tokens.reasoningTokens += call.usage.reasoningTokens if (call.activeDurationMs !== undefined) { modelBreakdown[modelKey].activeDurationMs = (modelBreakdown[modelKey].activeDurationMs ?? 0) + call.activeDurationMs - modelBreakdown[modelKey].activeGeneratedTokens = (modelBreakdown[modelKey].activeGeneratedTokens ?? 0) + (call.activeGeneratedTokens ?? call.usage.outputTokens + call.usage.reasoningTokens) + modelBreakdown[modelKey].activeGeneratedTokens = (modelBreakdown[modelKey].activeGeneratedTokens ?? 0) + (call.activeGeneratedTokens ?? billableOutputTokens(call.provider, call.usage.outputTokens, call.usage.reasoningTokens)) modelBreakdown[modelKey].toolWaitMs = (modelBreakdown[modelKey].toolWaitMs ?? 0) + (call.toolWaitMs ?? 0) } diff --git a/src/providers/codex.ts b/src/providers/codex.ts index 7693c7fa..e6aafe85 100644 --- a/src/providers/codex.ts +++ b/src/providers/codex.ts @@ -7,6 +7,7 @@ import { homedir } from 'os' import { readSessionLines } from '../fs-utils.js' import { billableOutputTokens, calculateCost, getModelCosts } from '../models.js' import { readCachedCodexResults, writeCachedCodexResults, getCachedCodexProject, fingerprintFile, type CodexFileFingerprint } from '../codex-cache.js' +import { mergeToolIntervals } from '../codex-throughput.js' import { normalizeContentBlocks } from '../content-utils.js' import { estimateTokensFromChars } from '../token-estimate.js' import type { ToolCall } from '../types.js' @@ -612,6 +613,12 @@ type CodexResumeState = { turnCounter: number currentTurnId: string taskStartedAt?: number + // #1088 BUG-1: timestamp of the first request-context event (turn_context, + // world_state, event_msg/user_message, or response_item/message) seen since + // the last task_started. Codex fires task_started before it assembles the + // request, so the gap up to this event is CLI/harness startup, not model + // wait -- the active window for Tok/s starts here, not at task_started. + taskActiveStartedAt?: number } // The state comes back off our own JSON cache; a truncated or hand-edited file @@ -720,6 +727,7 @@ function createParser(source: SessionSource, seenKeys: Set, capture?: { let taskGeneratedTokens = 0 let taskToolIntervals: Array<[number, number]> = [] let taskStartedAt: number | undefined = resume?.state.taskStartedAt + let taskActiveStartedAt: number | undefined = resume?.state.taskActiveStartedAt const openToolStarts = new Map() // Resume point for the NEXT run, refreshed at every task boundary. @@ -763,6 +771,22 @@ function createParser(source: SessionSource, seenKeys: Set, capture?: { continue } + // #1088 BUG-1: the first request-context event since task_started marks + // where model-request assembly actually began. Checked before any of + // these types `continue` below, and unconditionally (like turn_context's + // model capture above) so a forked replay's own request-context events + // still mark it -- matching how those events are already read regardless + // of isForkReplay, which only filters task boundaries and tool events. + if (taskActiveStartedAt === undefined && ( + entry.type === 'turn_context' + || entry.type === 'world_state' + || (entry.type === 'event_msg' && entry.payload?.type === 'user_message') + || (entry.type === 'response_item' && entry.payload?.type === 'message') + )) { + const ctxAt = entry.timestamp ? Date.parse(entry.timestamp) : NaN + if (Number.isFinite(ctxAt)) taskActiveStartedAt = ctxAt + } + if (entry.type === 'turn_context' && typeof entry.payload?.model === 'string') { sessionModel = entry.payload.model continue @@ -789,6 +813,7 @@ function createParser(source: SessionSource, seenKeys: Set, capture?: { taskToolIntervals = [] const startedAt = entry.timestamp ? Date.parse(entry.timestamp) : NaN taskStartedAt = Number.isFinite(startedAt) ? startedAt : undefined + taskActiveStartedAt = undefined openToolStarts.clear() // Everything decoded so far is now in `results` and the per-task // accumulators are empty: a clean restart point for an appended tail. @@ -817,6 +842,7 @@ function createParser(source: SessionSource, seenKeys: Set, capture?: { turnCounter, currentTurnId, ...(taskStartedAt !== undefined ? { taskStartedAt } : {}), + ...(taskActiveStartedAt !== undefined ? { taskActiveStartedAt } : {}), } continue } @@ -860,26 +886,33 @@ function createParser(source: SessionSource, seenKeys: Set, capture?: { } if (entry.type === 'event_msg' && entry.payload?.type === 'task_complete') { - const durationMs = entry.payload.duration_ms + // #1088 BUG-8: task_complete's duration can arrive as {secs,nanos} or + // a string too (mcp_tool_call_end already tolerates both, below, via + // this same durationValueMs helper); read it the same permissive way + // instead of only the plain-number `duration_ms` field. + const durationMs = durationValueMs(entry.payload.duration_ms) ?? durationValueMs(entry.payload.duration) if (typeof durationMs === 'number' && durationMs > 0 && taskGeneratedTokens > 0 && pendingTaskCalls.length > 0) { const completedAt = entry.timestamp ? Date.parse(entry.timestamp) : NaN - const windowStart = taskStartedAt ?? (Number.isFinite(completedAt) ? completedAt - durationMs : undefined) - const windowEnd = windowStart !== undefined ? windowStart + durationMs : undefined - const clipped = taskToolIntervals.map(([start, end]) => [ - windowStart !== undefined ? Math.max(start, windowStart) : start, - windowEnd !== undefined ? Math.min(end, windowEnd) : end, - ] as [number, number]).filter(([start, end]) => end > start) - const merged = clipped.sort((a, b) => a[0] - b[0]).reduce>((acc, interval) => { - const previous = acc.at(-1) - if (previous && interval[0] <= previous[1]) previous[1] = Math.max(previous[1], interval[1]) - else acc.push([...interval]) - return acc - }, []) - const toolWaitMs = Math.min(durationMs, merged.reduce((sum, interval) => sum + interval[1] - interval[0], 0)) - const activeMs = durationMs - toolWaitMs + // #1088 BUG-1: Codex fires task_started before it assembles the + // request, so the gap up to the first request-context event is + // CLI/harness startup, not model wait. The active window starts + // there instead of at task_started; task completion (windowEnd, + // inside mergeToolIntervals) is unchanged. + const activeWindowStart = taskActiveStartedAt ?? taskStartedAt + const startupGapMs = activeWindowStart !== undefined && taskStartedAt !== undefined + ? activeWindowStart - taskStartedAt + : 0 + const effectiveDurationMs = Math.max(0, durationMs - startupGapMs) + // #1088 BUG-8: shared with codex-throughput.ts's live estimate + // instead of a second inline copy of the same clip/merge/cap. + const toolWaitMs = mergeToolIntervals(taskToolIntervals, effectiveDurationMs, activeWindowStart, Number.isFinite(completedAt) ? completedAt : undefined) + const activeMs = effectiveDurationMs - toolWaitMs if (activeMs <= 0) continue for (const call of pendingTaskCalls) { - const generated = call.outputTokens + call.reasoningTokens + // Reasoning is already inside output_tokens (#1075/#1078); the + // throughput numerator must agree with the cost numerator or + // Tok/s reads high for reasoning-heavy calls (#1079). + const generated = billableOutputTokens('codex', call.outputTokens, call.reasoningTokens) if (generated <= 0) continue call.activeGeneratedTokens = generated call.activeDurationMs = activeMs * (generated / taskGeneratedTokens) @@ -1099,6 +1132,10 @@ function createParser(source: SessionSource, seenKeys: Set, capture?: { // key would spuriously diverge on a replay and double-count it. const dedupKey = `codex:${forkedFromId || sessionId}:${cumulativeTotal}:${total?.input_tokens ?? 0}:${total?.cached_input_tokens ?? 0}:${total?.output_tokens ?? 0}:${total?.reasoning_output_tokens ?? 0}` + // A drop here can only be a byte-identical replay: the + // prevCumulativeTotal guard above already discards a repeated + // running total, so nothing reaching this point ever loses real + // tokens -- no active-time rescaling needed (#1088 investigation). if (seenKeys.has(dedupKey)) continue seenKeys.add(dedupKey) @@ -1140,7 +1177,7 @@ function createParser(source: SessionSource, seenKeys: Set, capture?: { ...(pendingLocRemoved ? { locRemoved: pendingLocRemoved } : {}), ...(pendingEditFailed ? { editFailed: pendingEditFailed } : {}), }) - taskGeneratedTokens += outputTokens + reasoningTokens + taskGeneratedTokens += billableOutputTokens('codex', outputTokens, reasoningTokens) pendingTools = [] pendingToolSequence = [] diff --git a/src/session-cache.ts b/src/session-cache.ts index 3a5f9751..91929290 100644 --- a/src/session-cache.ts +++ b/src/session-cache.ts @@ -286,7 +286,11 @@ export const PROVIDER_PARSE_VERSIONS: Record = { // models with an explicit cache-write rate. The bucket move does NOT self-heal // on read (cached entries store the buckets, not the raw event), so cached // sessions must re-parse. - codex: 'mcp-attribution-v5-est-cost-active-timing-mcp-wait-rich-capture-v1-cross-provider-pr-v1-session-meta-model-v1-session-meta-fields-v1-codex-pricing-v1', + // codex-tps-v1 (#1079): activeGeneratedTokens summed output + reasoning, the + // same double-count codex-pricing-v1 removed from cost. Cached entries store + // activeGeneratedTokens/activeDurationMs/toolWaitMs verbatim (cachedCallToApiCall + // passes them through without recomputing), so this does NOT self-heal either. + codex: 'mcp-attribution-v5-est-cost-active-timing-mcp-wait-rich-capture-v1-cross-provider-pr-v1-session-meta-model-v1-session-meta-fields-v1-codex-pricing-v1-codex-tps-v1', cursor: 'composer-anchored-crediting-v1-est-cost', 'cursor-agent': 'workspaceless-transcript-v1', // source-provenance-v1 (#944): CLI sessions were misread as VS Code diff --git a/tests/codex-throughput.test.ts b/tests/codex-throughput.test.ts index 1e0fd4da..fa4fb2b5 100644 --- a/tests/codex-throughput.test.ts +++ b/tests/codex-throughput.test.ts @@ -21,8 +21,38 @@ describe('Codex throughput prototype', () => { const points = await readCodexThroughput(path) expect(points).toHaveLength(2) - expect(points[1]).toMatchObject({ generatedTokens: 50, elapsedSeconds: 5, generatedTokensPerSecond: 10, activeDurationSeconds: 7, activeGeneratedTokensPerSecond: 21.428571428571427, toolWaitSeconds: 3, model: 'gpt-5.6-sol' }) - expect(renderCodexThroughput(points, path)).toContain('21.4 generated tokens/sec') + // Reasoning is a subset of output_tokens (#1075/#1078), not additive: the + // checkpoints report output 80/40 and reasoning 20/10, so the generated + // numerator is output alone (80, then 40), matching the cost path. + expect(points[1]).toMatchObject({ generatedTokens: 40, elapsedSeconds: 5, generatedTokensPerSecond: 8, activeDurationSeconds: 7, activeGeneratedTokensPerSecond: (80 + 40) / 7, toolWaitSeconds: 3, model: 'gpt-5.6-sol' }) + expect(renderCodexThroughput(points, path)).toContain('17.1 generated tokens/sec') + }) + + it('REGRESSION (#1079): does not add reasoning tokens on top of output for Tok/s', async () => { + // Reasoning tokens are a SUBSET of output_tokens (#1075/#1078), not a + // separate bucket. A single checkpoint reporting output=60, reasoning=40 + // must drive Tok/s off 60, not 100 -- summing them would double-count 40 + // tokens that are already inside the 60. If this ever reverts to + // `outputTokens + reasoningTokens`, activeGeneratedTokensPerSecond becomes + // 10 (100 tokens / 10s) instead of 6 (60 tokens / 10s). + const dir = await mkdtemp(join(tmpdir(), 'codeburn-tps-regression-')) + const path = join(dir, 'rollout.jsonl') + await writeFile(path, [ + JSON.stringify({ type: 'session_meta', timestamp: '2026-07-25T00:00:00.000Z', payload: { model: 'gpt-5.5' } }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-07-25T00:00:00.000Z', payload: { type: 'task_started' } }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-07-25T00:00:10.000Z', payload: { type: 'token_count', info: { last_token_usage: { output_tokens: 60, reasoning_output_tokens: 40 }, total_token_usage: { total_tokens: 100, output_tokens: 60, reasoning_output_tokens: 40 } } } }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-07-25T00:00:10.000Z', payload: { type: 'task_complete', duration_ms: 10000 } }), + ].join('\n')) + + const points = await readCodexThroughput(path) + expect(points).toHaveLength(1) + expect(points[0]).toMatchObject({ + outputTokens: 60, + reasoningTokens: 40, + generatedTokens: 60, + taskGeneratedTokens: 60, + activeGeneratedTokensPerSecond: 6, + }) }) it('parses only appended complete lines while watching a growing rollout', async () => { @@ -36,7 +66,9 @@ describe('Codex throughput prototype', () => { await appendFile(path, first.slice(40) + '\n' + second + '\n') const points = await reader.update(path) expect(points).toHaveLength(2) - expect(points[1]).toMatchObject({ generatedTokens: 5, generatedTokensPerSecond: 5 }) + // second checkpoint: output 4 + reasoning 1 -> billable numerator is 4 + // (reasoning already inside output_tokens), not the additive 5. + expect(points[1]).toMatchObject({ generatedTokens: 4, generatedTokensPerSecond: 4 }) }) it('ignores replayed pre-fork checkpoints before estimating new work', async () => { diff --git a/tests/providers/codex.test.ts b/tests/providers/codex.test.ts index 66613174..198eb411 100644 --- a/tests/providers/codex.test.ts +++ b/tests/providers/codex.test.ts @@ -722,11 +722,58 @@ describe('codex provider - JSONL parsing', () => { reasoningTokens: 20, tools: ['Bash'], activeDurationMs: 7000, - activeGeneratedTokens: 120, + // Reasoning (20) is a subset of output_tokens (100), not additive + // (#1075/#1078/#1079): the billable/throughput numerator is 100, not 120. + activeGeneratedTokens: 100, toolWaitMs: 3000, }) }) + it('REGRESSION (#1088 BUG-1): excludes the task_started -> first request-context gap from active time', async () => { + // Codex fires task_started before it assembles the request; the 7s gap to + // the first request-context event (here, the user message) is CLI/harness + // startup, not model wait, and must not count toward active time. If this + // ever reverts to windowStart = taskStartedAt, activeDurationMs becomes + // 20000 (the full duration_ms) instead of 13000 (20000 - the 7s gap). + const filePath = await writeSession(tmpDir, '2026-04-14', 'rollout-startup-gap.jsonl', [ + sessionMeta({ session_id: 'sess-startup-gap', model: 'gpt-5.5' }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-04-14T10:00:00Z', payload: { type: 'task_started' } }), + userMessage('run the tool', '2026-04-14T10:00:07Z'), + tokenCount({ timestamp: '2026-04-14T10:00:20Z', last: { output: 100 }, total: { output: 100, total: 100 } }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-04-14T10:00:20Z', payload: { type: 'task_complete', duration_ms: 20_000 } }), + ]) + + const provider = createCodexProvider(tmpDir) + const source = { path: filePath, project: 'test', provider: 'codex' } + const calls: ParsedProviderCall[] = [] + for await (const call of provider.createSessionParser(source, new Set()).parse()) calls.push(call) + + expect(calls).toHaveLength(1) + expect(calls[0]).toMatchObject({ activeGeneratedTokens: 100, activeDurationMs: 13_000, toolWaitMs: 0 }) + }) + + it('#1088 BUG-8: reads a task_complete duration reported as {secs,nanos}, not only a plain number', async () => { + // mcp_tool_call_end already tolerates {secs,nanos} and string durations + // (durationValueMs); task_complete only read the plain-number duration_ms + // field, so a task_complete reported the object form was silently dropped + // (no active timing at all) instead of parsed. + const filePath = await writeSession(tmpDir, '2026-04-14', 'rollout-object-duration.jsonl', [ + sessionMeta({ session_id: 'sess-object-duration', model: 'gpt-5.5' }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-04-14T10:00:00Z', payload: { type: 'task_started' } }), + userMessage('run the tool', '2026-04-14T10:00:00Z'), + tokenCount({ timestamp: '2026-04-14T10:00:10Z', last: { output: 100 }, total: { output: 100, total: 100 } }), + JSON.stringify({ type: 'event_msg', timestamp: '2026-04-14T10:00:10Z', payload: { type: 'task_complete', duration: { secs: 10, nanos: 0 } } }), + ]) + + const provider = createCodexProvider(tmpDir) + const source = { path: filePath, project: 'test', provider: 'codex' } + const calls: ParsedProviderCall[] = [] + for await (const call of provider.createSessionParser(source, new Set()).parse()) calls.push(call) + + expect(calls).toHaveLength(1) + expect(calls[0]).toMatchObject({ activeGeneratedTokens: 100, activeDurationMs: 10_000 }) + }) + it('keeps estimated output parsing for large token lines without usage info', async () => { // Some rollout variants put token_count metadata beyond the compact head // or omit `info` entirely. The line must still reach the character-based