From ba2152f5453e1cfbb84d2950b2f97dc995718363 Mon Sep 17 00:00:00 2001 From: JSONbored <49853598+JSONbored@users.noreply.github.com> Date: Mon, 13 Jul 2026 10:52:46 -0700 Subject: [PATCH] feat(miner): persist coding-agent provider + real cost on the attempt log Adds a new attempt_outcome_summary event type, written once per completed attempt from attempt-cli.js, carrying the real configured provider and the real accumulated cost -- the two signals a per-provider usage dashboard needs that the existing per-iteration attempt-log events don't carry. tokensUsed stays null (never fabricated): no coding-agent driver reports real token usage yet. Extends the redacted AMS reporting export and its datasource docs so the new columns reach Grafana without ever exposing the live ledger. Prerequisite for the per-provider usage dashboard. --- .../src/miner/attempt-log.ts | 35 ++++++++ .../test/attempt-log.test.ts | 43 ++++++++++ .../gittensory-miner/docs/observability.md | 4 +- packages/gittensory-miner/lib/attempt-cli.js | 24 +++++- .../gittensory-miner/lib/attempt-log.d.ts | 8 ++ packages/gittensory-miner/lib/attempt-log.js | 34 +++++++- scripts/export-ams-reporting-db.sh | 9 +- test/unit/coding-agent-miner.test.ts | 43 ++++++++++ test/unit/miner-attempt-cli.test.ts | 84 ++++++++++++++++++ test/unit/miner-attempt-log.test.ts | 85 +++++++++++++++++++ test/unit/selfhost-ams-reporting.test.ts | 71 +++++++++++++++- 11 files changed, 432 insertions(+), 8 deletions(-) diff --git a/packages/gittensory-engine/src/miner/attempt-log.ts b/packages/gittensory-engine/src/miner/attempt-log.ts index a231128b00..507c161779 100644 --- a/packages/gittensory-engine/src/miner/attempt-log.ts +++ b/packages/gittensory-engine/src/miner/attempt-log.ts @@ -11,6 +11,11 @@ export const ATTEMPT_LOG_EVENT_TYPES = Object.freeze([ "attempt_succeeded", "attempt_failed", "attempt_aborted", + // #5185: one summary row per completed attempt, written by the miner CLI (attempt-cli.js) once `runIterateLoop` + // returns -- distinct from the five iteration-level types above (all written from inside iterate-loop.ts's own + // per-iteration decision trail). Carries provider/costUsd, the two real (never-fabricated) signals a + // per-provider usage dashboard needs that no iteration-level event captures today. + "attempt_outcome_summary", ] as const); export type AttemptLogEventType = (typeof ATTEMPT_LOG_EVENT_TYPES)[number]; @@ -22,6 +27,15 @@ export type AttemptLogEvent = { mode: CodingAgentExecutionMode; reason: string; payload?: Record | undefined; + /** Coding-agent provider name (claude-cli/codex-cli/agent-sdk/noop) this attempt used, when known (#5185). + * Optional: every event type that predates this field omits it; only `attempt_outcome_summary` sets it. */ + provider?: string | undefined; + /** Real dollar cost, mirroring `CodingAgentDriverResult.costUsd`'s own convention: absent (not zero) when the + * provider never reports a cost signal, never fabricated (#5185). */ + costUsd?: number | undefined; + /** Real token count, when some future driver reports one. Always absent today -- no driver reports real token + * usage yet (#5395) -- an honest gap, not a fabricated zero. */ + tokensUsed?: number | undefined; }; export type NormalizedAttemptLogEvent = { @@ -31,6 +45,9 @@ export type NormalizedAttemptLogEvent = { mode: CodingAgentExecutionMode; reason: string; payloadJson: string; + provider: string | null; + costUsd: number | null; + tokensUsed: number | null; }; const attemptEventTypeSet = new Set(ATTEMPT_LOG_EVENT_TYPES); @@ -84,6 +101,21 @@ function normalizeMode(value: unknown): CodingAgentExecutionMode { return mode as CodingAgentExecutionMode; } +/** `undefined` -> `null` ("not set"); any other non-empty-string value must be a valid string, or this fails + * closed rather than silently coercing (#5185). */ +function normalizeOptionalString(value: unknown, code: string): string | null { + if (value === undefined) return null; + return normalizeRequiredString(value, code); +} + +/** `undefined` -> `null` ("no signal, never fabricated as 0"); any other value must be a finite number >= 0 + * (#5185) -- mirrors `CodingAgentDriverResult.costUsd`'s own absent-vs-zero distinction. */ +function normalizeOptionalNonNegativeNumber(value: unknown, code: string): number | null { + if (value === undefined) return null; + if (typeof value !== "number" || !Number.isFinite(value) || value < 0) throw new Error(code); + return value; +} + /** Validate and normalize an attempt-log row before append. Fail-closed on unknown types/modes. */ export function normalizeAttemptLogEvent(input: unknown): NormalizedAttemptLogEvent { if (!input || typeof input !== "object") throw new Error("invalid_event"); @@ -97,6 +129,9 @@ export function normalizeAttemptLogEvent(input: unknown): NormalizedAttemptLogEv mode: normalizeMode(event.mode), reason: normalizeRequiredString(event.reason, "invalid_reason"), payloadJson: serializePayload(event.payload), + provider: normalizeOptionalString(event.provider, "invalid_provider"), + costUsd: normalizeOptionalNonNegativeNumber(event.costUsd, "invalid_cost_usd"), + tokensUsed: normalizeOptionalNonNegativeNumber(event.tokensUsed, "invalid_tokens_used"), }; } diff --git a/packages/gittensory-engine/test/attempt-log.test.ts b/packages/gittensory-engine/test/attempt-log.test.ts index 1227638e88..959ae1d021 100644 --- a/packages/gittensory-engine/test/attempt-log.test.ts +++ b/packages/gittensory-engine/test/attempt-log.test.ts @@ -15,9 +15,52 @@ test("ATTEMPT_LOG_EVENT_TYPES is a fixed vocabulary", () => { "attempt_succeeded", "attempt_failed", "attempt_aborted", + "attempt_outcome_summary", ]); }); +test("normalizeAttemptLogEvent leaves provider/costUsd/tokensUsed null when omitted, and passes through real values", () => { + const omitted = normalizeAttemptLogEvent({ + eventType: "attempt_started", + attemptId: "a-1", + actionClass: "codegen", + mode: "live", + reason: "live run", + }); + assert.equal(omitted.provider, null); + assert.equal(omitted.costUsd, null); + assert.equal(omitted.tokensUsed, null); + + const withValues = normalizeAttemptLogEvent({ + eventType: "attempt_outcome_summary", + attemptId: "a-1", + actionClass: "attempt_submitted", + mode: "live", + reason: "attempt finished", + provider: "claude-cli", + costUsd: 0.42, + tokensUsed: 1000, + }); + assert.equal(withValues.provider, "claude-cli"); + assert.equal(withValues.costUsd, 0.42); + assert.equal(withValues.tokensUsed, 1000); +}); + +test("normalizeAttemptLogEvent rejects a negative/non-finite costUsd or tokensUsed, never coercing to 0", () => { + const base = { + eventType: "attempt_outcome_summary", + attemptId: "a-1", + actionClass: "attempt_submitted", + mode: "live", + reason: "attempt finished", + }; + assert.throws(() => normalizeAttemptLogEvent({ ...base, costUsd: -1 }), /invalid_cost_usd/); + assert.throws(() => normalizeAttemptLogEvent({ ...base, costUsd: Number.NaN }), /invalid_cost_usd/); + assert.throws(() => normalizeAttemptLogEvent({ ...base, costUsd: "0.5" }), /invalid_cost_usd/); + assert.throws(() => normalizeAttemptLogEvent({ ...base, tokensUsed: -1 }), /invalid_tokens_used/); + assert.throws(() => normalizeAttemptLogEvent({ ...base, provider: "" }), /invalid_provider/); +}); + test("normalizeAttemptLogEvent validates mode and payload round-trip", () => { const normalized = normalizeAttemptLogEvent({ eventType: "attempt_shadow", diff --git a/packages/gittensory-miner/docs/observability.md b/packages/gittensory-miner/docs/observability.md index e641105573..8cfaca7fb3 100644 --- a/packages/gittensory-miner/docs/observability.md +++ b/packages/gittensory-miner/docs/observability.md @@ -11,7 +11,9 @@ The miner writes append-only SQLite ledgers under `GITTENSORY_MINER_CONFIG_DIR` [`DEPLOYMENT.md`](../DEPLOYMENT.md)): - **`attempt-log.sqlite3`** — the driver-level attempt event trace (event type, action class, mode, reason, - timestamps), table `attempt_log_events`. + timestamps), table `attempt_log_events`. One `attempt_outcome_summary` row per completed attempt also carries + the real configured `provider` and the real accumulated `cost_usd` (#5185) — `tokens_used` is always `NULL` + today, an honest gap rather than a fabricated `0`: no coding-agent driver reports real token usage yet (#5395). - **`prediction-ledger.sqlite3`** — recorded predicted-gate verdicts for later scoring. Those live files can contain free-form payloads, repo/target identifiers, readiness scores, and blocker/warning diff --git a/packages/gittensory-miner/lib/attempt-cli.js b/packages/gittensory-miner/lib/attempt-cli.js index 25e5a93b60..75ffa7c153 100644 --- a/packages/gittensory-miner/lib/attempt-cli.js +++ b/packages/gittensory-miner/lib/attempt-cli.js @@ -12,7 +12,7 @@ // governor.convergenceInput is an honest first-attempt-shaped literal, not a real per-issue attempt-history // query (attempt-log.js's schema has no repo+issue index, and reenqueue counts aren't tracked anywhere yet). -import { resolveCodingAgentModeFromConfig } from "@loopover/engine"; +import { resolveCodingAgentModeFromConfig, resolveFirstConfiguredCodingAgentDriverName } from "@loopover/engine"; import { argsWantJson, describeCliError, reportCliFailure } from "./cli-error.js"; import { constructProductionCodingAgentDriver } from "./coding-agent-construction.js"; import { runSlopAssessment } from "./slop-assessment.js"; @@ -477,6 +477,28 @@ export async function runAttempt(args, options = {}) { ...(claimConflict !== undefined ? { claimConflict } : {}), }; + // One summary row per completed attempt (#5185), for the Grafana per-provider usage dashboard the redacted + // 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. + try { + attemptLog.appendAttemptLogEvent({ + eventType: "attempt_outcome_summary", + attemptId, + actionClass: finalResult.outcome, + mode, + reason: `attempt finished with outcome: ${result.outcome}`, + provider: resolveFirstConfiguredCodingAgentDriverName(env), + costUsd: finalResult.totalCostUsd, + }); + } catch { + // Deliberately swallowed -- see comment above. + } + if (parsed.json) { console.log(JSON.stringify(finalResult, null, 2)); } else { diff --git a/packages/gittensory-miner/lib/attempt-log.d.ts b/packages/gittensory-miner/lib/attempt-log.d.ts index fddfeba3c7..9f6528803e 100644 --- a/packages/gittensory-miner/lib/attempt-log.d.ts +++ b/packages/gittensory-miner/lib/attempt-log.d.ts @@ -9,6 +9,14 @@ export type AttemptLogEntry = { mode: string; reason: string; payload: Record; + /** Coding-agent provider name, when the event set one (#5185). Null for every event type that predates this + * field. */ + provider: string | null; + /** Real dollar cost, when the event set one (#5185). Null (not 0) when absent -- never fabricated. */ + costUsd: number | null; + /** Real token count, when some future driver reports one (#5185). Always null today -- no driver reports real + * token usage yet (#5395). */ + tokensUsed: number | null; createdAt: string; }; diff --git a/packages/gittensory-miner/lib/attempt-log.js b/packages/gittensory-miner/lib/attempt-log.js index 63a5af4cda..1ed29152e9 100644 --- a/packages/gittensory-miner/lib/attempt-log.js +++ b/packages/gittensory-miner/lib/attempt-log.js @@ -57,6 +57,9 @@ function rowToEntry(row) { mode: row.mode, reason: row.reason, payload, + provider: row.provider, + costUsd: row.cost_usd, + tokensUsed: row.tokens_used, createdAt: row.created_at, }; } @@ -69,9 +72,31 @@ function rowToNormalized(row) { mode: row.mode, reason: row.reason, payloadJson: row.payload_json, + provider: row.provider, + costUsd: row.cost_usd, + tokensUsed: row.tokens_used, }; } +// Add the provider/cost_usd/tokens_used columns (#5185) to an on-disk file created before they existed. `CREATE +// TABLE IF NOT EXISTS` above is a no-op against an already-existing table, so a pre-#5185 file needs this +// explicit ALTER -- guarded by a per-column presence check (same technique as governor-state.js's own +// ensurePauseColumns) so a file missing only one of the three still gets exactly what it's missing. +function ensureOutcomeColumns(db) { + const existingColumns = new Set( + db.prepare("PRAGMA table_info(attempt_log_events)").all().map((column) => column.name), + ); + if (!existingColumns.has("provider")) { + db.exec("ALTER TABLE attempt_log_events ADD COLUMN provider TEXT"); + } + if (!existingColumns.has("cost_usd")) { + db.exec("ALTER TABLE attempt_log_events ADD COLUMN cost_usd REAL"); + } + if (!existingColumns.has("tokens_used")) { + db.exec("ALTER TABLE attempt_log_events ADD COLUMN tokens_used INTEGER"); + } +} + /** * Opens the append-only attempt log, creating the table on first use. `seq` is a monotonically increasing counter * maintained by this module (next = current MAX(seq) + 1) with a UNIQUE(seq) constraint. Rows read back in seq ASC @@ -93,6 +118,7 @@ export function initAttemptLog(dbPath = resolveAttemptLogDbPath()) { created_at TEXT NOT NULL ) `); + ensureOutcomeColumns(db); db.exec( "CREATE INDEX IF NOT EXISTS idx_attempt_log_attempt ON attempt_log_events (attempt_id, seq)", ); @@ -100,9 +126,10 @@ export function initAttemptLog(dbPath = resolveAttemptLogDbPath()) { const nextSeqStatement = db.prepare("SELECT COALESCE(MAX(seq), 0) + 1 AS nextSeq FROM attempt_log_events"); const appendStatement = db.prepare(` INSERT INTO attempt_log_events ( - seq, attempt_id, event_type, action_class, mode, reason, payload_json, created_at + seq, attempt_id, event_type, action_class, mode, reason, payload_json, provider, cost_usd, tokens_used, + created_at ) - VALUES (?, ?, ?, ?, ?, ?, ?, ?) + VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) `); const getByIdStatement = db.prepare("SELECT * FROM attempt_log_events WHERE id = ?"); const readAllStatement = db.prepare("SELECT * FROM attempt_log_events ORDER BY seq ASC"); @@ -126,6 +153,9 @@ export function initAttemptLog(dbPath = resolveAttemptLogDbPath()) { normalized.mode, normalized.reason, normalized.payloadJson, + normalized.provider, + normalized.costUsd, + normalized.tokensUsed, createdAt, ); const entry = rowToEntry(getByIdStatement.get(Number(result.lastInsertRowid))); diff --git a/scripts/export-ams-reporting-db.sh b/scripts/export-ams-reporting-db.sh index 29ce3549ed..0ec390d513 100644 --- a/scripts/export-ams-reporting-db.sh +++ b/scripts/export-ams-reporting-db.sh @@ -138,7 +138,9 @@ DETACH report; # attempt_log_events: DROP `reason` and `payload_json` -- both free-form (payload_json in particular can nest # arbitrary per-event-type detail, up to and including file paths/diffs/prompt fragments). Every other column is -# a bounded-vocabulary identifier/enum/timestamp, safe for a shared reporting export. +# a bounded-vocabulary identifier/enum/timestamp, safe for a shared reporting export -- including provider/ +# cost_usd/tokens_used (#5185, added by attempt-cli.js's own attempt_outcome_summary event), each a real +# structured value (provider name, a dollar figure, a token count), never free text. export_ledger \ "attempt-log" \ "$ATTEMPT_LOG_SOURCE_DB" \ @@ -152,11 +154,14 @@ export_ledger \ event_type TEXT NOT NULL, action_class TEXT NOT NULL, mode TEXT NOT NULL, + provider TEXT, + cost_usd REAL, + tokens_used INTEGER, created_at TEXT NOT NULL ); CREATE INDEX attempt_log_events_attempt_idx ON attempt_log_events(attempt_id, seq); CREATE INDEX attempt_log_events_created_idx ON attempt_log_events(created_at);" \ - "id, seq, attempt_id, event_type, action_class, mode, created_at" + "id, seq, attempt_id, event_type, action_class, mode, provider, cost_usd, tokens_used, created_at" # predictions: kept as-is. Unlike attempt_log_events, every column here is already a bounded identifier, enum, # score, or a fixed-vocabulary code array (blocker_codes_json/warning_codes_json -- engine-defined codes, never diff --git a/test/unit/coding-agent-miner.test.ts b/test/unit/coding-agent-miner.test.ts index 9504fc9c1b..32f59629a2 100644 --- a/test/unit/coding-agent-miner.test.ts +++ b/test/unit/coding-agent-miner.test.ts @@ -116,10 +116,53 @@ describe("attempt log normalization (#4294)", () => { "attempt_succeeded", "attempt_failed", "attempt_aborted", + "attempt_outcome_summary", ]); expect(Object.isFrozen(ATTEMPT_LOG_EVENT_TYPES)).toBe(true); }); + it("leaves provider/costUsd/tokensUsed null when omitted, real values when set (#5185)", () => { + const omitted = normalizeAttemptLogEvent({ + eventType: "attempt_started", + attemptId: "a-1", + actionClass: "codegen", + mode: "live", + reason: "live run", + }); + expect(omitted.provider).toBeNull(); + expect(omitted.costUsd).toBeNull(); + expect(omitted.tokensUsed).toBeNull(); + + const withValues = normalizeAttemptLogEvent({ + eventType: "attempt_outcome_summary", + attemptId: "a-1", + actionClass: "attempt_submitted", + mode: "live", + reason: "attempt finished", + provider: "codex-cli", + costUsd: 0, + tokensUsed: 0, + }); + expect(withValues.provider).toBe("codex-cli"); + expect(withValues.costUsd).toBe(0); + expect(withValues.tokensUsed).toBe(0); + }); + + it("rejects a negative/non-finite/non-numeric costUsd or tokensUsed, and a blank provider (#5185)", () => { + const base = { + eventType: "attempt_outcome_summary", + attemptId: "a-1", + actionClass: "attempt_submitted", + mode: "live", + reason: "attempt finished", + }; + expect(() => normalizeAttemptLogEvent({ ...base, costUsd: -1 })).toThrow(/invalid_cost_usd/); + expect(() => normalizeAttemptLogEvent({ ...base, costUsd: Number.NaN })).toThrow(/invalid_cost_usd/); + expect(() => normalizeAttemptLogEvent({ ...base, costUsd: "0.5" } as unknown)).toThrow(/invalid_cost_usd/); + expect(() => normalizeAttemptLogEvent({ ...base, tokensUsed: -1 })).toThrow(/invalid_tokens_used/); + expect(() => normalizeAttemptLogEvent({ ...base, provider: " " })).toThrow(/invalid_provider/); + }); + it("normalizes a valid event with payload round-trip", () => { const normalized = normalizeAttemptLogEvent({ eventType: "attempt_shadow", diff --git a/test/unit/miner-attempt-cli.test.ts b/test/unit/miner-attempt-cli.test.ts index 9cdfafbb5c..5c81b2c9dd 100644 --- a/test/unit/miner-attempt-cli.test.ts +++ b/test/unit/miner-attempt-cli.test.ts @@ -10,6 +10,7 @@ vi.mock("@loopover/engine", async () => { import { closeDefaultClaimLedger, openClaimLedger } from "../../packages/gittensory-miner/lib/claim-ledger.js"; import { closeDefaultEventLedger, initEventLedger } from "../../packages/gittensory-miner/lib/event-ledger.js"; import { closeDefaultAttemptLog, initAttemptLog } from "../../packages/gittensory-miner/lib/attempt-log.js"; +import type { AttemptLog } from "../../packages/gittensory-miner/lib/attempt-log.js"; import { closeDefaultGovernorLedger, initGovernorLedger } from "../../packages/gittensory-miner/lib/governor-ledger.js"; import { closeDefaultWorktreeAllocator, openWorktreeAllocator } from "../../packages/gittensory-miner/lib/worktree-allocator.js"; import { buildAttemptDeps, parseAttemptArgs, runAttempt } from "../../packages/gittensory-miner/lib/attempt-cli.js"; @@ -302,6 +303,10 @@ describe("runAttempt (#5132)", () => { const { allocator, claimLedger, eventLedger, attemptLog, governorLedger } = tempLedgers(); const log = vi.spyOn(console, "log").mockImplementation(() => undefined); const releaseSpy = vi.spyOn(allocator, "release"); + // attemptLog is closed in runAttempt's own `finally` block once it returns (same DI convention documented at + // the claim-ledger test below) -- so the appended event is asserted via a spy recorded DURING the call, not + // by re-querying the ledger once it's already closed. + const appendAttemptLogEventSpy = vi.spyOn(attemptLog, "appendAttemptLogEvent"); const worktreeResult = fakeWorktreeResult(); const cleanupAttemptWorktreeSpy = vi.fn().mockResolvedValue({ ok: true, removed: true }); const runMinerAttemptSpy = vi.fn().mockResolvedValue({ @@ -369,6 +374,85 @@ describe("runAttempt (#5132)", () => { expect(input.governor.capLimits).toEqual(DEFAULT_AMS_POLICY_SPEC.capLimits); expect(deps).toBeDefined(); expect(typeof deps.driver.run).toBe("function"); + + // #5185: one real attempt_outcome_summary call per completed attempt, carrying the real configured provider + // and the real accumulated cost -- not a per-iteration event iterate-loop.ts already writes. + const summaryCalls = appendAttemptLogEventSpy.mock.calls + .map(([event]) => event) + .filter((event) => event.eventType === "attempt_outcome_summary"); + expect(summaryCalls).toHaveLength(1); + expect(summaryCalls[0]).toMatchObject({ + attemptId: "fixed-attempt-id", + actionClass: "attempt_submitted", + mode: "dry_run", + provider: "noop", + costUsd: 0.42, + }); + expect(summaryCalls[0]).not.toHaveProperty("tokensUsed"); + }); + + it("#5185: writes attempt_outcome_summary with the real provider/cost on a non-submitted outcome too", async () => { + const { allocator, claimLedger, eventLedger, attemptLog, governorLedger } = tempLedgers(); + vi.spyOn(console, "log").mockImplementation(() => undefined); + const appendAttemptLogEventSpy = vi.spyOn(attemptLog, "appendAttemptLogEvent"); + const runMinerAttemptSpy = vi.fn().mockResolvedValue({ + outcome: "abandon", + reason: "self_review_ambiguous", + loopResult: { outcome: "abandon", totalTurnsUsed: 1, totalCostUsd: 0, iterationsUsed: 1 }, + }); + + const exitCode = await runAttempt(["acme/widgets", "7", "--miner-login", "alice", "--json"], { + env: { MINER_CODING_AGENT_PROVIDER: "codex-cli" }, + nowMs: 999, + attemptId: "abandoned-attempt-id", + openWorktreeAllocator: () => allocator, + openClaimLedger: () => claimLedger, + initEventLedger: () => eventLedger, + initAttemptLog: () => attemptLog, + initGovernorLedger: () => governorLedger, + ...readyPipelineOptions({ runMinerAttempt: runMinerAttemptSpy }), + }); + + expect(exitCode).toBe(7); + const summaryCalls = appendAttemptLogEventSpy.mock.calls + .map(([event]) => event) + .filter((event) => event.eventType === "attempt_outcome_summary"); + expect(summaryCalls).toHaveLength(1); + expect(summaryCalls[0]).toMatchObject({ actionClass: "attempt_abandon", provider: "codex-cli", costUsd: 0 }); + }); + + it("#5185: a broken appendAttemptLogEvent never fails an otherwise-successful attempt", async () => { + const { allocator, claimLedger, eventLedger, governorLedger } = tempLedgers(); + vi.spyOn(console, "log").mockImplementation(() => undefined); + const runMinerAttemptSpy = vi.fn().mockResolvedValue({ + outcome: "submitted", + spec: { command: "gh pr create", cwd: "/tmp/work", timeoutMs: 1000 }, + execResult: { code: 0 }, + loopResult: { outcome: "handoff", totalTurnsUsed: 1, totalCostUsd: 0, iterationsUsed: 1 }, + }); + const brokenAttemptLog: AttemptLog = { + dbPath: ":memory:", + appendAttemptLogEvent: vi.fn().mockImplementation(() => { + throw new Error("disk full"); + }), + readAttemptLogEvents: () => [], + exportAttemptLogJsonl: () => "", + close: () => {}, + }; + + const exitCode = await runAttempt(["acme/widgets", "7", "--miner-login", "alice", "--json"], { + env: { MINER_CODING_AGENT_PROVIDER: "noop" }, + nowMs: 999, + attemptId: "resilient-attempt-id", + openWorktreeAllocator: () => allocator, + openClaimLedger: () => claimLedger, + initEventLedger: () => eventLedger, + initAttemptLog: () => brokenAttemptLog, + initGovernorLedger: () => governorLedger, + ...readyPipelineOptions({ runMinerAttempt: runMinerAttemptSpy }), + }); + + expect(exitCode).toBe(0); }); it("REGRESSION (#4848): a real submitted outcome with a recoverable PR number runs the real claim-conflict check and surfaces its result", async () => { diff --git a/test/unit/miner-attempt-log.test.ts b/test/unit/miner-attempt-log.test.ts index 5f65906044..17e19f5f4d 100644 --- a/test/unit/miner-attempt-log.test.ts +++ b/test/unit/miner-attempt-log.test.ts @@ -231,4 +231,89 @@ describe("gittensory-miner attempt log (#4294)", () => { const source = readFileSync("packages/gittensory-miner/lib/attempt-log.js", "utf8"); expect(source).not.toMatch(/\b(UPDATE|DELETE)\b/i); }); + + it("appends and reads back provider/costUsd/tokensUsed, null when omitted (#5185)", () => { + const log = tempAttemptLog(); + const withValues = log.appendAttemptLogEvent({ + eventType: "attempt_outcome_summary", + ...baseEvent, + actionClass: "attempt_submitted", + reason: "attempt finished", + provider: "claude-cli", + costUsd: 0.42, + tokensUsed: 1000, + }); + expect(withValues).toMatchObject({ provider: "claude-cli", costUsd: 0.42, tokensUsed: 1000 }); + + const omitted = log.appendAttemptLogEvent({ eventType: "attempt_started", ...baseEvent }); + expect(omitted).toMatchObject({ provider: null, costUsd: null, tokensUsed: null }); + + expect(log.readAttemptLogEvents()).toEqual([withValues, omitted]); + }); + + it("migrates a pre-#5185 on-disk file missing provider/cost_usd/tokens_used columns", () => { + const root = mkdtempSync(join(tmpdir(), "gittensory-miner-attempt-log-migrate-")); + roots.push(root); + const dbPath = join(root, "attempt-log.sqlite3"); + const raw = new DatabaseSync(dbPath); + raw.exec(` + CREATE TABLE attempt_log_events ( + id INTEGER PRIMARY KEY AUTOINCREMENT, + seq INTEGER NOT NULL UNIQUE, + attempt_id TEXT NOT NULL, + event_type TEXT NOT NULL, + action_class TEXT NOT NULL, + mode TEXT NOT NULL, + reason TEXT NOT NULL, + payload_json TEXT NOT NULL, + created_at TEXT NOT NULL + ) + `); + raw + .prepare( + "INSERT INTO attempt_log_events (seq, attempt_id, event_type, action_class, mode, reason, payload_json, created_at) VALUES (1, 'attempt-1', 'attempt_started', 'codegen', 'live', 'live run', '{}', '2026-01-01T00:00:00.000Z')", + ) + .run(); + raw.close(); + + const log = initAttemptLog(dbPath); + logs.push(log); + const preExisting = log.readAttemptLogEvents(); + expect(preExisting).toHaveLength(1); + expect(preExisting[0]).toMatchObject({ provider: null, costUsd: null, tokensUsed: null }); + + const appended = log.appendAttemptLogEvent({ + eventType: "attempt_outcome_summary", + ...baseEvent, + actionClass: "attempt_submitted", + reason: "attempt finished", + provider: "agent-sdk", + costUsd: 1.5, + }); + expect(appended).toMatchObject({ provider: "agent-sdk", costUsd: 1.5, tokensUsed: null }); + }); + + it("re-opening an already-migrated file is a no-op: no duplicate/failing ALTER TABLE", () => { + const root = mkdtempSync(join(tmpdir(), "gittensory-miner-attempt-log-reopen-")); + roots.push(root); + const dbPath = join(root, "attempt-log.sqlite3"); + + const first = initAttemptLog(dbPath); + first.appendAttemptLogEvent({ eventType: "attempt_started", ...baseEvent }); + first.close(); + + // ensureOutcomeColumns runs again on this second open; provider/cost_usd/tokens_used are already present from + // the first open's own migration, so every per-column ALTER TABLE this time must be skipped, not re-run. + const second = initAttemptLog(dbPath); + logs.push(second); + expect(second.readAttemptLogEvents()).toHaveLength(1); + const appended = second.appendAttemptLogEvent({ + eventType: "attempt_outcome_summary", + ...baseEvent, + actionClass: "attempt_submitted", + reason: "attempt finished", + provider: "claude-cli", + }); + expect(appended).toMatchObject({ provider: "claude-cli", costUsd: null, tokensUsed: null }); + }); }); diff --git a/test/unit/selfhost-ams-reporting.test.ts b/test/unit/selfhost-ams-reporting.test.ts index 9d23a5a7aa..7cdde2e7a3 100644 --- a/test/unit/selfhost-ams-reporting.test.ts +++ b/test/unit/selfhost-ams-reporting.test.ts @@ -49,7 +49,28 @@ function runExporter( }); } -function seedAttemptLog(db: string, rows: Array<{ seq: number; attemptId: string; eventType: string; actionClass: string; mode: string; reason: string; payloadJson: string; createdAt: string }>): void { +function sqlLiteral(value: string | number | null | undefined): string { + if (value === null || value === undefined) return "NULL"; + if (typeof value === "number") return String(value); + return `'${value.replace(/'/g, "''")}'`; +} + +function seedAttemptLog( + db: string, + rows: Array<{ + seq: number; + attemptId: string; + eventType: string; + actionClass: string; + mode: string; + reason: string; + payloadJson: string; + provider?: string | null; + costUsd?: number | null; + tokensUsed?: number | null; + createdAt: string; + }>, +): void { sqlite( db, ` @@ -62,12 +83,15 @@ function seedAttemptLog(db: string, rows: Array<{ seq: number; attemptId: string mode TEXT NOT NULL, reason TEXT NOT NULL, payload_json TEXT NOT NULL, + provider TEXT, + cost_usd REAL, + tokens_used INTEGER, created_at TEXT NOT NULL ); ${rows .map( (r) => - `INSERT INTO attempt_log_events (seq, attempt_id, event_type, action_class, mode, reason, payload_json, created_at) VALUES (${r.seq}, '${r.attemptId}', '${r.eventType}', '${r.actionClass}', '${r.mode}', '${r.reason.replace(/'/g, "''")}', '${r.payloadJson.replace(/'/g, "''")}', '${r.createdAt}');`, + `INSERT INTO attempt_log_events (seq, attempt_id, event_type, action_class, mode, reason, payload_json, provider, cost_usd, tokens_used, created_at) VALUES (${r.seq}, '${r.attemptId}', '${r.eventType}', '${r.actionClass}', '${r.mode}', '${r.reason.replace(/'/g, "''")}', '${r.payloadJson.replace(/'/g, "''")}', ${sqlLiteral(r.provider ?? null)}, ${sqlLiteral(r.costUsd ?? null)}, ${sqlLiteral(r.tokensUsed ?? null)}, '${r.createdAt}');`, ) .join("\n")} `, @@ -132,6 +156,49 @@ describe("scripts/export-ams-reporting-db.sh", () => { expect(sqlite(outDb, "SELECT count(*) FROM pragma_table_info('attempt_log_events') WHERE name IN ('reason', 'payload_json');")).toBe("0"); }); + it("exports attempt_log_events' provider/cost_usd/tokens_used (#5185) unchanged, NULL when unset", () => { + const root = tmpRoot(); + const src = join(root, "attempt-log.sqlite3"); + seedAttemptLog(src, [ + { + seq: 1, + attemptId: "attempt-1", + eventType: "attempt_outcome_summary", + actionClass: "attempt_submitted", + mode: "live", + reason: "attempt finished", + payloadJson: "{}", + provider: "claude-cli", + costUsd: 0.42, + tokensUsed: 1000, + createdAt: "2026-07-12T00:00:00Z", + }, + { + seq: 2, + attemptId: "attempt-1", + eventType: "attempt_started", + actionClass: "codegen", + mode: "live", + reason: "live run", + payloadJson: "{}", + createdAt: "2026-07-12T00:00:01Z", + }, + ]); + + runExporter(root, { attemptLogSource: src }); + + const outDb = join(root, "reporting", "ams-attempt-log.sqlite"); + expect( + sqlite(outDb, "SELECT provider || '|' || cost_usd || '|' || tokens_used FROM attempt_log_events WHERE seq = 1;"), + ).toBe("claude-cli|0.42|1000"); + expect( + sqlite( + outDb, + "SELECT COALESCE(provider, 'NULL') || '|' || COALESCE(cost_usd, 'NULL') || '|' || COALESCE(tokens_used, 'NULL') FROM attempt_log_events WHERE seq = 2;", + ), + ).toBe("NULL|NULL|NULL"); + }); + it("exports predictions with every column intact (already bounded/structured, no free text)", () => { const root = tmpRoot(); const src = join(root, "prediction-ledger.sqlite3");