From ad9734c6374e5972fa8424d03cf5044e65ddf4fe Mon Sep 17 00:00:00 2001 From: JSONbored <49853598+JSONbored@users.noreply.github.com> Date: Mon, 13 Jul 2026 14:31:54 -0700 Subject: [PATCH 1/2] feat(miner): extract and persist real coding-agent token usage Both driver implementations now report a real tokensUsed count instead of always leaving it 0: the Agent SDK driver reads usage.input_tokens/ output_tokens off the SDK's own result message, and the CLI-subprocess driver ports src/selfhost/ai.ts's extractCliUsage to scan CLI JSON/JSONL stdout for the same signal. iterate-loop.ts sums this per-iteration total into finalMeterTotals.tokens (previously hardcoded 0), and attempt-cli.js surfaces it as totalTokensUsed and persists it on the attempt_outcome_summary ledger event alongside the existing cost/provider fields. Closes #5653 --- .../src/miner/agent-sdk-driver.ts | 18 +++ .../src/miner/cli-subprocess-driver.ts | 87 +++++++++---- .../src/miner/coding-agent-driver.ts | 4 + .../src/miner/iterate-loop.ts | 19 +-- .../test/agent-sdk-driver.test.ts | 117 ++++++++++++++++++ packages/gittensory-miner/lib/attempt-cli.js | 13 +- test/unit/agent-sdk-driver.test.ts | 115 +++++++++++++++++ test/unit/cli-subprocess-driver.test.ts | 102 +++++++++++++++ test/unit/miner-attempt-cli.test.ts | 69 +++++++---- test/unit/miner-attempt-runner.test.ts | 11 +- 10 files changed, 492 insertions(+), 63 deletions(-) diff --git a/packages/gittensory-engine/src/miner/agent-sdk-driver.ts b/packages/gittensory-engine/src/miner/agent-sdk-driver.ts index 3eeaa8be4f..24efcac60c 100644 --- a/packages/gittensory-engine/src/miner/agent-sdk-driver.ts +++ b/packages/gittensory-engine/src/miner/agent-sdk-driver.ts @@ -76,6 +76,20 @@ function asRecord(value: unknown): Record | null { return typeof value === "object" && value !== null ? (value as Record) : null; } +/** Real token count from the SDK's own result message (#5653). Both `SDKResultSuccess` and `SDKResultError` + * declare `usage: NonNullableUsage` unconditionally -- present whenever a result message arrived at all, same + * as `total_cost_usd`. `NonNullableUsage`'s `input_tokens`/`output_tokens` are themselves non-nullable numbers + * once `usage` exists, but this driver reads `resultMessage` as a loosely-typed record (like every other field + * read here), so both are re-validated defensively rather than trusted from an untyped source. Returns + * undefined (never a fabricated 0) when `usage` is absent or malformed. */ +function tokensFromResultMessage(resultMessage: Record | null): number | undefined { + const usage = asRecord(resultMessage?.usage); + const inputTokens = typeof usage?.input_tokens === "number" ? usage.input_tokens : undefined; + const outputTokens = typeof usage?.output_tokens === "number" ? usage.output_tokens : undefined; + if (inputTokens === undefined && outputTokens === undefined) return undefined; + return (inputTokens ?? 0) + (outputTokens ?? 0); +} + async function listWorktreeChangedFiles(cwd: string): Promise { const [tracked, untracked] = await Promise.all([ execFileAsync("git", ["-C", cwd, "diff", "--name-only", "HEAD", "--"]), @@ -168,6 +182,7 @@ export function createAgentSdkCodingAgentDriver( // or not (the session was billed either way), absent only when the stream produced no result message. const costUsd = typeof resultMessage?.total_cost_usd === "number" ? resultMessage.total_cost_usd : undefined; + const tokensUsed = tokensFromResultMessage(resultMessage); const resultText = typeof resultMessage?.result === "string" ? redactSecrets(resultMessage.result) : ""; const transcript = redactSecrets( @@ -194,6 +209,7 @@ export function createAgentSdkCodingAgentDriver( transcript, turnsUsed, costUsd, + tokensUsed, error: `agent_sdk_${subtype === "success" ? "errored" : subtype}`, }; } @@ -210,6 +226,7 @@ export function createAgentSdkCodingAgentDriver( transcript, turnsUsed, costUsd, + tokensUsed, error: `agent_sdk_changed_files_unavailable: ${detail}`, }; } @@ -222,6 +239,7 @@ export function createAgentSdkCodingAgentDriver( transcript, turnsUsed, costUsd, + tokensUsed, }; }, }; diff --git a/packages/gittensory-engine/src/miner/cli-subprocess-driver.ts b/packages/gittensory-engine/src/miner/cli-subprocess-driver.ts index 6721479e72..36d6cb907a 100644 --- a/packages/gittensory-engine/src/miner/cli-subprocess-driver.ts +++ b/packages/gittensory-engine/src/miner/cli-subprocess-driver.ts @@ -122,41 +122,69 @@ function resolveDefaultBuildArgs(command: string): (task: CodingAgentDriverTask) throw new Error(`unsupported_cli_subprocess_command:${command}`); } -/** Best-effort real dollar-cost extraction from a CLI's own stdout. Mirrors src/selfhost/ai.ts's - * `extractCliUsage`/`COST_KEYS` (redeclared here, not imported, per this file's own no-src-import - * convention) but narrowed to just the cost field this driver's `CodingAgentDriverResult` surfaces -- tokens - * and model aren't part of that shape. Tries the whole trimmed stdout as one JSON object first (claude's - * `--output-format json` shape, empirically confirmed to carry `total_cost_usd`, the exact same field name - * the Agent-SDK's own result message carries), then scans line by line (codex's `--json` JSONL stream, - * "still evolving" per src/selfhost/ai.ts's own comment, so multiple real key spellings are tolerated). A - * missing/malformed field means "no cost signal", never an error -- never fabricated. */ +/** Best-effort real dollar-cost AND token-usage extraction from a CLI's own stdout. Mirrors src/selfhost/ai.ts's + * `extractCliUsage`/`COST_KEYS`/`INPUT_TOKEN_KEYS`/`OUTPUT_TOKEN_KEYS`/`TOTAL_TOKEN_KEYS` (redeclared here, not + * imported, per this file's own no-src-import convention) -- ported in full as of #5653 (previously narrowed + * to just cost; tokens were left out at the time, not because the data doesn't exist). Tries the whole trimmed + * stdout as one JSON object first (claude's `--output-format json` shape, empirically confirmed to carry + * `total_cost_usd`, the exact same field name the Agent-SDK's own result message carries), then scans line by + * line (codex's `--json` JSONL stream, "still evolving" per src/selfhost/ai.ts's own comment, so multiple real + * key spellings are tolerated, and usage/token_usage/tokenUsage/usage_metadata sub-objects are all checked, same + * as src/selfhost/ai.ts). A missing/malformed field means "no signal", never an error -- never fabricated. */ const COST_KEYS = ["total_cost_usd", "totalCostUsd", "cost_usd", "costUsd"] as const; +const INPUT_TOKEN_KEYS = ["input_tokens", "inputTokens", "prompt_tokens", "promptTokens"] as const; +const OUTPUT_TOKEN_KEYS = ["output_tokens", "outputTokens", "completion_tokens", "completionTokens"] as const; +const TOTAL_TOKEN_KEYS = ["total_tokens", "totalTokens"] as const; + +type CliUsage = { costUsd?: number; inputTokens?: number; outputTokens?: number; totalTokens?: number }; function finiteNonNegativeNumber(value: unknown): number | undefined { const n = typeof value === "number" ? value : typeof value === "string" && value.trim() ? Number(value) : NaN; return Number.isFinite(n) && n >= 0 ? n : undefined; } -function costUsdFromRecord(record: Record): number | undefined { - let best: number | undefined; - for (const key of COST_KEYS) { +function maxNumber(record: Record, keys: readonly string[]): number | undefined { + let out: number | undefined; + for (const key of keys) { const n = finiteNonNegativeNumber(record[key]); - if (n !== undefined) best = Math.max(best ?? 0, n); + if (n !== undefined) out = Math.max(out ?? 0, n); } - return best; + return out; +} + +function asPlainRecord(value: unknown): Record | null { + return value && typeof value === "object" && !Array.isArray(value) ? (value as Record) : null; } -function extractCostUsd(stdout: string): number | undefined { +function mergeCliUsage(out: CliUsage, record: Record): void { + const nested = [ + record, + asPlainRecord(record.usage), + asPlainRecord(record.token_usage), + asPlainRecord(record.tokenUsage), + asPlainRecord(record.usage_metadata), + asPlainRecord(record.usageMetadata), + ].filter((entry): entry is Record => Boolean(entry)); + for (const entry of nested) { + const costUsd = maxNumber(entry, COST_KEYS); + if (costUsd !== undefined) out.costUsd = Math.max(out.costUsd ?? 0, costUsd); + const inputTokens = maxNumber(entry, INPUT_TOKEN_KEYS); + if (inputTokens !== undefined) out.inputTokens = Math.max(out.inputTokens ?? 0, inputTokens); + const outputTokens = maxNumber(entry, OUTPUT_TOKEN_KEYS); + if (outputTokens !== undefined) out.outputTokens = Math.max(out.outputTokens ?? 0, outputTokens); + const totalTokens = maxNumber(entry, TOTAL_TOKEN_KEYS); + if (totalTokens !== undefined) out.totalTokens = Math.max(out.totalTokens ?? 0, totalTokens); + } +} + +function extractCliUsage(stdout: string): CliUsage { + const usage: CliUsage = {}; const trimmed = stdout.trim(); - if (!trimmed) return undefined; - let best: number | undefined; + if (!trimmed) return usage; const tryLine = (text: string): void => { try { - const parsed = JSON.parse(text) as unknown; - if (parsed && typeof parsed === "object" && !Array.isArray(parsed)) { - const n = costUsdFromRecord(parsed as Record); - if (n !== undefined) best = Math.max(best ?? 0, n); - } + const parsed = asPlainRecord(JSON.parse(text)); + if (parsed) mergeCliUsage(usage, parsed); } catch { /* not JSON -- best-effort only */ } @@ -165,7 +193,16 @@ function extractCostUsd(stdout: string): number | undefined { for (const line of trimmed.split(/\r?\n/)) { if (line.trim()) tryLine(line); } - return best; + return usage; +} + +/** Real token count (input + output) from `extractCliUsage`'s CliUsage, when either is present -- prefers an + * explicit `totalTokens` key if the CLI reported one directly (never double-counted against input+output), + * otherwise sums input+output. Undefined (never a fabricated 0) when neither is present. */ +function totalTokensFromUsage(usage: CliUsage): number | undefined { + if (usage.totalTokens !== undefined) return usage.totalTokens; + if (usage.inputTokens === undefined && usage.outputTokens === undefined) return undefined; + return (usage.inputTokens ?? 0) + (usage.outputTokens ?? 0); } /** Claude Code's `--output-format json` sometimes exits non-zero while still emitting a structured @@ -328,13 +365,15 @@ export function createCliSubprocessCodingAgentDriver(options: CliSubprocessDrive }; } } - const costUsd = extractCostUsd(spawned.stdout); + const usage = extractCliUsage(spawned.stdout); + const tokensUsed = totalTokensFromUsage(usage); return { ok: true, changedFiles: [], summary: `${options.command} completed for ${task.attemptId}`, transcript, - ...(costUsd !== undefined ? { costUsd } : {}), + ...(usage.costUsd !== undefined ? { costUsd: usage.costUsd } : {}), + ...(tokensUsed !== undefined ? { tokensUsed } : {}), }; }, }; diff --git a/packages/gittensory-engine/src/miner/coding-agent-driver.ts b/packages/gittensory-engine/src/miner/coding-agent-driver.ts index 4d7993fad3..653fd153ea 100644 --- a/packages/gittensory-engine/src/miner/coding-agent-driver.ts +++ b/packages/gittensory-engine/src/miner/coding-agent-driver.ts @@ -23,6 +23,10 @@ export type CodingAgentDriverResult = { /** Real dollar cost of this driver run, when the provider reports one. Absent (not zero) when the provider * never got far enough to have a cost, or reports no cost signal at all -- never fabricated. */ costUsd?: number | undefined; + /** Real token count (input + output) of this driver run, when the provider reports one (#5653). Absent (not + * zero) when the provider never got far enough, or reports no token signal at all -- never fabricated, + * mirroring `costUsd`'s own convention. */ + tokensUsed?: number | undefined; error?: string | undefined; }; diff --git a/packages/gittensory-engine/src/miner/iterate-loop.ts b/packages/gittensory-engine/src/miner/iterate-loop.ts index 7961a45cbe..702c573c83 100644 --- a/packages/gittensory-engine/src/miner/iterate-loop.ts +++ b/packages/gittensory-engine/src/miner/iterate-loop.ts @@ -17,10 +17,10 @@ // // BOUNDED INSIDE THE LOOP: both the iteration ceiling (`input.maxIterations`) and the optional cumulative // budget (`input.budget`, evaluated every iteration via attempt-metering.ts's `accumulateAttemptUsage`/ -// `evaluateAttemptBudget` against real per-iteration turns/costUsd/wallClockMs -- tokens stays an honest 0, -// no driver reports a real token count today, #5395) are enforced here every iteration -- not left to an -// external caller to remember, and not just capped after the fact between loop cycles (loop-cli.js's own -// governor cap usage). A `maxIterations <= 0` input abandons immediately, before ever invoking the driver. +// `evaluateAttemptBudget` against real per-iteration turns/costUsd/wallClockMs/tokens, #5395/#5653) are +// enforced here every iteration -- not left to an external caller to remember, and not just capped after the +// fact between loop cycles (loop-cli.js's own governor cap usage). A `maxIterations <= 0` input abandons +// immediately, before ever invoking the driver. // // AUDITABLE: every iteration's decision (continue / handoff / abandon) is recorded via the injected // `appendAttemptLogEvent` dependency (attempt-log.ts's normalized event shape) before this function returns @@ -120,8 +120,8 @@ export type IterateLoopResult = { totalCostUsd: number; /** The real accumulated {@link AttemptMeterTotals} across every iteration that ran (attempt-metering.ts, * #5395) -- a superset of `totalTurnsUsed`/`totalCostUsd` above that also carries `wallClockMs` (real, - * measured around each driver invocation) and `tokens` (always 0 today -- no driver reports a real token - * count, an honest absence rather than a fabricated number). */ + * measured around each driver invocation) and `tokens` (real per-iteration token usage when the driver + * reports one, #5653 -- 0 for a driver/iteration that reports no token signal, never fabricated). */ finalMeterTotals: AttemptMeterTotals; /** The budget axes breached at the point this attempt abandoned, when `input.budget` was set and at least * one axis was at/over its ceiling -- empty when no budget was configured or none breached. */ @@ -328,10 +328,11 @@ async function runIterateLoopCore(input: IterateLoopInput, deps: IterateLoopDeps const iterationElapsedMs = Math.max(0, nowMs() - iterationStartMs); totalTurnsUsed += driverResult.turnsUsed ?? 0; totalCostUsd += driverResult.costUsd ?? 0; - // tokens stays an honest 0: no CodingAgentDriver reports a real per-iteration token count today (#5395) -- - // an absence, never a fabricated number, matching this package's costUsd discipline elsewhere. + // Real per-iteration tokens (#5653): CodingAgentDriverResult.tokensUsed is now populated by every driver + // that reports one (Agent SDK's own result-message usage, or CLI JSON/JSONL stdout) -- 0 only when the + // driver genuinely reports no token signal for this iteration, same honest-absence discipline as costUsd. tracker.totals = accumulateAttemptUsage(tracker.totals, { - tokens: 0, + tokens: driverResult.tokensUsed ?? 0, turns: driverResult.turnsUsed ?? 0, wallClockMs: iterationElapsedMs, costUsd: driverResult.costUsd ?? 0, diff --git a/packages/gittensory-engine/test/agent-sdk-driver.test.ts b/packages/gittensory-engine/test/agent-sdk-driver.test.ts index a2e42ea51d..86c1d99ec2 100644 --- a/packages/gittensory-engine/test/agent-sdk-driver.test.ts +++ b/packages/gittensory-engine/test/agent-sdk-driver.test.ts @@ -117,6 +117,123 @@ test("success fails closed when changed-file enumeration is unavailable, but sti assert.equal(result.costUsd, 0.0042); }); +test("success reports real input+output tokens from the SDK's own usage field (#5653)", async () => { + const driver = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "success", + is_error: false, + num_turns: 3, + result: "done", + total_cost_usd: 0.01, + usage: { input_tokens: 1000, output_tokens: 234 }, + }, + ]), + }); + + const result = await driver.run(task); + + assert.equal(result.ok, true); + assert.equal(result.tokensUsed, 1234); +}); + +test("failure (non-success subtype) still reports real tokens -- the session was billed either way, same as costUsd", async () => { + const driver = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "error_max_turns", + is_error: true, + num_turns: 6, + total_cost_usd: 0.05, + usage: { input_tokens: 500, output_tokens: 100 }, + }, + ]), + }); + + const result = await driver.run(task); + + assert.equal(result.ok, false); + assert.equal(result.tokensUsed, 600); +}); + +test("tokensUsed is undefined (never a fabricated 0) when the result message carries no usage field at all", async () => { + const driver = driverWith({ + query: queryYielding([ + { type: "result", subtype: "success", is_error: false, num_turns: 2, result: "done" }, + ]), + }); + + const result = await driver.run(task); + + assert.equal(result.ok, true); + assert.equal(result.tokensUsed, undefined); +}); + +test("tokensUsed is undefined when usage exists but is malformed (not an object, or non-numeric fields)", async () => { + const malformedUsage = driverWith({ + query: queryYielding([ + { type: "result", subtype: "success", is_error: false, num_turns: 2, result: "done", usage: "not-an-object" }, + ]), + }); + const malformedResult = await malformedUsage.run(task); + assert.equal(malformedResult.tokensUsed, undefined); + + const nonNumericFields = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "success", + is_error: false, + num_turns: 2, + result: "done", + usage: { input_tokens: "a lot", output_tokens: null }, + }, + ]), + }); + const nonNumericResult = await nonNumericFields.run(task); + assert.equal(nonNumericResult.tokensUsed, undefined); +}); + +test("tokensUsed sums whichever of input/output tokens IS a real number, when only input is present", async () => { + const driver = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "success", + is_error: false, + num_turns: 2, + result: "done", + usage: { input_tokens: 42 }, + }, + ]), + }); + + const result = await driver.run(task); + + assert.equal(result.tokensUsed, 42); +}); + +test("tokensUsed sums whichever of input/output tokens IS a real number, when only output is present", async () => { + const driver = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "success", + is_error: false, + num_turns: 2, + result: "done", + usage: { output_tokens: 17 }, + }, + ]), + }); + + const result = await driver.run(task); + + assert.equal(result.tokensUsed, 17); +}); + test("success stringifies a non-Error changed-file enumeration failure", async () => { const driver = driverWith({ query: queryYielding([ diff --git a/packages/gittensory-miner/lib/attempt-cli.js b/packages/gittensory-miner/lib/attempt-cli.js index 75ffa7c153..fc211cf139 100644 --- a/packages/gittensory-miner/lib/attempt-cli.js +++ b/packages/gittensory-miner/lib/attempt-cli.js @@ -466,6 +466,10 @@ export async function runAttempt(args, options = {}) { // is 0 for those -- an honest absence, not a fabricated number. totalTurnsUsed: result.loopResult.totalTurnsUsed, totalCostUsd: result.loopResult.totalCostUsd, + // Real accumulated tokens (#5653) -- read from finalMeterTotals rather than a flat totalTokensUsed field + // (IterateLoopResult has no such flat field, unlike turns/cost). 0 when no driver reported a token signal + // on any iteration this attempt ran, never fabricated. + totalTokensUsed: result.loopResult.finalMeterTotals.tokens, iterationsUsed: result.loopResult.iterationsUsed, ...("reason" in result ? { reason: result.reason } : {}), ...("decision" in result ? { decision: result.decision } : {}), @@ -481,10 +485,10 @@ export async function runAttempt(args, options = {}) { // AMS reporting export exposes -- distinct from the per-iteration attempt_started/attempt_tool_edit/... trail // iterate-loop.ts already writes. No fallback for an unconfigured provider: buildAttemptDeps already fails // closed (throws) on the same env before a worktree is even allocated, so reaching this point guarantees - // resolveFirstConfiguredCodingAgentDriverName(env) resolves a real name. tokensUsed is deliberately omitted - // (normalizes to null): no driver reports real token usage today (#5395), and null-for-"no signal" is more - // honest here than a fabricated 0. A logging failure must never fail an otherwise-successful attempt -- - // mirrors iterate-loop.ts's own safeAppendAttemptLogEvent non-fatal handling. + // resolveFirstConfiguredCodingAgentDriverName(env) resolves a real name. costUsd/tokensUsed are both real, + // driver-reported accumulated totals (#5653) -- 0 when no iteration's driver reported a signal, never + // fabricated. A logging failure must never fail an otherwise-successful attempt -- mirrors iterate-loop.ts's + // own safeAppendAttemptLogEvent non-fatal handling. try { attemptLog.appendAttemptLogEvent({ eventType: "attempt_outcome_summary", @@ -494,6 +498,7 @@ export async function runAttempt(args, options = {}) { reason: `attempt finished with outcome: ${result.outcome}`, provider: resolveFirstConfiguredCodingAgentDriverName(env), costUsd: finalResult.totalCostUsd, + tokensUsed: finalResult.totalTokensUsed, }); } catch { // Deliberately swallowed -- see comment above. diff --git a/test/unit/agent-sdk-driver.test.ts b/test/unit/agent-sdk-driver.test.ts index 26fdd8a6fa..7f870d610a 100644 --- a/test/unit/agent-sdk-driver.test.ts +++ b/test/unit/agent-sdk-driver.test.ts @@ -154,6 +154,121 @@ describe("createAgentSdkCodingAgentDriver", () => { expect(result.costUsd).toBe(0.0042); }); + it("reports real input+output tokens from the SDK's own usage field (#5653)", async () => { + const driver = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "success", + is_error: false, + num_turns: 3, + result: "done", + total_cost_usd: 0.01, + usage: { input_tokens: 1000, output_tokens: 234 }, + }, + ]), + }); + + const result = await driver.run(task); + + expect(result.ok).toBe(true); + expect(result.tokensUsed).toBe(1234); + }); + + it("still reports real tokens on a non-success subtype -- the session was billed either way, same as costUsd", async () => { + const driver = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "error_max_turns", + is_error: true, + num_turns: 6, + total_cost_usd: 0.05, + usage: { input_tokens: 500, output_tokens: 100 }, + }, + ]), + }); + + const result = await driver.run(task); + + expect(result.ok).toBe(false); + expect(result.tokensUsed).toBe(600); + }); + + it("tokensUsed is undefined (never a fabricated 0) when the result message carries no usage field at all", async () => { + const driver = driverWith({ + query: queryYielding([ + { type: "result", subtype: "success", is_error: false, num_turns: 2, result: "done" }, + ]), + }); + + const result = await driver.run(task); + + expect(result.ok).toBe(true); + expect(result.tokensUsed).toBeUndefined(); + }); + + it("tokensUsed is undefined when usage exists but is malformed (not an object, or non-numeric fields)", async () => { + const malformedUsage = driverWith({ + query: queryYielding([ + { type: "result", subtype: "success", is_error: false, num_turns: 2, result: "done", usage: "not-an-object" }, + ]), + }); + expect((await malformedUsage.run(task)).tokensUsed).toBeUndefined(); + + const nonNumericFields = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "success", + is_error: false, + num_turns: 2, + result: "done", + usage: { input_tokens: "a lot", output_tokens: null }, + }, + ]), + }); + expect((await nonNumericFields.run(task)).tokensUsed).toBeUndefined(); + }); + + it("tokensUsed sums whichever of input/output tokens IS a real number, when only input is present", async () => { + const driver = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "success", + is_error: false, + num_turns: 2, + result: "done", + usage: { input_tokens: 42 }, + }, + ]), + }); + + const result = await driver.run(task); + + expect(result.tokensUsed).toBe(42); + }); + + it("tokensUsed sums whichever of input/output tokens IS a real number, when only output is present", async () => { + const driver = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "success", + is_error: false, + num_turns: 2, + result: "done", + usage: { output_tokens: 17 }, + }, + ]), + }); + + const result = await driver.run(task); + + expect(result.tokensUsed).toBe(17); + }); + it("stringifies a non-Error changed-file enumeration failure", async () => { const driver = driverWith({ query: queryYielding([ diff --git a/test/unit/cli-subprocess-driver.test.ts b/test/unit/cli-subprocess-driver.test.ts index 523ee78278..49963b6095 100644 --- a/test/unit/cli-subprocess-driver.test.ts +++ b/test/unit/cli-subprocess-driver.test.ts @@ -474,6 +474,108 @@ describe("createCliSubprocessCodingAgentDriver (#4266)", () => { }); }); + describe("REGRESSION: real token-usage extraction, ported from src/selfhost/ai.ts's extractCliUsage (#5653)", () => { + it("sums claude's top-level input_tokens + output_tokens from its single JSON result on success", async () => { + const { spawn } = fakeSpawn({ + stdout: JSON.stringify({ type: "result", subtype: "success", result: "done", input_tokens: 1000, output_tokens: 234 }), + code: 0, + }); + const driver = createCliSubprocessCodingAgentDriver({ command: "claude", spawn }); + const result = await driver.run(TASK); + expect(result.tokensUsed).toBe(1234); + }); + + it("extracts tokens from a nested `usage` object, not just top-level fields", async () => { + const { spawn } = fakeSpawn({ + stdout: JSON.stringify({ usage: { input_tokens: 500, output_tokens: 100 } }), + code: 0, + }); + const driver = createCliSubprocessCodingAgentDriver({ command: "claude", spawn }); + const result = await driver.run(TASK); + expect(result.tokensUsed).toBe(600); + }); + + it("tolerates codex's alternate key spellings (camelCase) across a JSONL stream", async () => { + const { spawn } = fakeSpawn({ + stdout: '{"type":"start"}\n{"tokenUsage":{"inputTokens":50,"outputTokens":25}}\n{"type":"end"}', + code: 0, + }); + const driver = createCliSubprocessCodingAgentDriver({ command: "codex", spawn }); + const result = await driver.run(TASK); + expect(result.tokensUsed).toBe(75); + }); + + it("prefers an explicit total_tokens field over summing input+output, when the CLI reports one directly", async () => { + const { spawn } = fakeSpawn({ + stdout: JSON.stringify({ input_tokens: 100, output_tokens: 50, total_tokens: 999 }), + code: 0, + }); + const driver = createCliSubprocessCodingAgentDriver({ command: "claude", spawn }); + const result = await driver.run(TASK); + expect(result.tokensUsed).toBe(999); + }); + + it("takes the largest token value seen across a multi-event codex stream (cumulative, matches the cost convention)", async () => { + const { spawn } = fakeSpawn({ + stdout: '{"total_tokens":10}\n{"total_tokens":70}\n{"total_tokens":30}', + code: 0, + }); + const driver = createCliSubprocessCodingAgentDriver({ command: "codex", spawn }); + const result = await driver.run(TASK); + expect(result.tokensUsed).toBe(70); + }); + + it("stays undefined (never fabricated) when stdout carries no token field at all", async () => { + const { spawn } = fakeSpawn({ stdout: "plain text output, no JSON", code: 0 }); + const driver = createCliSubprocessCodingAgentDriver({ command: "claude", spawn }); + const result = await driver.run(TASK); + expect(result.ok).toBe(true); + expect(result.tokensUsed).toBeUndefined(); + }); + + it("ignores non-numeric/negative token field values instead of throwing or fabricating a number", async () => { + const { spawn } = fakeSpawn({ + stdout: JSON.stringify({ input_tokens: "a lot", output_tokens: -5 }), + code: 0, + }); + const driver = createCliSubprocessCodingAgentDriver({ command: "claude", spawn }); + const result = await driver.run(TASK); + expect(result.ok).toBe(true); + expect(result.tokensUsed).toBeUndefined(); + }); + + it("sums whichever of input/output tokens IS a real number, when only input is present", async () => { + const { spawn } = fakeSpawn({ + stdout: JSON.stringify({ input_tokens: 42 }), + code: 0, + }); + const driver = createCliSubprocessCodingAgentDriver({ command: "claude", spawn }); + const result = await driver.run(TASK); + expect(result.tokensUsed).toBe(42); + }); + + it("sums whichever of input/output tokens IS a real number, when only output is present", async () => { + const { spawn } = fakeSpawn({ + stdout: JSON.stringify({ output_tokens: 17 }), + code: 0, + }); + const driver = createCliSubprocessCodingAgentDriver({ command: "claude", spawn }); + const result = await driver.run(TASK); + expect(result.tokensUsed).toBe(17); + }); + + it("reports both a real cost and real tokens from the same result, independently", async () => { + const { spawn } = fakeSpawn({ + stdout: JSON.stringify({ total_cost_usd: 0.02, input_tokens: 10, output_tokens: 5 }), + code: 0, + }); + const driver = createCliSubprocessCodingAgentDriver({ command: "claude", spawn }); + const result = await driver.run(TASK); + expect(result.costUsd).toBe(0.02); + expect(result.tokensUsed).toBe(15); + }); + }); + describe("two-tier stalled-output timeout regression (#5196 — guards the #4994/#5053 CLI-stall outage)", () => { it("surfaces a distinct 'stalled' error (not a full timeout) when the CLI emits zero stdout past firstOutputTimeoutMs", async () => { // #4994/#5053: a claude/codex process that produced NO output was killed only at the full timeoutMs, masking diff --git a/test/unit/miner-attempt-cli.test.ts b/test/unit/miner-attempt-cli.test.ts index 5c81b2c9dd..0010ce79d4 100644 --- a/test/unit/miner-attempt-cli.test.ts +++ b/test/unit/miner-attempt-cli.test.ts @@ -53,6 +53,19 @@ function fakeCodingTaskSpec() { }; } +/** A minimal but real-shaped IterateLoopResult stand-in for a mocked runMinerAttempt result (#5653) -- + * attempt-cli.js reads `finalMeterTotals.tokens` unconditionally (the real loop always produces one), so + * every mocked `loopResult` needs one too, not just the flat totalTurnsUsed/totalCostUsd fields. */ +function fakeLoopResult(overrides: Record = {}) { + return { + totalTurnsUsed: 0, + totalCostUsd: 0, + iterationsUsed: 0, + finalMeterTotals: { tokens: 0, turns: 0, wallClockMs: 0, costUsd: 0 }, + ...overrides, + }; +} + /** The default set of injected options a test needs to reach past every real dependency and into (or * through) the final runMinerAttempt call, without doing any real network/git/subprocess work. */ function readyPipelineOptions(overrides: Record = {}) { @@ -313,7 +326,13 @@ describe("runAttempt (#5132)", () => { outcome: "submitted", spec: { command: "gh pr create", cwd: worktreeResult.worktreePath, timeoutMs: 1000 }, execResult: { code: 0 }, - loopResult: { outcome: "handoff", totalTurnsUsed: 3, totalCostUsd: 0.42, iterationsUsed: 2 }, + loopResult: fakeLoopResult({ + outcome: "handoff", + totalTurnsUsed: 3, + totalCostUsd: 0.42, + iterationsUsed: 2, + finalMeterTotals: { tokens: 1234, turns: 3, wallClockMs: 500, costUsd: 0.42 }, + }), }); const exitCode = await runAttempt(["acme/widgets", "7", "--miner-login", "alice", "--json"], { @@ -341,6 +360,7 @@ describe("runAttempt (#5132)", () => { submissionMode: "observe", totalTurnsUsed: 3, totalCostUsd: 0.42, + totalTokensUsed: 1234, iterationsUsed: 2, spec: { command: "gh pr create", cwd: worktreeResult.worktreePath, timeoutMs: 1000 }, execResult: { code: 0 }, @@ -387,8 +407,9 @@ describe("runAttempt (#5132)", () => { mode: "dry_run", provider: "noop", costUsd: 0.42, + // Real accumulated tokens (#5653), read the same way as costUsd -- from the loop's own finalMeterTotals. + tokensUsed: 1234, }); - expect(summaryCalls[0]).not.toHaveProperty("tokensUsed"); }); it("#5185: writes attempt_outcome_summary with the real provider/cost on a non-submitted outcome too", async () => { @@ -398,7 +419,7 @@ describe("runAttempt (#5132)", () => { const runMinerAttemptSpy = vi.fn().mockResolvedValue({ outcome: "abandon", reason: "self_review_ambiguous", - loopResult: { outcome: "abandon", totalTurnsUsed: 1, totalCostUsd: 0, iterationsUsed: 1 }, + loopResult: fakeLoopResult({ outcome: "abandon", totalTurnsUsed: 1, totalCostUsd: 0, iterationsUsed: 1 }), }); const exitCode = await runAttempt(["acme/widgets", "7", "--miner-login", "alice", "--json"], { @@ -428,7 +449,7 @@ describe("runAttempt (#5132)", () => { outcome: "submitted", spec: { command: "gh pr create", cwd: "/tmp/work", timeoutMs: 1000 }, execResult: { code: 0 }, - loopResult: { outcome: "handoff", totalTurnsUsed: 1, totalCostUsd: 0, iterationsUsed: 1 }, + loopResult: fakeLoopResult({ outcome: "handoff", totalTurnsUsed: 1, totalCostUsd: 0, iterationsUsed: 1 }), }); const brokenAttemptLog: AttemptLog = { dbPath: ":memory:", @@ -462,7 +483,7 @@ describe("runAttempt (#5132)", () => { outcome: "submitted", spec: { command: "gh pr create", cwd: "/fake", timeoutMs: 1000 }, execResult: { code: 0, stdout: "https://github.com/acme/widgets/pull/123\n", stderr: "", timedOut: false }, - loopResult: { outcome: "handoff", totalTurnsUsed: 3, totalCostUsd: 0.42, iterationsUsed: 2 }, + loopResult: fakeLoopResult({ outcome: "handoff", totalTurnsUsed: 3, totalCostUsd: 0.42, iterationsUsed: 2 }), }); const resolveClaimConflictSpy = vi.fn().mockResolvedValue({ checked: true, isWinner: true, winnerNumber: 123, competingCount: 0 }); @@ -516,7 +537,7 @@ describe("runAttempt (#5132)", () => { outcome: "submitted", spec: { command: "gh pr create", cwd: "/fake", timeoutMs: 1000 }, execResult: { code: 0, stdout: "https://github.com/acme/widgets/pull/9\n" }, - loopResult: {}, + loopResult: fakeLoopResult(), }), }), // resolveClaimConflict deliberately omitted -- exercises the real module-level default. @@ -544,7 +565,7 @@ describe("runAttempt (#5132)", () => { initEventLedger: () => eventLedger, initAttemptLog: () => attemptLog, initGovernorLedger: () => governorLedger, - ...readyPipelineOptions({ runMinerAttempt: async () => ({ outcome: "abandon", loopResult: {} }) }), + ...readyPipelineOptions({ runMinerAttempt: async () => ({ outcome: "abandon", loopResult: fakeLoopResult() }) }), resolveClaimConflict: resolveClaimConflictSpy, }); @@ -568,7 +589,7 @@ describe("runAttempt (#5132)", () => { outcome: "submitted", spec: { command: "gh pr create", cwd: "/fake", timeoutMs: 1000 }, execResult: { code: 0 }, - loopResult: {}, + loopResult: fakeLoopResult(), }), }), resolveClaimConflict: resolveClaimConflictSpy, @@ -595,7 +616,7 @@ describe("runAttempt (#5132)", () => { outcome: "submitted", spec: { command: "gh pr create", cwd: "/fake", timeoutMs: 1000 }, execResult: { code: 0, stdout: "https://github.com/acme/widgets/pull/6\n" }, - loopResult: {}, + loopResult: fakeLoopResult(), }), }), resolveClaimConflict: async () => lossResult, @@ -607,7 +628,7 @@ describe("runAttempt (#5132)", () => { it("resolves live mode only when --live is passed, and threads it through to the real loopInput", async () => { const { allocator, claimLedger, eventLedger, attemptLog, governorLedger } = tempLedgers(); const log = vi.spyOn(console, "log").mockImplementation(() => undefined); - const runMinerAttemptSpy = vi.fn().mockResolvedValue({ outcome: "abandon", loopResult: {} }); + const runMinerAttemptSpy = vi.fn().mockResolvedValue({ outcome: "abandon", loopResult: fakeLoopResult() }); const exitCode = await runAttempt(["acme/widgets", "7", "--miner-login", "alice", "--live", "--json"], { env: { MINER_CODING_AGENT_PROVIDER: "noop" }, @@ -635,7 +656,7 @@ describe("runAttempt (#5132)", () => { initEventLedger: () => eventLedger, initAttemptLog: () => attemptLog, initGovernorLedger: () => governorLedger, - ...readyPipelineOptions({ runMinerAttempt: async () => ({ outcome: "abandon", loopResult: {} }) }), + ...readyPipelineOptions({ runMinerAttempt: async () => ({ outcome: "abandon", loopResult: fakeLoopResult() }) }), }); expect(exitCode).toBe(7); @@ -643,9 +664,9 @@ describe("runAttempt (#5132)", () => { }); it.each([ - ["stale", 8, { outcome: "stale", reason: "expired", loopResult: {} }], - ["blocked", 9, { outcome: "blocked", decision: { allow: false }, loopResult: {} }], - ["governed", 10, { outcome: "governed", decision: { allowed: false }, loopResult: {} }], + ["stale", 8, { outcome: "stale", reason: "expired", loopResult: fakeLoopResult() }], + ["blocked", 9, { outcome: "blocked", decision: { allow: false }, loopResult: fakeLoopResult() }], + ["governed", 10, { outcome: "governed", decision: { allowed: false }, loopResult: fakeLoopResult() }], ] as const)("reports a real %s outcome with exit code %i", async (_label, expectedExitCode, mockResult) => { const { allocator, claimLedger, eventLedger, attemptLog, governorLedger } = tempLedgers(); const log = vi.spyOn(console, "log").mockImplementation(() => undefined); @@ -680,7 +701,7 @@ describe("runAttempt (#5132)", () => { initGovernorLedger: () => governorLedger, ...readyPipelineOptions({ cleanupAttemptWorktree: cleanupAttemptWorktreeSpy, - runMinerAttempt: async () => ({ outcome: "governed", decision: { allowed: false }, loopResult: {} }), + runMinerAttempt: async () => ({ outcome: "governed", decision: { allowed: false }, loopResult: fakeLoopResult() }), }), }); @@ -852,7 +873,7 @@ describe("runAttempt (#5132)", () => { initEventLedger: () => eventLedger, initAttemptLog: () => attemptLog, initGovernorLedger: () => governorLedger, - ...readyPipelineOptions({ resolveRejectionSignaled: resolveRejectionSignaledSpy, fetchImpl, runMinerAttempt: async () => ({ outcome: "abandon", loopResult: {} }) }), + ...readyPipelineOptions({ resolveRejectionSignaled: resolveRejectionSignaledSpy, fetchImpl, runMinerAttempt: async () => ({ outcome: "abandon", loopResult: fakeLoopResult() }) }), }); expect(resolveRejectionSignaledSpy).toHaveBeenCalledWith("acme/widgets", { fetchImpl }); @@ -931,7 +952,7 @@ describe("runAttempt (#5132)", () => { initEventLedger: () => eventLedger, initAttemptLog: () => attemptLog, initGovernorLedger: () => governorLedger, - ...readyPipelineOptions({ prepareAttemptWorktree: prepareAttemptWorktreeSpy, runMinerAttempt: async () => ({ outcome: "abandon", loopResult: {} }) }), + ...readyPipelineOptions({ prepareAttemptWorktree: prepareAttemptWorktreeSpy, runMinerAttempt: async () => ({ outcome: "abandon", loopResult: fakeLoopResult() }) }), }); expect(prepareAttemptWorktreeSpy).toHaveBeenCalledWith("acme/widgets", expect.any(String), expect.objectContaining({ baseBranch: "develop" })); @@ -949,7 +970,7 @@ describe("runAttempt (#5132)", () => { initEventLedger: () => eventLedger, initAttemptLog: () => attemptLog, initGovernorLedger: () => governorLedger, - ...readyPipelineOptions({ fetchSelfReviewContext: fetchSelfReviewContextSpy, runMinerAttempt: async () => ({ outcome: "abandon", loopResult: {} }) }), + ...readyPipelineOptions({ fetchSelfReviewContext: fetchSelfReviewContextSpy, runMinerAttempt: async () => ({ outcome: "abandon", loopResult: fakeLoopResult() }) }), }); expect(fetchSelfReviewContextSpy).toHaveBeenCalledWith("acme/widgets", { @@ -991,7 +1012,7 @@ describe("runAttempt (#5132)", () => { initAttemptLog: () => submittedLedgers.attemptLog, initGovernorLedger: () => submittedLedgers.governorLedger, ...readyPipelineOptions({ - runMinerAttempt: async () => ({ outcome: "submitted", spec: { command: "gh pr create", cwd: "/fake", timeoutMs: 1 }, execResult: { code: 0 }, loopResult: {} }), + runMinerAttempt: async () => ({ outcome: "submitted", spec: { command: "gh pr create", cwd: "/fake", timeoutMs: 1 }, execResult: { code: 0 }, loopResult: fakeLoopResult() }), }), onResult, }); @@ -1007,7 +1028,7 @@ describe("runAttempt: real per-repo kill switch (#5392)", () => { const worktreeResult = fakeWorktreeResult(); const resolveMinerGoalSpecSpy = vi.fn().mockReturnValue({ present: true, spec: { ...DEFAULT_MINER_GOAL_SPEC, killSwitch: { paused: true } }, warnings: [] }); const checkMinerKillSwitchSpy = vi.fn().mockReturnValue({ scope: "repo" as const, active: true }); - const runMinerAttemptSpy = vi.fn().mockResolvedValue({ outcome: "governed", decision: { allowed: false }, loopResult: {} }); + const runMinerAttemptSpy = vi.fn().mockResolvedValue({ outcome: "governed", decision: { allowed: false }, loopResult: fakeLoopResult() }); await runAttempt(["acme/widgets", "7", "--miner-login", "alice", "--json"], { env: { MINER_CODING_AGENT_PROVIDER: "noop" }, @@ -1036,7 +1057,7 @@ describe("runAttempt: real per-repo kill switch (#5392)", () => { const repoRoot = mkdtempSync(join(tmpdir(), "gittensory-miner-attempt-cli-repo-")); roots.push(repoRoot); writeFileSync(join(repoRoot, ".gittensory-miner.yml"), "killSwitch:\n paused: true\n"); - const runMinerAttemptSpy = vi.fn().mockResolvedValue({ outcome: "governed", decision: { allowed: false }, loopResult: {} }); + const runMinerAttemptSpy = vi.fn().mockResolvedValue({ outcome: "governed", decision: { allowed: false }, loopResult: fakeLoopResult() }); await runAttempt(["acme/widgets", "7", "--miner-login", "alice", "--json"], { env: { MINER_CODING_AGENT_PROVIDER: "noop" }, @@ -1063,7 +1084,7 @@ describe("runAttempt: real per-repo kill switch (#5392)", () => { vi.spyOn(console, "log").mockImplementation(() => undefined); const repoRoot = mkdtempSync(join(tmpdir(), "gittensory-miner-attempt-cli-repo-")); roots.push(repoRoot); - const runMinerAttemptSpy = vi.fn().mockResolvedValue({ outcome: "abandon", loopResult: {} }); + const runMinerAttemptSpy = vi.fn().mockResolvedValue({ outcome: "abandon", loopResult: fakeLoopResult() }); await runAttempt(["acme/widgets", "7", "--miner-login", "alice", "--json"], { env: { MINER_CODING_AGENT_PROVIDER: "noop" }, @@ -1101,7 +1122,7 @@ describe("runAttempt: real claim-ledger wiring (#5393)", () => { outcome: "submitted", spec: { command: "gh pr create", cwd: "/fake", timeoutMs: 1 }, execResult: { code: 0 }, - loopResult: {}, + loopResult: fakeLoopResult(), }; }); @@ -1134,7 +1155,7 @@ describe("runAttempt: real claim-ledger wiring (#5393)", () => { initEventLedger: () => eventLedger, initAttemptLog: () => attemptLog, initGovernorLedger: () => governorLedger, - ...readyPipelineOptions({ runMinerAttempt: async () => ({ outcome: "abandon", loopResult: {} }) }), + ...readyPipelineOptions({ runMinerAttempt: async () => ({ outcome: "abandon", loopResult: fakeLoopResult() }) }), }); expect(releaseClaimSpy).toHaveBeenCalledWith("acme/widgets", 7); diff --git a/test/unit/miner-attempt-runner.test.ts b/test/unit/miner-attempt-runner.test.ts index c5acc59633..7ceadb8e3d 100644 --- a/test/unit/miner-attempt-runner.test.ts +++ b/test/unit/miner-attempt-runner.test.ts @@ -92,8 +92,13 @@ function driverReturning(result: CodingAgentDriverResult): CodingAgentDriver { return { async run() { return result; } }; } -function okDriverResult(changedFiles: string[] = ["src/upload.ts"], turnsUsed = 5, costUsd = 0.42): CodingAgentDriverResult { - return { ok: true, changedFiles, summary: "added retry logic", turnsUsed, costUsd }; +function okDriverResult( + changedFiles: string[] = ["src/upload.ts"], + turnsUsed = 5, + costUsd = 0.42, + tokensUsed = 1234, +): CodingAgentDriverResult { + return { ok: true, changedFiles, summary: "added retry logic", turnsUsed, costUsd, tokensUsed }; } // ── Governor "everything allows" fixture, mirroring test/unit/miner-governor-chokepoint.test.ts's own ──────── @@ -162,6 +167,8 @@ describe("runMinerAttempt (#2337) — the real create->review->gate->submit pipe expect(result.loopResult.outcome).toBe("handoff"); // Real per-iteration driver costUsd summed into the loop result (#5135's loop needs this for budgetSpent). expect(result.loopResult.totalCostUsd).toBe(0.42); + // Real per-iteration driver tokensUsed summed into finalMeterTotals.tokens (#5653) -- was hardcoded 0 before. + expect(result.loopResult.finalMeterTotals.tokens).toBe(1234); }); it("defaults the open_pr body to an empty string when the loop input never set one", async () => { From 1fbf67752c33326b8dc3732af9d6d98e82552545 Mon Sep 17 00:00:00 2001 From: JSONbored <49853598+JSONbored@users.noreply.github.com> Date: Mon, 13 Jul 2026 14:38:37 -0700 Subject: [PATCH 2/2] fix(miner): add totalTokensUsed to AttemptCliResult's hand-maintained type attempt-cli.js's runtime finalResult object already carries this field (the previous commit) but the hand-maintained .d.ts was missed. --- packages/gittensory-miner/lib/attempt-cli.d.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/packages/gittensory-miner/lib/attempt-cli.d.ts b/packages/gittensory-miner/lib/attempt-cli.d.ts index 3dc05778e3..0699d6c4fb 100644 --- a/packages/gittensory-miner/lib/attempt-cli.d.ts +++ b/packages/gittensory-miner/lib/attempt-cli.d.ts @@ -42,6 +42,7 @@ export type AttemptCliResult = submissionMode: "observe" | "enforce"; totalTurnsUsed: number; totalCostUsd: number; + totalTokensUsed: number; iterationsUsed: number; reason?: string; decision?: unknown;