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");