From 61bfa1b2a371524b4496b172754e03dae2d6e1c0 Mon Sep 17 00:00:00 2001 From: JSONbored <49853598+JSONbored@users.noreply.github.com> Date: Fri, 31 Jul 2026 05:11:45 -0700 Subject: [PATCH] fix(observability): report the miner's real input/output token split to PostHog Both engine coding-agent drivers read input and output tokens separately and then returned only their sum, so CodingAgentDriverResult carried a single blended tokensUsed. The miner's $ai_generation capture had nothing real to put in $ai_input_tokens/$ai_output_tokens and hardcoded them to 0, emitting the true figure under a non-standard tokens_used property that PostHog's own cost views do not read -- so miner spend registered there as zero tokens across the board. Carry inputTokens/outputTokens on the driver result, populated by both drivers from values they already had, and report them. The split is still never fabricated: a CLI that reports only total_tokens leaves it absent and the blended figure keeps riding in tokens_used, and a side that is missing or out-of-contract (negative/NaN/Infinity) stays absent rather than becoming a 0 that is indistinguishable from a real 0 once aggregated. Closes #10198 --- .../src/miner/agent-sdk-driver.ts | 27 +++++-- .../src/miner/cli-subprocess-driver.ts | 20 +++-- .../src/miner/coding-agent-driver.ts | 11 +++ .../test/agent-sdk-driver.test.ts | 76 +++++++++++++++++++ .../lib/coding-agent-construction.ts | 8 +- packages/loopover-miner/lib/posthog.ts | 27 ++++--- test/unit/cli-subprocess-driver.test.ts | 46 +++++++++++ .../miner-coding-agent-construction.test.ts | 20 ++++- test/unit/miner-posthog.test.ts | 25 +++++- 9 files changed, 227 insertions(+), 33 deletions(-) diff --git a/packages/loopover-engine/src/miner/agent-sdk-driver.ts b/packages/loopover-engine/src/miner/agent-sdk-driver.ts index a566b9e741..6d20127b9e 100644 --- a/packages/loopover-engine/src/miner/agent-sdk-driver.ts +++ b/packages/loopover-engine/src/miner/agent-sdk-driver.ts @@ -16,6 +16,7 @@ import type { CodingAgentDriver, CodingAgentDriverResult, CodingAgentDriverTask, + CodingAgentTokenUsage, } from "./coding-agent-driver.js"; /** @@ -91,13 +92,23 @@ function finiteNonNegativeNumber(value: unknown): number | undefined { * 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 (finite + non-negative, #5827) 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 { + * untyped source. Returns an EMPTY usage (never a fabricated 0) when `usage` is absent or malformed. + * + * #10198: returns the split alongside the blended total rather than only the sum. Both sides were already read + * here and then added together, discarding the parts -- which left the miner with nothing to put in PostHog's + * own `$ai_input_tokens`/`$ai_output_tokens`, the properties its cost views read. Each field is omitted rather + * than zeroed when the provider did not report it: a fabricated 0 is indistinguishable from a real one in an + * aggregate. */ +function tokensFromResultMessage(resultMessage: Record | null): CodingAgentTokenUsage { const usage = asRecord(resultMessage?.usage); const inputTokens = finiteNonNegativeNumber(usage?.input_tokens); const outputTokens = finiteNonNegativeNumber(usage?.output_tokens); - if (inputTokens === undefined && outputTokens === undefined) return undefined; - return (inputTokens ?? 0) + (outputTokens ?? 0); + if (inputTokens === undefined && outputTokens === undefined) return {}; + return { + tokensUsed: (inputTokens ?? 0) + (outputTokens ?? 0), + ...(inputTokens === undefined ? {} : { inputTokens }), + ...(outputTokens === undefined ? {} : { outputTokens }), + }; } async function listWorktreeChangedFiles(cwd: string): Promise { @@ -197,7 +208,7 @@ export function createAgentSdkCodingAgentDriver( // `total_cost_usd: number` unconditionally -- present whenever a result message arrived at all, success // or not (the session was billed either way), absent only when the stream produced no result message. const costUsd = finiteNonNegativeNumber(resultMessage?.total_cost_usd); - const tokensUsed = tokensFromResultMessage(resultMessage); + const tokenUsage = tokensFromResultMessage(resultMessage); const resultText = typeof resultMessage?.result === "string" ? redactSecrets(resultMessage.result) : ""; const transcript = redactSecrets( @@ -224,7 +235,7 @@ export function createAgentSdkCodingAgentDriver( transcript, turnsUsed, costUsd, - tokensUsed, + ...tokenUsage, error: `agent_sdk_${subtype === "success" ? "errored" : subtype}`, }; } @@ -241,7 +252,7 @@ export function createAgentSdkCodingAgentDriver( transcript, turnsUsed, costUsd, - tokensUsed, + ...tokenUsage, error: `agent_sdk_changed_files_unavailable: ${detail}`, }; } @@ -254,7 +265,7 @@ export function createAgentSdkCodingAgentDriver( transcript, turnsUsed, costUsd, - tokensUsed, + ...tokenUsage, }; }, }; diff --git a/packages/loopover-engine/src/miner/cli-subprocess-driver.ts b/packages/loopover-engine/src/miner/cli-subprocess-driver.ts index 0436fb587c..4508e54ba2 100644 --- a/packages/loopover-engine/src/miner/cli-subprocess-driver.ts +++ b/packages/loopover-engine/src/miner/cli-subprocess-driver.ts @@ -2,6 +2,7 @@ import type { CodingAgentDriver, CodingAgentDriverResult, CodingAgentDriverTask, + CodingAgentTokenUsage, } from "./coding-agent-driver.js"; import { buildAllowlistedEnv, redactSecrets } from "../subprocess-env.js"; @@ -206,10 +207,18 @@ function extractCliUsage(stdout: string): CliUsage { /** 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); +/** #10198: carries the input/output split through alongside the blended total. The CLI reports the two sides + * separately and this used to return only their sum, so the miner could not populate PostHog's own + * `$ai_input_tokens`/`$ai_output_tokens`. A CLI that reports ONLY `totalTokens` still yields just the blended + * figure -- the split stays absent rather than being invented from it. */ +function totalTokensFromUsage(usage: CliUsage): CodingAgentTokenUsage { + const split = { + ...(usage.inputTokens === undefined ? {} : { inputTokens: usage.inputTokens }), + ...(usage.outputTokens === undefined ? {} : { outputTokens: usage.outputTokens }), + }; + if (usage.totalTokens !== undefined) return { tokensUsed: usage.totalTokens, ...split }; + if (usage.inputTokens === undefined && usage.outputTokens === undefined) return {}; + return { tokensUsed: (usage.inputTokens ?? 0) + (usage.outputTokens ?? 0), ...split }; } /** Claude Code's `--output-format json` sometimes exits non-zero while still emitting a structured @@ -282,10 +291,9 @@ export function createCliSubprocessCodingAgentDriver(options: CliSubprocessDrive // below report spend symmetrically with the success path and with agent-sdk-driver.ts, preventing // attempt-metering budget-ceiling undercounting (#8871). extractCliUsage tolerates unparseable/empty stdout. const usage = extractCliUsage(spawned.stdout); - const tokensUsed = totalTokensFromUsage(usage); const usageFields = { ...(usage.costUsd !== undefined ? { costUsd: usage.costUsd } : {}), - ...(tokensUsed !== undefined ? { tokensUsed } : {}), + ...totalTokensFromUsage(usage), }; if (spawned.timedOut && spawned.stalledNoOutput) { diff --git a/packages/loopover-engine/src/miner/coding-agent-driver.ts b/packages/loopover-engine/src/miner/coding-agent-driver.ts index 653fd153ea..3ca5ddc294 100644 --- a/packages/loopover-engine/src/miner/coding-agent-driver.ts +++ b/packages/loopover-engine/src/miner/coding-agent-driver.ts @@ -27,9 +27,20 @@ export type CodingAgentDriverResult = { * 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; + /** The input/output split behind `tokensUsed`, when the provider reports the two sides separately (#10198). + * Both drivers already read them individually and then summed them away, which left the miner unable to + * populate PostHog's own `$ai_input_tokens`/`$ai_output_tokens` -- the properties its cost views read -- + * so miner spend was invisible there. Same never-fabricated convention as the two fields above: a provider + * that reports only a blended total leaves these absent, and the blended `tokensUsed` still stands alone. */ + inputTokens?: number | undefined; + outputTokens?: number | undefined; error?: string | undefined; }; +/** The token fields a driver contributes to its result (#10198) -- spread into the result at each return site + * so a driver can never report a split that disagrees with its own blended total. */ +export type CodingAgentTokenUsage = Pick; + export interface CodingAgentDriver { run(task: CodingAgentDriverTask): Promise; } diff --git a/packages/loopover-engine/test/agent-sdk-driver.test.ts b/packages/loopover-engine/test/agent-sdk-driver.test.ts index a1bdb61805..da692d6d5b 100644 --- a/packages/loopover-engine/test/agent-sdk-driver.test.ts +++ b/packages/loopover-engine/test/agent-sdk-driver.test.ts @@ -397,3 +397,79 @@ test("constructs with no options, defaulting to the real SDK query loop without const driver = createAgentSdkCodingAgentDriver(); assert.equal(typeof driver.run, "function"); }); + +// #10198: the driver used to sum input/output tokens and DISCARD the two sides. The miner's PostHog capture +// therefore had nothing to put in `$ai_input_tokens`/`$ai_output_tokens` -- the properties PostHog's own cost +// views read -- so every miner generation registered there as 0 input and 0 output tokens. +test("reports the input/output split alongside the blended total (#10198)", async () => { + const driver = driverWith({ + query: queryYielding([ + { + type: "result", + subtype: "success", + is_error: false, + num_turns: 2, + result: "done", + usage: { input_tokens: 1000, output_tokens: 234 }, + }, + ]), + }); + + const result = await driver.run(task); + + assert.equal(result.tokensUsed, 1234); + assert.equal(result.inputTokens, 1000); + assert.equal(result.outputTokens, 234); +}); + +test("the split rides the failure results too, exactly like tokensUsed and costUsd (#10198)", 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.inputTokens, 500); + assert.equal(result.outputTokens, 100); +}); + +test("a side the provider did not report stays ABSENT rather than being zeroed (#10198)", async () => { + // A fabricated 0 is indistinguishable from a real 0 once aggregated, so an out-of-contract or missing side + // must not become one -- the blended total still counts only what was real. + const onlyInput = driverWith({ + query: queryYielding([ + { type: "result", subtype: "success", is_error: false, num_turns: 2, result: "done", usage: { input_tokens: 100 } }, + ]), + }); + const onlyInputResult = await onlyInput.run(task); + assert.equal(onlyInputResult.tokensUsed, 100); + assert.equal(onlyInputResult.inputTokens, 100); + assert.equal(onlyInputResult.outputTokens, undefined); + + const badOutput = driverWith({ + query: queryYielding([ + { type: "result", subtype: "success", is_error: false, num_turns: 2, result: "done", usage: { input_tokens: 100, output_tokens: -5 } }, + ]), + }); + const badOutputResult = await badOutput.run(task); + assert.equal(badOutputResult.tokensUsed, 100); + assert.equal(badOutputResult.outputTokens, undefined); + + const noUsage = driverWith({ + query: queryYielding([{ type: "result", subtype: "success", is_error: false, num_turns: 2, result: "done" }]), + }); + const noUsageResult = await noUsage.run(task); + assert.equal(noUsageResult.tokensUsed, undefined); + assert.equal(noUsageResult.inputTokens, undefined); + assert.equal(noUsageResult.outputTokens, undefined); +}); diff --git a/packages/loopover-miner/lib/coding-agent-construction.ts b/packages/loopover-miner/lib/coding-agent-construction.ts index 1fe9d68bfa..cf1f10b766 100644 --- a/packages/loopover-miner/lib/coding-agent-construction.ts +++ b/packages/loopover-miner/lib/coding-agent-construction.ts @@ -78,9 +78,9 @@ export function createRealCliSubprocessSpawn(): CliSubprocessSpawnFn { * vendor client -- the same "no cross-package import" boundary this file's own header already documents * for its spawn implementation): this is the miner CLI's own host-bound construction site, exactly where * `src/selfhost/`'s equivalent ORB-side wrapper (`withAiGenerationCapture`, ai.ts) lives relative to its - * own chain. `CodingAgentDriverResult` carries a single blended `costUsd`/`tokensUsed` (no input/output - * split, unlike ORB's `AiUsage`) -- captureMinerPostHogAiGeneration is deliberately built for that exact - * shape, never fabricating a split its source data doesn't have. A driver failure is reported via + * own chain. `CodingAgentDriverResult` carries the blended `costUsd`/`tokensUsed` plus the input/output + * split when the provider reported one (#10198); all of it is forwarded verbatim, and a driver that knows + * no split simply leaves those fields absent rather than having one fabricated. A driver failure is reported via * `result.ok === false` (the real, observed contract every shipped driver follows -- none of them throw * for an ordinary task failure), with a genuine thrown exception handled defensively on top. */ export function withCodingAgentAiGenerationCapture(providerName: string, model: string, driver: CodingAgentDriver): CodingAgentDriver { @@ -95,6 +95,8 @@ export function withCodingAgentAiGenerationCapture(providerName: string, model: latencyMs: Date.now() - startedAtMs, isError: !result.ok, totalTokens: result.tokensUsed, + inputTokens: result.inputTokens, + outputTokens: result.outputTokens, totalCostUsd: result.costUsd, error: result.ok ? undefined : result.error, }); diff --git a/packages/loopover-miner/lib/posthog.ts b/packages/loopover-miner/lib/posthog.ts index b3a7b6a16c..21b1aa3fdc 100644 --- a/packages/loopover-miner/lib/posthog.ts +++ b/packages/loopover-miner/lib/posthog.ts @@ -114,20 +114,24 @@ export function captureMinerPostHogEvent(event: string, properties: Record { }); describe("REGRESSION: real token-usage extraction, ported from src/selfhost/ai.ts's extractCliUsage (#5653)", () => { + // #10198: the driver read both sides and returned only their sum, so the miner's PostHog capture had + // nothing for `$ai_input_tokens`/`$ai_output_tokens` -- the properties PostHog's own cost views read. + it("reports the input/output split alongside the blended total (#10198)", 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); + expect(result.inputTokens).toBe(1000); + expect(result.outputTokens).toBe(234); + }); + + it("keeps an explicit total_tokens as the blended figure WITHOUT inventing a split from it (#10198)", async () => { + // A CLI that reports only a total genuinely has no split to report; deriving one would be a fabrication. + const { spawn } = fakeSpawn({ stdout: JSON.stringify({ total_tokens: 999 }), code: 0 }); + const driver = createCliSubprocessCodingAgentDriver({ command: "claude", spawn }); + const result = await driver.run(TASK); + expect(result.tokensUsed).toBe(999); + expect(result.inputTokens).toBeUndefined(); + expect(result.outputTokens).toBeUndefined(); + }); + + it("carries the split through when total_tokens AND the two sides are all reported (#10198)", 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); + // The CLI's own total still wins over the sum -- unchanged from before the split existed. + expect(result.tokensUsed).toBe(999); + expect(result.inputTokens).toBe(100); + expect(result.outputTokens).toBe(50); + }); + + it("leaves a side ABSENT rather than zeroed when the CLI reported only one of them (#10198)", 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); + expect(result.inputTokens).toBe(42); + expect(result.outputTokens).toBeUndefined(); + }); + 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 }), diff --git a/test/unit/miner-coding-agent-construction.test.ts b/test/unit/miner-coding-agent-construction.test.ts index ad78450f98..4c48b12d10 100644 --- a/test/unit/miner-coding-agent-construction.test.ts +++ b/test/unit/miner-coding-agent-construction.test.ts @@ -211,12 +211,12 @@ describe("withCodingAgentAiGenerationCapture (#8296 AMS follow-up)", () => { expect(posthogMock.capture).not.toHaveBeenCalled(); }); - it("captures a successful attempt's cost/tokens as a combined figure (no fabricated input/output split)", async () => { + it("forwards the driver's cost, blended tokens AND input/output split to the capture (#10198)", async () => { await initMinerPostHog({ LOOPOVER_MINER_POSTHOG_API_KEY: "phc_test_key" }); const driver = withCodingAgentAiGenerationCapture( "claude-cli", "claude-sonnet-5", - driverReturning({ ok: true, changedFiles: ["a.ts"], summary: "done", transcript: "", costUsd: 0.12, tokensUsed: 4000 }), + driverReturning({ ok: true, changedFiles: ["a.ts"], summary: "done", transcript: "", costUsd: 0.12, tokensUsed: 4000, inputTokens: 3200, outputTokens: 800 }), ); await driver.run(task); expect(posthogMock.capture).toHaveBeenCalledTimes(1); @@ -225,9 +225,25 @@ describe("withCodingAgentAiGenerationCapture (#8296 AMS follow-up)", () => { expect(properties.$ai_model).toBe("claude-sonnet-5"); expect(properties.$ai_is_error).toBe(false); expect(properties.tokens_used).toBe(4000); + expect(properties.$ai_input_tokens).toBe(3200); + expect(properties.$ai_output_tokens).toBe(800); expect(properties.$ai_total_cost_usd).toBe(0.12); }); + it("leaves the split at 0 for a driver that reports only a blended total (#10198)", async () => { + await initMinerPostHog({ LOOPOVER_MINER_POSTHOG_API_KEY: "phc_test_key" }); + const driver = withCodingAgentAiGenerationCapture( + "codex-cli", + "gpt-5-codex", + driverReturning({ ok: true, changedFiles: [], summary: "done", transcript: "", tokensUsed: 4000 }), + ); + await driver.run(task); + const { properties } = posthogMock.capture.mock.calls[0]?.[0]; + expect(properties.tokens_used).toBe(4000); + expect(properties.$ai_input_tokens).toBe(0); + expect(properties.$ai_output_tokens).toBe(0); + }); + it("captures result.ok:false as a failure, using the driver's own error string -- no exception thrown", async () => { await initMinerPostHog({ LOOPOVER_MINER_POSTHOG_API_KEY: "phc_test_key" }); const driver = withCodingAgentAiGenerationCapture( diff --git a/test/unit/miner-posthog.test.ts b/test/unit/miner-posthog.test.ts index 0bb91083ed..43b22a71cf 100644 --- a/test/unit/miner-posthog.test.ts +++ b/test/unit/miner-posthog.test.ts @@ -155,9 +155,9 @@ describe("loopover-miner opt-in PostHog (#8292, epic #8286)", () => { expect(posthogMock.capture).not.toHaveBeenCalled(); }); - it("captures a well-formed $ai_generation event with a combined tokens_used property (no fabricated input/output split)", async () => { + it("captures a well-formed $ai_generation event, keeping the blended tokens_used alongside the real split", async () => { await initMinerPostHog({ LOOPOVER_MINER_POSTHOG_API_KEY: "phc_test_key" }); - captureMinerPostHogAiGeneration({ ...BASE, totalTokens: 1500, totalCostUsd: 0.05 }); + captureMinerPostHogAiGeneration({ ...BASE, totalTokens: 1500, inputTokens: 1200, outputTokens: 300, totalCostUsd: 0.05 }); expect(posthogMock.capture).toHaveBeenCalledTimes(1); const call = posthogMock.capture.mock.calls[0]?.[0]; expect(call.event).toBe("$ai_generation"); @@ -166,8 +166,10 @@ describe("loopover-miner opt-in PostHog (#8292, epic #8286)", () => { expect(call.properties.$ai_provider).toBe("claude-cli"); expect(call.properties.$ai_latency).toBe(2.5); expect(call.properties.$ai_http_status).toBe(200); - expect(call.properties.$ai_input_tokens).toBe(0); - expect(call.properties.$ai_output_tokens).toBe(0); + // #10198: these are the properties PostHog's own cost views read. They were hardcoded to 0, so the + // miner's whole spend was invisible there while the real figure sat in the non-standard tokens_used. + expect(call.properties.$ai_input_tokens).toBe(1200); + expect(call.properties.$ai_output_tokens).toBe(300); expect(call.properties.tokens_used).toBe(1500); expect(call.properties.$ai_total_cost_usd).toBe(0.05); expect(call.properties.$ai_is_error).toBe(false); @@ -175,6 +177,21 @@ describe("loopover-miner opt-in PostHog (#8292, epic #8286)", () => { expect("$ai_output_choices" in call.properties).toBe(false); }); + it("falls back to 0 for a side the driver could not report, without losing the blended total (#10198)", async () => { + // A provider that reports only a blended total genuinely has no split; 0 here means "no split known", + // and tokens_used still carries the figure that IS known. + await initMinerPostHog({ LOOPOVER_MINER_POSTHOG_API_KEY: "phc_test_key" }); + captureMinerPostHogAiGeneration({ ...BASE, totalTokens: 999 }); + captureMinerPostHogAiGeneration({ ...BASE, totalTokens: 999, inputTokens: 800, outputTokens: Number.NaN }); + const blended = posthogMock.capture.mock.calls[0]?.[0].properties; + expect(blended.$ai_input_tokens).toBe(0); + expect(blended.$ai_output_tokens).toBe(0); + expect(blended.tokens_used).toBe(999); + const partial = posthogMock.capture.mock.calls[1]?.[0].properties; + expect(partial.$ai_input_tokens).toBe(800); + expect(partial.$ai_output_tokens).toBe(0); + }); + it("omits tokens_used/$ai_total_cost_usd when neither is supplied or finite", async () => { await initMinerPostHog({ LOOPOVER_MINER_POSTHOG_API_KEY: "phc_test_key" }); captureMinerPostHogAiGeneration({ ...BASE, totalTokens: Number.NaN });