diff --git a/scripts/turn-persistence-census.ts b/scripts/turn-persistence-census.ts new file mode 100644 index 000000000..be28f9752 --- /dev/null +++ b/scripts/turn-persistence-census.ts @@ -0,0 +1,277 @@ +#!/usr/bin/env bun +/** + * CL-10667 before/after measurement: per-turn session persistence write ops. + * + * Mirrors the reactor's persist sequence for one agentic turn: one inference + * cycle (writePrompt + writeResponse) and two tool batches followed by the + * cycle terminal. Every write-kind fs.promises call of the store stack is + * counted (split by whether the path is under .git), so the coalescing becomes + * an honest before/after delta on the same host and scenario. + * + * The flow itself changed shape with CL-10667, so the same script models both: + * --flow=legacy replicates the pre-coalescing reactor (tool-batch commitCycle + * per batch); --flow=coalesced replicates the post-coalescing one (writeTurns + * per tool batch, full commitCycle only at the cycle terminal). + * + * Usage: + * bun scripts/turn-persistence-census.ts [turnCount] [--flow=legacy|coalesced] [--json] + */ + +import fs from "node:fs"; +import path from "node:path"; +import type { ConversationTurn, TokenUsage } from "@intx/types/runtime"; +import { TransformRecord } from "@intx/types/runtime"; +import { createOptimizedContextStore } from "../src/session/optimized-context-store.js"; + +const WRITE_OPS = [ + "writeFile", + "appendFile", + "rename", + "unlink", + "truncate", + "mkdir", + "copyFile", +] as const; + +const counts: Record = {}; +const gitPaths: Record = {}; + +function bump(table: Record, op: string): void { + table[op] = (table[op] ?? 0) + 1; +} + +function installCounters(): void { + const target = fs.promises as unknown as Record; + for (const op of WRITE_OPS) { + const original = target[op]; + if (typeof original !== "function") continue; + target[op] = function counted(this: unknown, ...args: unknown[]) { + const first = args[0]; + if (typeof first === "string" && first.includes(`/.git/`)) { + bump(gitPaths, op); + } + bump(counts, op); + return (original as (...args: unknown[]) => unknown).apply(this, args); + }; + } +} + +function turn(text: string): ConversationTurn { + return { role: "user", content: [{ type: "text", text }], timestamp: 1 }; +} + +function assistantTurn(text: string): ConversationTurn { + return { + role: "assistant", + content: [{ type: "text", text }], + timestamp: 2, + }; +} + +function toolResultTurn(name: string): ConversationTurn { + return { + role: "user", + content: [ + { + type: "tool_result", + callId: `call-${name}`, + content: [{ type: "text", text: `${name} result` }], + }, + ], + timestamp: 3, + }; +} + +function turnBody(index: number): string { + return ( + `turn ${index}: ` + "census padding. ".repeat(40) + `end-of-turn ${index}` + ); +} + +const EMPTY_USAGE: TokenUsage = { + input: 0, + output: 0, + cacheRead: 0, + cacheWrite: 0, + thinking: 0, +}; + +function usageForTurn(turnCount: number): TokenUsage { + return { + ...EMPTY_USAGE, + input: 1000 * turnCount, + output: 500 * turnCount, + }; +} + +async function runScenario( + dir: string, + turnCount: number, + flow: string, +): Promise<{ turns: number; persistCalls: Record }> { + const base = await createOptimizedContextStore(dir); + const PERSIST_METHODS = [ + "writePrompt", + "writeResponse", + "writeTurns", + "writeManifest", + "writeMetadata", + "commit", + ] as const; + const persistCalls: Record = {}; + const store = Object.assign(Object.create(base), base) as typeof base; + for (const method of PERSIST_METHODS) { + const original = base[method] as ( + ...callArgs: unknown[] + ) => Promise; + (store as never as Record)[method] = ( + ...callArgs: unknown[] + ) => { + bump(persistCalls, method); + return original.apply(base, callArgs); + }; + } + const history: ConversationTurn[] = []; + const record: () => TransformRecord = () => ({ + strategy: "test.transform", + version: "1", + parameters: {}, + reason: "census", + decisions: {}, + }); + for (let t = 0; t < turnCount; t++) { + // Inference cycle: prompt + assistant turn. + history.push(turn(turnBody(t))); + history.push(assistantTurn(`reply to ${t}`)); + await store.writePrompt(history); + + if (flow === "legacy") { + const last = history[history.length - 1]; + if (last !== undefined && last.role === "assistant") { + await store.writeResponse({ + ...last, + role: "assistant", + model: last.model ?? "census-model", + }); + } + } + + for (let batch = 0; batch < 2; batch++) { + history.push(toolResultTurn(`tool-${t}-${batch}`)); + if (flow === "legacy") { + // Old tool-batch path: a full commitCycle per batch. + await store.writeTurns(history); + await store.writeManifest([record()]); + await store.writeMetadata({ + pendingOperations: [], + tokenUsage: usageForTurn(t + 1), + }); + await store.commit({ message: "checkpoint: tool-execution" }); + } else { + // Coalesced tool-batch path: segments on disk only. + await store.writeTurns(history); + } + } + + // Cycle terminal (reply/wait/done): the remaining cycle persists. + if (flow !== "legacy") { + await store.writeTurns(history); + // Two transforms happened; the terminal commit carries them. + await store.writeManifest([record(), record()]); + await store.writeMetadata({ + pendingOperations: [], + tokenUsage: usageForTurn(t), + }); + await store.commit({ message: "Cycle: done" }); + } + } + const fresh = await createOptimizedContextStore(dir); + const turns = (await fresh.load()).turns.length; + return { turns, persistCalls }; +} + +function sortedEntries(table: Record): [string, number][] { + return Object.entries(table).sort((a, b) => b[1] - a[1]); +} + +async function main(argv: string[]): Promise { + const arg = argv[2]; + const flow = argv.find((a) => a.startsWith("--flow="))?.split("=")[1]; + if (flow !== "legacy" && flow !== "coalesced") { + console.error( + "usage: bun scripts/turn-persistence-census.ts [turnCount] --flow=legacy|coalesced [--json]", + ); + return 1; + } + const turnCount = + arg !== undefined && !arg.startsWith("-") ? Number(arg) : 40; + if (!Number.isFinite(turnCount) || turnCount < 1) { + console.error(`invalid turnCount: ${arg}`); + return 1; + } + installCounters(); + + const prefix = `census-${flow}-`; + const dir = await fs.promises.mkdtemp(path.join(process.cwd(), prefix)); + const started = performance.now(); + const { turns: loadedTurns, persistCalls } = await runScenario( + dir, + turnCount, + flow, + ); + const wallMs = Math.round(performance.now() - started); + + const totalOps = Object.values(counts).reduce((sum, n) => sum + n, 0); + const gitOps = Object.values(gitPaths).reduce((sum, n) => sum + n, 0); + + const asJson = argv.includes("--json"); + if (asJson) { + console.log( + JSON.stringify( + { + flow, + turnCount, + wallMs, + loadedTurns, + totalWriteOps: totalOps, + gitPathWriteOps: gitOps, + byName: counts, + gitByPath: gitPaths, + perTurn: { + wallMs: +(wallMs / turnCount).toFixed(2), + writeOps: +(totalOps / turnCount).toFixed(2), + }, + persistCalls, + persistCallsPerTurn: Object.fromEntries( + Object.entries(persistCalls).map(([k, v]) => [ + k, + +(v / turnCount).toFixed(3), + ]), + ), + }, + null, + 2, + ), + ); + } else { + console.log( + `flow=${flow} ${turnCount} turns; verified ${loadedTurns} turns at the end`, + ); + console.log( + `wall: ${wallMs} ms (${(wallMs / turnCount).toFixed(2)} ms/turn)`, + ); + console.log( + `write ops: ${totalOps} total (${(totalOps / turnCount).toFixed(2)}/turn), of which ${gitOps} under .git`, + ); + for (const [op, n] of sortedEntries(counts)) { + console.log(` ${op}: ${n}`); + } + for (const [op, n] of sortedEntries(gitPaths)) { + console.log(` (.git) ${op}: ${n}`); + } + } + await fs.promises.rm(dir, { recursive: true, force: true }); + return 0; +} + +process.exit(await main(process.argv)); diff --git a/src/exec/runner.test.ts b/src/exec/runner.test.ts index d01f86cc1..de85c49d1 100644 --- a/src/exec/runner.test.ts +++ b/src/exec/runner.test.ts @@ -1,5 +1,6 @@ import { describe, expect, spyOn, test } from "bun:test"; import type { ToolCall } from "@intx/types/runtime"; +import { defined } from "../../testkit/defined.js"; import type { AgentTool } from "@intx/agent"; import { submitOutputDefinition } from "../agent/director.js"; import { DIRECTOR_REGISTRY } from "../agent/directors/registry.js"; @@ -564,6 +565,99 @@ describe("runExec", () => { cleanup(); } }); + + test("heartbeat forces identical-payload writes; a failed save does not take the baseline", async () => { + // CL-10667 review fix: the exec heartbeat tick must bypass the + // identical-payload skip (mtime freshness is a liveness contract read + // cross-process by ageStaleRunningState), and the baseline must record + // only successes so a transient save failure cannot freeze run.json. + const previous = getActiveRun(); + clearActiveRun(); + const sessionId = "exec-heartbeat-fail"; + const { cwd, home, cleanup } = createTempDirs( + "corbits-exec-heartbeat-cwd-", + "corbits-exec-heartbeat-home-", + ); + try { + const saveCalls: { ok: boolean; status?: string }[] = []; + await withMockedHomedir(home, () => + withMockedModuleDuring( + import.meta.resolve("../session/state.js"), + (real: typeof import("../session/state.js")) => + ({ + ...real, + saveState( + cwd: string, + sessionId: string, + state: import("../session/state.js").RunState, + dir?: string, + ) { + if (saveCalls.length === 0) { + saveCalls.push({ ok: false, status: state.status }); + // Transient failure on the first running write. + return Promise.reject(new Error("ENOSPC-like")); + } + saveCalls.push({ ok: true, status: state.status }); + return real.saveState(cwd, sessionId, state, dir); + }, + }) as typeof real, + () => + withMockedModuleDuring( + import.meta.resolve("../session/run-liveness.js"), + (real: typeof import("../session/run-liveness.js")) => + ({ + ...real, + RUN_HEARTBEAT_INTERVAL_MS: 10, + }) as typeof real, + () => + withMockedModuleDuring( + import.meta.resolve("../session/assemble-runtime.js"), + (inner: typeof import("../session/assemble-runtime.js")) => + ({ + ...inner, + assembleInferenceBase: () => + // Delay the bootstrap failure so heartbeat ticks run + // while the run is unsettled. + new Promise((_, reject) => { + setTimeout( + () => reject(new Error("bootstrap failed")), + 80, + ); + }), + }) as typeof inner, + async () => { + const { runExec: runExecUnderMock } = + await import("./runner.js"); + const result = await runExecUnderMock({ + ...bareConfig("do the thing"), + cwd, + sessionId, + }); + expect(result.status).toBe("failed"); + }, + ), + ), + ), + ); + + // Write 1 (running) failed; the heartbeat retried the identical payload + // and forced a disk write past any baseline; the terminal wrote last. + expect(saveCalls[0]).toEqual({ ok: false, status: "running" }); + const runningOk = saveCalls.findIndex((call) => call.ok); + expect(runningOk).toBeGreaterThan(0); + expect(defined(saveCalls[runningOk]).status).toBe("running"); + expect(defined(saveCalls[saveCalls.length - 1]).status).toBe("failed"); + const finalPersisted = await loadState(cwd, sessionId, home); + expect(finalPersisted).toMatchObject({ + kind: "ok", + state: { status: "failed" }, + }); + } finally { + if (previous !== null) setActiveRun(previous); + else clearActiveRun(); + cleanup(); + } + }); }); describe("resolveExecDirectorOverlay", () => { diff --git a/src/exec/runner.ts b/src/exec/runner.ts index c8a1b93bc..ff16db28e 100644 --- a/src/exec/runner.ts +++ b/src/exec/runner.ts @@ -101,6 +101,7 @@ import { clearActiveDisposeHost, } from "../session/active-host.js"; import { + createRunSnapshotDebouncer, finalizeRunState, loadState, saveState, @@ -531,13 +532,23 @@ export async function runExec(config: Config): Promise { : {}), }; let stopHeartbeat: (() => void) | undefined; + // CL-10667: debounced per-turn boundary snapshots; terminal exposes flush. + let runSnapshotDebouncer: + | ReturnType + | undefined; + + // CL-10667: last written running snapshot is the compare baseline for the + // identical-payload skip (terminal writes always land). + let lastProgressJson: string | null = null; const persist = async ( status: "running" | "done" | "failed" | "cancelled", extra?: { error?: string }, + force = false, ): Promise => { if (finalized && status === "running") return; if (status !== "running") { + await runSnapshotDebouncer?.flush(); finalized = true; stopHeartbeat?.(); stopHeartbeat = undefined; @@ -568,6 +579,12 @@ export async function runExec(config: Config): Promise { ? { error: sanitizeExecDiagnostic(extra.error) } : {}), }; + const payloadJson = JSON.stringify(snapshot, null, 2); + // force = heartbeat tick: mtime freshness is the write's job even when + // the payload is byte-identical to the baseline. + if (status === "running" && !force && payloadJson === lastProgressJson) { + return; + } const write = status === "running" ? saveState(config.cwd, sessionId, snapshot).then(() => { @@ -576,9 +593,12 @@ export async function runExec(config: Config): Promise { } }) : finalizeRunState(config.cwd, sessionId, snapshot); - await write.catch((err: unknown) => { - // A persistence failure must not fail the run, but silent drops hide - // disk/permission problems that leave run.json stale. + try { + await write; + // Baseline only what actually landed: a transient save failure (next + // tick or boundary snapshot then retries the same payload). + lastProgressJson = payloadJson; + } catch (err: unknown) { logger.warn( "saveState failed for session {sessionId} status={status}: {error}", { @@ -587,13 +607,18 @@ export async function runExec(config: Config): Promise { error: sanitizeExecDiagnostic(formatCaughtError(err)), }, ); - }); + } }; await persist("running"); + runSnapshotDebouncer = createRunSnapshotDebouncer({ + write: () => persist("running"), + }); stopHeartbeat = startRunHeartbeat({ shouldTick: () => !finalized, - tick: () => persist("running"), + // The heartbeat's job is mtime freshness, not payload change: force the + // write past the identical-payload skip. + tick: () => persist("running", undefined, true), }); try { @@ -1041,7 +1066,8 @@ export async function runExec(config: Config): Promise { activeRunHandle.cacheWriteModel = `${event.data.source.provider}:${event.data.source.model}`; } } - void persist("running"); + // CL-10667: debounced — the write recomputes state when it fires. + runSnapshotDebouncer?.schedule(); }, resolveContextDir: () => workdir, }); diff --git a/src/session/optimized-context-store.test.ts b/src/session/optimized-context-store.test.ts index 1d4f01804..8c78df32c 100644 --- a/src/session/optimized-context-store.test.ts +++ b/src/session/optimized-context-store.test.ts @@ -1993,3 +1993,278 @@ describe("createOptimizedContextStore per-turn perf (CL-10666)", () => { ).toBe(JSON.stringify({ turnSegments: [segmentFileName(TURNS_FILE, 1)] })); }); }); + +describe("createOptimizedContextStore response fold (CL-10667)", () => { + test("writeResponse touches no disk and a commit does not reintroduce the file", async () => { + const dir = tempDir(); + const store = await createOptimizedContextStore(dir); + await store.writeTurns([turn("a")]); + await store.writeResponse({ + role: "assistant", + content: [{ type: "text", text: "reply" }], + model: "m", + timestamp: 2, + }); + expect(fs.existsSync(path.join(dir, "response.jsonl"))).toBe(false); + await store.commit({ message: "fold" }); + const tree = await git.listFiles({ fs, dir, ref: "HEAD" }); + expect(tree.includes("response.jsonl")).toBe(false); + expect(fs.existsSync(path.join(dir, "response.jsonl"))).toBe(false); + }); +}); + +describe("createOptimizedContextStore manifest skip (CL-10667)", () => { + test("an empty buffer converges manifest.jsonl to absent by the next commit", async () => { + const dir = tempDir(); + const store = await createOptimizedContextStore(dir); + await store.writeTurns([turn("a")]); + await store.writeManifest([ + { + strategy: "test.transform", + version: "1", + parameters: {}, + reason: "ingest", + decisions: {}, + }, + ]); + await store.commit({ message: "with manifest" }); + expect( + (await git.listFiles({ fs, dir, ref: "HEAD" })).includes( + "manifest.jsonl", + ), + ).toBe(true); + + await store.writeManifest([]); + expect(fs.existsSync(path.join(dir, "manifest.jsonl"))).toBe(false); + await store.commit({ message: "empty buffer" }); + expect( + (await git.listFiles({ fs, dir, ref: "HEAD" })).includes( + "manifest.jsonl", + ), + ).toBe(false); + // readManifestHistory walks the commit chain: the earlier commit's + // records are still its history, exactly as they were when an empty + // write produced an empty blob; the converged worktree only removes the + // HEAD blob, not history. + expect(await store.readManifestHistory(5)).toEqual([ + { + strategy: "test.transform", + version: "1", + parameters: {}, + reason: "ingest", + decisions: {}, + }, + ]); + }); + + test("repeated empty buffers are disk no-ops", async () => { + const dir = tempDir(); + const store = await createOptimizedContextStore(dir); + await store.writeManifest([]); + await store.writeManifest([]); + expect(fs.existsSync(path.join(dir, "manifest.jsonl"))).toBe(false); + }); + + test("a non-empty buffer still writes and stages the manifest", async () => { + const dir = tempDir(); + const store = await createOptimizedContextStore(dir); + await store.writeTurns([turn("a")]); + await store.writeManifest([]); + await store.commit({ message: "prune" }); + await store.writeManifest([ + { + strategy: "test.transform", + version: "1", + parameters: {}, + reason: "ingest", + decisions: {}, + }, + ]); + const committed = await store.commit({ message: "re-write manifest" }); + expect( + (await git.listFiles({ fs, dir, ref: committed.hash })).includes( + "manifest.jsonl", + ), + ).toBe(true); + }); +}); + +describe("createOptimizedContextStore metadata ownership (CL-10667)", () => { + const USAGE_ONE = { + input: 10, + output: 20, + cacheRead: 1, + cacheWrite: 2, + thinking: 3, + }; + const USAGE_TWO = { + input: 110, + output: 220, + cacheRead: 1, + cacheWrite: 2, + thinking: 3, + }; + const pendingOp = { + correlationId: "corr-1", + kind: "approval" as const, + registeredAt: 1_700_000_000_000, + gateId: "gate-1", + }; + + test("writeMetadata keeps pendingOperations on metadata.json and usage on the sidecar", async () => { + const dir = tempDir(); + const store = await createOptimizedContextStore(dir); + await store.writeMetadata({ + pendingOperations: [pendingOp], + tokenUsage: USAGE_ONE, + }); + + const metadata = JSON.parse( + fs.readFileSync(path.join(dir, "metadata.json"), "utf8"), + ); + expect(metadata.pendingOperations).toEqual([pendingOp]); + expect(metadata.connectorState).toBeNull(); + expect(Object.keys(metadata).includes("tokenUsage")).toBe(false); + + const sidecar = fs + .readFileSync(path.join(dir, "token-usage.jsonl"), "utf8") + .trim() + .split("\n"); + expect(sidecar).toHaveLength(1); + expect(JSON.parse(defined(sidecar[0]))).toHaveProperty("usage", USAGE_ONE); + + // A fresh store reads the sidecar over the rewritten metadata. + const fresh = await createOptimizedContextStore(dir); + const loaded = await fresh.load(); + expect(loaded.pendingOperations).toEqual([pendingOp]); + expect(loaded.tokenUsage).toEqual(USAGE_ONE); + }); + + test("unchanged usage appends no sidecar line and identical metadata skips the rewrite", async () => { + const dir = tempDir(); + const store = await createOptimizedContextStore(dir); + await store.writeMetadata({ + pendingOperations: [pendingOp], + tokenUsage: USAGE_ONE, + }); + const sidecarPath = path.join(dir, "token-usage.jsonl"); + const metadataPath = path.join(dir, "metadata.json"); + expect((await fs.promises.stat(sidecarPath)).mtimeMs).toBeGreaterThan(0); + expect( + fs.readFileSync(sidecarPath, "utf8").trim().split("\n"), + ).toHaveLength(1); + // Stamp a long-gone mtime: a rewrite would move it. + await fs.promises.utimes(metadataPath, new Date(9e11), new Date(9e11)); + await store.writeMetadata({ + pendingOperations: [pendingOp], + tokenUsage: USAGE_ONE, + }); + expect( + fs.readFileSync(sidecarPath, "utf8").trim().split("\n"), + ).toHaveLength(1); + expect((await fs.promises.stat(metadataPath)).mtimeMs).toBe(9e11); + + // A usage change appends exactly one more line. + await store.writeMetadata({ + pendingOperations: [pendingOp], + tokenUsage: USAGE_TWO, + }); + const lines = fs.readFileSync(sidecarPath, "utf8").trim().split("\n"); + expect(lines).toHaveLength(2); + expect(JSON.parse(defined(lines[1]))).toHaveProperty("usage", USAGE_TWO); + const loaded = await (await createOptimizedContextStore(dir)).load(); + expect(loaded.tokenUsage).toEqual(USAGE_TWO); + }); + + test("the sidecar overrides a legacy metadata.json tokenUsage", async () => { + const dir = tempDir(); + fs.writeFileSync( + path.join(dir, "metadata.json"), + JSON.stringify({ + pendingOperations: [], + tokenUsage: { + input: 5, + output: 5, + cacheRead: 0, + cacheWrite: 0, + thinking: 0, + }, + connectorState: null, + }), + ); + fs.writeFileSync( + path.join(dir, "token-usage.jsonl"), + `${JSON.stringify({ turnIndex: 3, usage: USAGE_ONE })}\n`, + ); + const store = await createOptimizedContextStore(dir); + expect((await store.load()).tokenUsage).toEqual(USAGE_ONE); + }); + + test("no sidecar falls back to the legacy metadata.json tokenUsage", async () => { + const dir = tempDir(); + fs.writeFileSync( + path.join(dir, "metadata.json"), + JSON.stringify({ + pendingOperations: [], + tokenUsage: USAGE_TWO, + connectorState: null, + }), + ); + const store = await createOptimizedContextStore(dir); + expect((await store.load()).tokenUsage).toEqual(USAGE_TWO); + }); + + test("torn metadata.json does not zero a valid sidecar", async () => { + const dir = tempDir(); + fs.writeFileSync(path.join(dir, "metadata.json"), "{not-json"); + fs.writeFileSync( + path.join(dir, "token-usage.jsonl"), + `${JSON.stringify({ turnIndex: 1, usage: USAGE_ONE })}\n`, + ); + const store = await createOptimizedContextStore(dir); + const loaded = await store.load(); + expect(loaded.tokenUsage).toEqual(USAGE_ONE); + expect(loaded.tokenUsage.input).toBe(10); + expect(loaded.pendingOperations).toEqual([]); + expect(loaded.connectorState).toBeNull(); + }); + + test("a torn last sidecar line drops and the prior record survives", async () => { + const dir = tempDir(); + fs.writeFileSync( + path.join(dir, "token-usage.jsonl"), + `${JSON.stringify({ turnIndex: 1, usage: USAGE_ONE })}\n` + + '{"turnIndex":2,"usage":{"input":', + ); + const store = await createOptimizedContextStore(dir); + expect((await store.load()).tokenUsage).toEqual(USAGE_ONE); + }); + + test("resume restore picks the sidecar state the crashed turn reached", async () => { + const dir = tempDir(); + const storeA = await createOptimizedContextStore(dir); + await storeA.writeTurns([turn("a")]); + await storeA.writeMetadata({ + pendingOperations: [], + tokenUsage: { + input: 1, + output: 1, + cacheRead: 0, + cacheWrite: 0, + thinking: 0, + }, + }); + await storeA.commit({ message: "base" }); + await storeA.writeTurns([turn("a"), turn("b")]); + await storeA.writeMetadata({ + pendingOperations: [], + tokenUsage: USAGE_TWO, + }); + // No commit: the crash happened before the turn's git checkpoint. The + // next store instance reads the sidecar the crash left on disk. + await storeA.commit({ message: "unused" }); + + const resumed = await createOptimizedContextStore(dir); + expect((await resumed.load()).tokenUsage).toEqual(USAGE_TWO); + }); +}); diff --git a/src/session/optimized-context-store.ts b/src/session/optimized-context-store.ts index b1d59768e..0cc038c1b 100644 --- a/src/session/optimized-context-store.ts +++ b/src/session/optimized-context-store.ts @@ -7,12 +7,14 @@ import { type CommitSigner, } from "@intx/storage-isogit/node"; import { + ApprovalSnapshot, ContentBlock, + ConnectorThreadState, type AuditStore, - type ConnectorThreadState, + TokenUsage, type ConversationTurn, type PendingOperation, - type TokenUsage, + ToolCall, } from "@intx/types/runtime"; import { getLogger } from "@intx/log"; import { @@ -32,6 +34,12 @@ const PROMPT_FILE = "prompt.jsonl"; const RESPONSE_FILE = "response.jsonl"; const MANIFEST_FILE = "manifest.jsonl"; const METADATA_FILE = "metadata.json"; +// Append-only tokenUsage sidecar (CL-10667): a per-turn line keyed to the +// turn frontier so per-commit metadata.json rewrites stop re-hashing token +// data. No consumer ever read response.jsonl (sessions list, resume crash +// recovery all read the turns store), so it is folded away entirely; see +// store.writeResponse. +const TOKEN_USAGE_SIDECAR_FILE = "token-usage.jsonl"; const TOOL_OUTPUT_DIR = "tool-output"; const EVIDENCE_ARCHIVE_DIR = "evidence-archive"; const OWNER_MARKER_FILE = "session-owner.json"; @@ -250,24 +258,126 @@ function emptyMetadata(): SessionMetadata { } /** - * Soft-default metadata only when metadata.json is unreadable, so poisoned - * turns still resume without wiping pendingOperations / tokenUsage / - * connectorState. + * CL-10667 metadata ownership. metadata.json now carries pendingOperations + * and connectorState only; tokenUsage lives on an append-only sidecar keyed + * to the turn frontier so per-commit rewrites stop re-hashing token data. + * Legacy files still carry tokenUsage (the old vendor shape) and read as the + * fallback when the sidecar holds nothing. */ -async function loadMetadataSoft( - loadMetadata: () => Promise, -): Promise { +const StoredPendingOperationSchema = type({ + correlationId: "string", + kind: "'approval'", + "expectedFrom?": "string", + registeredAt: "number", + gateId: "string", + "timeoutAt?": "number", + "suspendedCall?": ToolCall, + "approvalSnapshot?": ApprovalSnapshot, +}); + +const StoredMetadataSchema = type({ + pendingOperations: StoredPendingOperationSchema.array(), + "tokenUsage?": TokenUsage, + "connectorState?": type("null").or(ConnectorThreadState), +}); + +const TokenUsageSidecarLineSchema = type({ + turnIndex: "number", + usage: TokenUsage, +}); + +async function readTextOrNull(filePath: string): Promise { try { - return await loadMetadata(); + return await fs.promises.readFile(filePath, "utf-8"); + } catch (cause) { + if (cause instanceof Error && "code" in cause && cause.code === "ENOENT") + return null; + throw cause; + } +} + +/** + * Last well-formed sidecar line wins; a torn line (append torn mid-write) + * drops silently like a torn JSONL tail. + */ +async function readLatestSidecarUsage(dir: string): Promise { + const raw = await readTextOrNull(path.join(dir, TOKEN_USAGE_SIDECAR_FILE)); + if (raw === null) return null; + let latest: TokenUsage | null = null; + for (const line of raw.split("\n")) { + if (line.length === 0) continue; + try { + const result = TokenUsageSidecarLineSchema(JSON.parse(line)); + if (!(result instanceof type.errors)) latest = result.usage; + } catch { + // Torn or non-JSON line: keep the last good record. + } + } + return latest; +} + +function readMetadataDocument(raw: string): Pick< + SessionMetadata, + "pendingOperations" | "connectorState" +> & { + legacyTokenUsage: TokenUsage | null; +} { + const parsed: unknown = JSON.parse(raw); + const result = StoredMetadataSchema(parsed); + if (result instanceof type.errors) { + throw new Error( + `metadata.json has unexpected structure: ${result.summary}`, + ); + } + return { + pendingOperations: result.pendingOperations, + connectorState: result.connectorState ?? null, + legacyTokenUsage: result.tokenUsage ?? null, + }; +} + +/** + * metadata.json + sidecar merge. Sidecar wins over a legacy tokenUsage field, + * which wins over empty. Parse failures stay inside this function: a torn + * "{not-json" document soft-defaults pending ops and connector state, but the + * sidecar is read anyway. Letting the throw escape made load()'s catch assign + * emptyMetadata() and report all-zero usage. + */ +async function readSessionMetadata(dir: string): Promise { + const sidecarUsage = await readLatestSidecarUsage(dir); + let document: ReturnType = { + pendingOperations: [], + connectorState: null, + legacyTokenUsage: null, + }; + try { + const raw = await readTextOrNull(path.join(dir, METADATA_FILE)); + if (raw !== null && raw.length > 0) { + document = readMetadataDocument(raw); + } } catch (cause) { log.warn( - "metadata.json unreadable during resilient load; using empty defaults", - { - cause: cause instanceof Error ? cause.message : String(cause), - }, + "session metadata document unreadable; keeping sidecar usage and empty document defaults", + { cause: cause instanceof Error ? cause.message : String(cause) }, ); - return emptyMetadata(); } + const tokenUsage = sidecarUsage ?? + document.legacyTokenUsage ?? { ...EMPTY_TOKEN_USAGE }; + return { + pendingOperations: document.pendingOperations, + tokenUsage, + connectorState: document.connectorState, + }; +} + +function sameTokenUsage(a: TokenUsage, b: TokenUsage): boolean { + return ( + a.input === b.input && + a.output === b.output && + a.cacheRead === b.cacheRead && + a.cacheWrite === b.cacheWrite && + a.thinking === b.thinking + ); } /** @@ -1024,6 +1134,32 @@ export interface SessionStoreOptions { ownerId?: string; } +let metadataPublishSeq = 0; + +/** + * Publish metadata.json only once the bytes are complete. writeFile on the + * published name can crash mid-write and leave "{not-json" as metadata.json; + * a temp sibling in the same directory plus rename is the published name + * appearing with a finished document, same as partial.jsonl. + */ +async function publishMetadataDocument( + dir: string, + desired: string, +): Promise { + const target = path.join(dir, METADATA_FILE); + const tmp = path.join( + dir, + `.${METADATA_FILE}.${process.pid}.${(metadataPublishSeq += 1)}.tmp`, + ); + try { + await fs.promises.writeFile(tmp, desired); + await fs.promises.rename(tmp, target); + } catch (cause) { + await fs.promises.rm(tmp, { force: true }).catch(() => undefined); + throw cause; + } +} + /** * Interchange git-store wrapper that avoids O(session length) work per * checkpoint: turns and prompts write as rolling segments so only the active @@ -1049,6 +1185,64 @@ export async function createSessionStores( let unpublishedRewrite: ConversationTurn[] | null = null; let pendingPrompt: ConversationTurn[] | null = null; let stagedPrompt: ConversationTurn[] | null = null; + // metadata.json ownership (CL-10667): this store writes the file itself, so + // the base's pendingConnectorState buffer would never land. The written + // payload is the compare baseline — metadata.json changes only through this + // path in-process, matching the segment writers' single-writer assumption. + let connectorStateBuffer: ConnectorThreadState | null = null; + let writtenMetadataJson: string | null = null; + let metadataJsonSeeded = false; + let sidecarUsage: TokenUsage | null = null; + let sidecarUsageSeeded = false; + + // One sidecar line per tokenUsage CHANGE, keyed to the turn frontier the + // store manages. Appending on change (instead of on every write call) + // keeps the last line exactly what a crash resume reads without growing + // one line per commit; usage is monotone, so an older line never wins. + async function appendUsageSidecar(tokenUsage: TokenUsage): Promise { + if (!sidecarUsageSeeded) { + sidecarUsage = await readLatestSidecarUsage(dir); + sidecarUsageSeeded = true; + } + if (sidecarUsage !== null && sameTokenUsage(sidecarUsage, tokenUsage)) { + return; + } + const turnIndex = (unpublishedRewrite ?? liveTurnRefs)?.length ?? 0; + await fs.promises.appendFile( + path.join(dir, TOKEN_USAGE_SIDECAR_FILE), + `${JSON.stringify({ turnIndex, usage: tokenUsage })}\n`, + "utf8", + ); + sidecarUsage = { ...tokenUsage }; + } + + async function writeMetadataLive(metadata: { + pendingOperations: PendingOperation[]; + tokenUsage: TokenUsage; + }): Promise { + await appendUsageSidecar(metadata.tokenUsage); + // Approval snapshot args persist into metadata.json in the clear; scrub + // them at this app-owned write (suspendedCall stays raw for the approved + // call's re-dispatch). + const desired = JSON.stringify( + { + pendingOperations: scrubPersistedPendingOperations( + metadata.pendingOperations, + ), + connectorState: connectorStateBuffer, + }, + null, + 2, + ); + if (!metadataJsonSeeded) { + writtenMetadataJson = await readTextOrNull(path.join(dir, METADATA_FILE)); + metadataJsonSeeded = true; + } + if (writtenMetadataJson !== desired) { + await publishMetadataDocument(dir, desired); + writtenMetadataJson = desired; + } + } function divertToVersionedBases(): void { if (versionedBase !== null) return; @@ -1468,10 +1662,26 @@ export async function createSessionStores( { cause }, ); } - const metadata = await loadMetadataSoft(() => base.loadMetadata()); + let metadata: SessionMetadata; + try { + metadata = await readSessionMetadata(dir); + } catch (cause) { + // Unreadable metadata alone must not abort resume when turns are + // fine: soft-default, the same contract the base load always had. + log.warn( + "session metadata unreadable during resilient load; using empty defaults", + { cause: cause instanceof Error ? cause.message : String(cause) }, + ); + metadata = emptyMetadata(); + } return { turns, ...metadata }; }, - setConnectorState: (state) => base.setConnectorState(state), + // Buffer is carried only by this store: base.writeMetadata is never + // called through the wrapper, so base's pendingConnectorState would + // never land. + setConnectorState: (state) => { + connectorStateBuffer = state; + }, branch: (name, signal) => base.branch(name, signal), log: (limit, signal) => base.log(limit, signal), async readAt(hash, signal) { @@ -1525,22 +1735,28 @@ export async function createSessionStores( // Skipped identical snapshots fall back to live turns; load() never reads // prompt.jsonl. writePrompt: (turns) => queuePrompt(turns), - writeResponse: (turn, signal) => base.writeResponse(turn, signal), - writeManifest: (records, signal) => base.writeManifest(records, signal), + // CL-10667 fold: response.jsonl duplicated the assistant turn turns.jsonl + // already carries, and nothing in the repo reads it (grep over src, + // scripts, e2e, and the vendored packages: write-only). The per-commit + // re-write plus re-hash went to zero; LEGACY trees that still hold one + // keep staging as a vendor root. + writeResponse: () => Promise.resolve(), + async writeManifest(records, signal) { + if (records.length === 0) { + // Empty cycle buffers converge the worktree to no manifest, the same + // way an identical prompt converges to no prompt segment: the removal + // joins the pending set, one index write carries it at commit, and + // readManifestHistory reads a missing manifest as no records. + if (await pathExists(path.join(dir, MANIFEST_FILE))) { + await fs.promises.unlink(path.join(dir, MANIFEST_FILE)); + pendingSegmentPaths.add(MANIFEST_FILE); + } + return; + } + await base.writeManifest(records, signal); + }, writeTurns: (turns) => writeTurnsLiveOrStage(turns), - writeMetadata: (metadata, signal) => - // Approval snapshot args persist into metadata.json in the clear; scrub - // them at the app-owned write boundary (suspendedCall stays raw for the - // approved call's re-dispatch). - base.writeMetadata( - { - ...metadata, - pendingOperations: scrubPersistedPendingOperations( - metadata.pendingOperations, - ), - }, - signal, - ), + writeMetadata: (metadata) => writeMetadataLive(metadata), readManifestHistory: (limit, signal) => base.readManifestHistory(limit, signal), async writeBlob(key, bytes, contentType, signal) { diff --git a/src/session/run-snapshot-debounce.test.ts b/src/session/run-snapshot-debounce.test.ts new file mode 100644 index 000000000..e54c68d13 --- /dev/null +++ b/src/session/run-snapshot-debounce.test.ts @@ -0,0 +1,82 @@ +import { describe, expect, test } from "bun:test"; + +import { createTempDirs } from "../../testkit/temporary-dirs.js"; +import { generateSessionId } from "./index.js"; +import { + createRunSnapshotDebouncer, + loadState, + saveState, + type RunState, +} from "./state.js"; + +function snap(turnsUsed: number): RunState { + return { + status: "running", + turnsUsed, + task: "debounce test", + startedAt: 1, + model: "test-provider:test-model", + mcpServers: [], + }; +} + +describe("createRunSnapshotDebouncer (CL-10667)", () => { + test("a burst of schedules behind one window lands as one write", async () => { + const { cwd, home, cleanup } = createTempDirs( + "corbits-debounce-cwd-", + "corbits-debounce-home-", + ); + const sessionId = generateSessionId(); + try { + let turnsUsed = 0; + const debouncer = createRunSnapshotDebouncer({ + write: async () => { + turnsUsed += 1; + await saveState(cwd, sessionId, snap(turnsUsed), home); + }, + intervalMs: 20, + }); + + for (let i = 0; i < 10; i++) debouncer.schedule(); + // The timer fires the coalesced batch once the window elapses. + await new Promise((resolve) => setTimeout(resolve, 120)); + + const onDisk = await loadState(cwd, sessionId, home); + expect(onDisk).toMatchObject({ kind: "ok", state: { turnsUsed: 1 } }); + } finally { + cleanup(); + } + }); + + test("flush runs a pending write immediately; a clean flush writes nothing", async () => { + let writes = 0; + const debouncer = createRunSnapshotDebouncer({ + write: async () => { + writes += 1; + }, + intervalMs: 60_000, // armed but never able to fire on its own + }); + + debouncer.schedule(); + await debouncer.flush(); + expect(writes).toBe(1); + // Nothing pending: flush is a no-op, not a second write. + await debouncer.flush(); + expect(writes).toBe(1); + }); + + test("flush after the timer already fired is a no-op", async () => { + let writes = 0; + const debouncer = createRunSnapshotDebouncer({ + write: async () => { + writes += 1; + }, + intervalMs: 15, + }); + + debouncer.schedule(); + await new Promise((resolve) => setTimeout(resolve, 60)); + await debouncer.flush(); + expect(writes).toBe(1); + }); +}); diff --git a/src/session/state.ts b/src/session/state.ts index df1633a1d..9b35fdaf6 100644 --- a/src/session/state.ts +++ b/src/session/state.ts @@ -131,6 +131,62 @@ export async function saveState( return write; } +/** + * Debounce window for mid-run `running` snapshots (CL-10667): coalesces the + * per-turn boundary write to ~0.2/turn at a ~1s/turn cadence, while the + * run-liveness heartbeat keeps mtime freshness over longer gaps. + */ +export const RUN_SNAPSHOT_DEBOUNCE_MS = 5_000; + +export interface RunSnapshotDebouncer { + /** Mark a pending write and arm the one-shot timer once. */ + schedule: () => void; + /** Cancel the timer and run any pending write immediately. */ + flush: () => Promise; +} + +/** + * Lazy payoff: the deferred write recomputes its snapshot when it fires, not + * at schedule time, so a front of rapid turns persists the state current at + * fire time. One timer; `schedule` while armed only re-marks dirty. The + * writer maps write failures to undefined so a stalled flush cannot wedge + * the terminal path that awaits it. + */ +export function createRunSnapshotDebouncer(args: { + write: () => Promise; + intervalMs?: number; +}): RunSnapshotDebouncer { + const intervalMs = args.intervalMs ?? RUN_SNAPSHOT_DEBOUNCE_MS; + let timer: ReturnType | null = null; + let dirty = false; + let inFlight: Promise = Promise.resolve(); + + const run = (): void => { + dirty = false; + inFlight = args.write().catch(() => undefined); + }; + + return { + schedule: () => { + dirty = true; + if (timer !== null) return; + timer = setTimeout(() => { + timer = null; + if (dirty) run(); + }, intervalMs); + timer.unref?.(); + }, + flush: async () => { + if (timer !== null) { + clearTimeout(timer); + timer = null; + } + if (dirty) run(); + await inFlight; + }, + }; +} + // Terminal-write path: clears the in-memory active-run handle (active-run.ts) // alongside the on-disk status so the two cannot drift. Non-terminal // ("running") snapshots use saveState directly. diff --git a/src/tui/runner/exit.test.ts b/src/tui/runner/exit.test.ts index d7ac5b2e3..261f4d0d1 100644 --- a/src/tui/runner/exit.test.ts +++ b/src/tui/runner/exit.test.ts @@ -27,6 +27,11 @@ import { withMockedModuleDuring, } from "../../../testkit/mock-module.js"; import { createTempDirs } from "../../../testkit/temporary-dirs.js"; +import fsSync from "node:fs"; +import { readFile, stat, utimes } from "node:fs/promises"; +import { sessionDir } from "../../session/index.js"; +import type { RunState } from "../../session/state.js"; +import { createRunPersistence } from "./exit.js"; import { createDeliveryGeneration, createSessionOperationQueue, @@ -1178,3 +1183,132 @@ describe("observeRecoveryAttempts fan-out", () => { expect(seat.reconnectRecovery.settle(reconnectAttempt)).not.toBeNull(); }); }); + +describe("createRunPersistence — identical-payload skip (CL-10667)", () => { + function persistenceStub(args: { + runSinkTurnCount: () => number; + cwd: string; + }): { + writeRunSnapshot: () => Promise; + heartbeatRunSnapshot: () => Promise; + persistOnce: () => Promise; + } { + const state = { + host: { waitUntilExit: async () => undefined }, + config: { cwd: args.cwd, task: "t" }, + sessionId: "s", + startedAt: 1, + runTaskTitle: "t", + connectedMcpServers: [], + liveSource: { id: "p", model: "m" }, + } as unknown as RunnerState; + const services = { + runSink: { getTurnCount: args.runSinkTurnCount }, + crashGuard: { markFinalized: () => undefined, isFinalized: () => false }, + activeRunHandle: { task: "", startedAt: 0, turnsUsed: 0, model: "" }, + activatedToolNames: { list: () => [] }, + } as unknown as RunnerServices; + const { writeRunSnapshot, persistRunSnapshot, heartbeatRunSnapshot } = + createRunPersistence(state, services); + return { + writeRunSnapshot: () => writeRunSnapshot("running"), + heartbeatRunSnapshot, + persistOnce: () => persistRunSnapshot("running"), + }; + } + + test("identical progress snapshots skip; heartbeat ticks bypass the skip", async () => { + const directories = createTempDirs( + "corbits-runpersist-cwd-", + "corbits-runpersist-home-", + ); + try { + let turnsUsed = 0; + await withMockedHomedir(directories.home, async () => { + const { heartbeatRunSnapshot, persistOnce } = persistenceStub({ + runSinkTurnCount: () => turnsUsed, + cwd: directories.cwd, + }); + const runPath = `${sessionDir(directories.cwd, "s")}/run.json`; + + await heartbeatRunSnapshot(); + const first = JSON.parse(await readFile(runPath, "utf8")); + expect(first.turnsUsed).toBe(0); + // Stamp a long-gone mtime: any rewrite would move it. + await utimes(runPath, new Date(9e11), new Date(9e11)); + + // Payload-identical non-heartbeat progress write: skipped, mtime + // untouched. + await persistOnce(); + expect((await stat(runPath)).mtimeMs).toBe(9e11); + + // Heartbeat tick with the SAME payload: forces the write — the mtime + // is what ageStaleRunningState reads cross-process, and a skipped + // heartbeat would age a live run to "interrupted". + await heartbeatRunSnapshot(); + expect((await stat(runPath)).mtimeMs).not.toBe(9e11); + + // A changed payload lands like before. + turnsUsed = 1; + await persistOnce(); + const changed = JSON.parse(await readFile(runPath, "utf8")); + expect(changed.turnsUsed).toBe(1); + }); + } finally { + await directories.cleanup(); + } + }); + + test("a failed save does not take the baseline; the identical retry rewrites", async () => { + const directories = createTempDirs( + "corbits-runpersist-fail-cwd-", + "corbits-runpersist-fail-home-", + ); + try { + let turnsUsed = 0; + await withMockedHomedir(directories.home, () => + withMockedModuleDuring( + import.meta.resolve("../../session/state.js"), + (real: typeof import("../../session/state.js")) => { + let failingFirst = true; + return { + ...real, + saveState( + cwd: string, + sessionId: string, + persisted: RunState, + home?: string, + ): Promise { + if (!failingFirst) + return real.saveState(cwd, sessionId, persisted, home); + failingFirst = false; + return Promise.reject(new Error("transient save failure")); + }, + }; + }, + async () => { + const { persistOnce } = persistenceStub({ + runSinkTurnCount: () => turnsUsed, + cwd: directories.cwd, + }); + // First attempt fails; the caller awaits the rejection. + await persistOnce().catch((err: unknown) => { + expect(String(err)).toMatch(/transient save failure/); + }); + const runPath = `${sessionDir(directories.cwd, "s")}/run.json`; + expect(fsSync.existsSync(runPath)).toBe(false); + + // Identical payload is still rewritten: the failed attempt + // never took the baseline. + await persistOnce(); + expect(JSON.parse(await readFile(runPath, "utf8")).turnsUsed).toBe( + 0, + ); + }, + ), + ); + } finally { + await directories.cleanup(); + } + }); +}); diff --git a/src/tui/runner/exit.ts b/src/tui/runner/exit.ts index a05e221ce..549dd9453 100644 --- a/src/tui/runner/exit.ts +++ b/src/tui/runner/exit.ts @@ -24,6 +24,7 @@ import { setAgentSourceUnlessClosed } from "../agent-source-sync.js"; import { billingIdentityFromSource } from "../../cost/session-cost.js"; import { createRunSummary, type RunSummary } from "../../session/hooks.js"; import { + createRunSnapshotDebouncer, finalizeRunState, saveState, type RunState, @@ -189,12 +190,22 @@ export function clearsActiveRun(kind: SnapshotKind): boolean { /** * The run.json snapshot writers. Pure over (state, services), so the * lifecycle and the finalize tail can each build their own instance. + * Exported for tests building the minimal (state, services) stub. */ -function createRunPersistence(state: RunnerState, services: RunnerServices) { +export function createRunPersistence( + state: RunnerState, + services: RunnerServices, +) { + // Identical-payload skip (CL-10667): the last written snapshot is the + // compare baseline; an unchanged progress snapshot skips the atomicWrite + // (terminal kinds always write — the skipped path never clears the active + // run handle, which finalizeRunState does). + let lastProgressJson: string | null = null; const writeRunSnapshot = async ( status: SnapshotStatus, extra?: SnapshotExtra, kind: SnapshotKind = "progress", + force = false, ): Promise => { const task = state.runTaskTitle.trim().length > 0 @@ -225,11 +236,20 @@ function createRunPersistence(state: RunnerState, services: RunnerServices) { : {}), ...extra, }; + const payloadJson = JSON.stringify(persisted, null, 2); + // force = heartbeat tick: mtime freshness is the write's job even when + // the payload is byte-identical to the baseline. + if (!force && kind === "progress" && payloadJson === lastProgressJson) { + return; + } if (clearsActiveRun(kind)) { await finalizeRunState(state.config.cwd, state.sessionId, persisted); } else { await saveState(state.config.cwd, state.sessionId, persisted); } + // Baseline only what landed: a failed save must not suppress the next + // attempt at the same payload. + lastProgressJson = payloadJson; }; // Progress snapshots fire unsequenced (model switch, MCP connect, turn @@ -249,7 +269,30 @@ function createRunPersistence(state: RunnerState, services: RunnerServices) { await writeRunSnapshot(status, extra, kind); }; - return { writeRunSnapshot, persistRunSnapshot }; + // The run-liveness heartbeat must bypass the identical-payload skip: its + // payload is often byte-identical (a long quiet turn), but run.json's + // mtime is what `ageStaleRunningState` reads cross-process — a skipped + // heartbeat would age a live run to "interrupted" after two missed beats. + const heartbeatRunSnapshot = async (): Promise => { + if (services.crashGuard.isFinalized()) return; + await writeRunSnapshot("running", undefined, "progress", true); + }; + + // CL-10667: per-turn boundary snapshots coalesce behind the debounce + // window plus the identical-payload skip above (lazy payoff — the deferred + // write recomputes state at fire time, so nothing scheduled goes stale). + // Observable exposes flush before they observe or supersede run.json. + const runSnapshotDebouncer = createRunSnapshotDebouncer({ + write: () => persistRunSnapshot("running"), + }); + + return { + writeRunSnapshot, + persistRunSnapshot, + heartbeatRunSnapshot, + scheduleRunSnapshot: runSnapshotDebouncer.schedule, + flushRunSnapshot: runSnapshotDebouncer.flush, + }; } /** @@ -295,8 +338,18 @@ export async function createRunLifecycle( newSession: () => void; agentProxy: Agent; }> { - const { persistRunSnapshot } = createRunPersistence(state, services); + const { + persistRunSnapshot, + heartbeatRunSnapshot, + scheduleRunSnapshot, + flushRunSnapshot, + } = createRunPersistence(state, services); state.persistRunSnapshot = persistRunSnapshot; + // CL-10667: per-turn boundary snapshots schedule behind the debounce + // window; observable exposes (interrupt rebuild, rotation, finalize) flush + // the pending write before they observe or supersede run.json. + state.scheduleRunSnapshot = scheduleRunSnapshot; + state.flushRunSnapshot = flushRunSnapshot; const activateAndCommitWire = (names: string[]): void => { if (!services.activatedToolNames.activate(names)) return; if (services.flushPromotions()) { @@ -310,7 +363,9 @@ export async function createRunLifecycle( }; const stopHeartbeat = startRunHeartbeat({ shouldTick: () => !services.crashGuard.isFinalized(), - tick: () => persistRunSnapshot("running"), + // The heartbeat's job is mtime freshness, not payload change: force the + // write past the identical-payload skip (see heartbeatRunSnapshot). + tick: () => heartbeatRunSnapshot(), }); state.stopRunHeartbeat = stopHeartbeat; @@ -586,6 +641,10 @@ export async function createRunLifecycle( enqueue: enqueueOp, rebuild: async () => { try { + // CL-10667: run.json is observable the moment the rebuild starts + // reading store state, so the pending debounced snapshot flushes + // first. + await state.flushRunSnapshot?.(); // close() tears down stream consumers before the aborted cycle's // inference.error is delivered, so the recorder never sees a // terminal event. Dispose before that teardown salvages the buffer @@ -672,6 +731,10 @@ export async function createRunLifecycle( }, ); }); + // CL-10667: the rotation terminal write supersets the pending + // snapshot for the outgoing session; flush so the debounced write + // cannot straddle the id repoint below. + await state.flushRunSnapshot?.(); await persistRunSnapshot( "done", { finishedAt: Date.now() }, @@ -755,6 +818,9 @@ export async function finalizeTUIRun( await hostOf(state).waitUntilExit(); state.stopRunHeartbeat?.(); delete state.stopRunHeartbeat; + // CL-10667: pending debounced snapshots flush ahead of the terminal write + // so a failed or dropped terminal write cannot leave run.json stale. + await state.flushRunSnapshot?.(); // Stop workers before awaiting the session-op tail so a hung enqueue cannot // delay abort/reap; persistence, hooks, and telemetry stay after stop. // Toolset dispose lives inside shutdownRuntime so quit, crash, and signals diff --git a/src/tui/runner/session.ts b/src/tui/runner/session.ts index bc039dfdc..7d5c039b0 100644 --- a/src/tui/runner/session.ts +++ b/src/tui/runner/session.ts @@ -176,7 +176,8 @@ export async function assembleTUISession( start.activeRunHandle.cacheWriteModel = `${event.data.source.provider}:${event.data.source.model}`; } } - void state.persistRunSnapshot?.("running"); + // CL-10667: debounced — the write recomputes state when it fires. + state.scheduleRunSnapshot?.(); }, hookEnabled: initialHookEnabled, onHookEvent: (event) => emitter.emit("hook", event), diff --git a/src/tui/runner/state.ts b/src/tui/runner/state.ts index 941769d05..c3393a911 100644 --- a/src/tui/runner/state.ts +++ b/src/tui/runner/state.ts @@ -332,6 +332,10 @@ export interface RunnerState { extra?: SnapshotExtra, kind?: Exclude, ) => Promise; + /** CL-10667: debounced per-turn boundary snapshot writer. */ + scheduleRunSnapshot?: () => void; + /** CL-10667: flush any pending debounced snapshot before observing run.json. */ + flushRunSnapshot?: () => Promise; shutdownRuntime?: () => Promise; stopFleetReporting?: () => void; stopRunHeartbeat?: () => void; diff --git a/vendor/intx-inference/PATCHES.md b/vendor/intx-inference/PATCHES.md index 6cb73fa35..516a7d704 100644 --- a/vendor/intx-inference/PATCHES.md +++ b/vendor/intx-inference/PATCHES.md @@ -409,22 +409,32 @@ doom-loop accounting. accounting block, re-verify the reset branch after upstream changes to batch signatures or repeat counting. -## reactor-ts-checkpoint-after-tool-cycle - -`reactor.ts` — Checkpoint after a tool cycle that appends to history. -`executeTools` now calls `commitCycle()` when `addToHistory` is true, so an -interrupt that rebuilds the agent from the store reloads the completed tool -exchange instead of losing an uncommitted tool turn (context previously -committed only at cycle terminals). - -**Disposition:** Promotion candidate. Durability correctness fix — -interrupting after a tool cycle must not lose committed tool turns. -**Removal path:** Upstream PR adding `commitCycle()` call in -`executeTools` when `addToHistory` is true. +## reactor-ts-tool-cycle-turns-only + +`reactor.ts` — Tool-cycle persistence coalescing (CL-10667; supersedes +#reactor-ts-checkpoint-after-tool-cycle). A tool cycle that appends to history +now touches the store's on-disk segments only: `executeTools` calls +`contextStore.writeTurns(stateManager.getTurns())` (guarded by +`pendingCompactOutput === null` and the shared `lastWrittenTurnsRevision` +revision gate from #reactor-ts-last-written-turns-revision) and defers the +full `commitCycle` (manifest, metadata, git index + commit) to the next +reply/wait/done/suspend/shutdown terminal. Durability contract is the +segments-on-disk story: the optimized context store keeps uncommitted turn +segments in the working tree, and `load()` (the path an interrupt-rebuild +takes) reads them, so the tool exchange survives a rebuild exactly as the +old per-batch commit did. + +**Disposition:** Promotion candidate. Performance coalescing — collapses K +git commits per agentic turn to one deferred commit while preserving +rebuild-from-disk durability. +**Removal path:** Upstream PR replacing the `executeTools` checkpoint with a +writeTurns-only segments touch and deferring the cycle commit to cycle +terminals. **Re-carry:** clean three-way at `0205b07b`, zero conflicts. Moderate risk — -upstream's doom-loop fatal break fires from inside the tool cycle; re-verify -that a doom-loop break still commits (or intentionally does not commit) the -in-flight cycle. +a doom-loop abort skips the deferred terminal (previously the in-flight +batch committed); the turns still reach disk segments, so only the cycle's +manifest records and metadata staging stay uncommitted. Intentionally not +committed; re-verify after upstream doom-loop accounting changes. ## reactor-ts-skip-unchanged-history @@ -442,6 +452,17 @@ in `commitCycle`. depends on the `turnsRevision` plumbing in `state.ts`, which is itself a patch (below). +**Known pre-existing hazard (documented, file-for-later — do not fix inside +this lane):** `lastWrittenTurnsRevision` advances only after a successful +`commitCycle`. When a commit fails after `contextStore.writeTurns` already +landed, the revision stays behind the turns actually on disk. Consequences +are bounded: the next checkpoint re-serializes and re-writes the same +generation (a perf cost, never a staleness bug — a larger revision is +always written on the next success, and the reactor resets accumulators on +the failure path). A staged compaction between revisions is guarded by +`pendingCompactOutput === null` in every writeTurns site. Keep this guard +intact when touching either site. + ## reactor-ts-after-checkpoint-director-only `reactor.ts` — `afterCheckpoint` fires only for a director-requested @@ -644,7 +665,7 @@ revisit point is the next vendored sync (see `docs/VENDORING.md`). | errors-ts-classify-abort-reason | Add optional `reason` param to `classifyAbortError`, carried as `raw: { origin }` | Alexander Guy | This ledger (#errors-ts-classify-abort-reason) | Next vendored sync | | harness-ts-inactivity-on-semantic-progress | Gate the inactivity watchdog's re-arm on parsed events, not raw SSE bytes | Alexander Guy | This ledger (#harness-ts-inactivity-on-semantic-progress) | Next vendored sync | | reactor-ts-correlating-ids-leak | Wrap `tryCorrelate` in try/finally so `correlatingIds` clears on success dispatch paths | Alexander Guy | This ledger (#reactor-ts-correlating-ids-leak) | Next vendored sync | -| reactor-ts-checkpoint-after-tool-cycle | Call `commitCycle()` in `executeTools` when `addToHistory` is true | Alexander Guy | This ledger (#reactor-ts-checkpoint-after-tool-cycle) | Next vendored sync | +| reactor-ts-tool-cycle-turns-only (supersedes reactor-ts-checkpoint-after-tool-cycle) | `executeTools` writes turns to store segments only and defers the cycle commit to terminals | Alexander Guy | This ledger (#reactor-ts-tool-cycle-turns-only) | Next vendored sync | | reactor-ts-skip-unchanged-history (+ reactor-ts-last-written-turns-revision) | Skip `contextStore.writeTurns` when `getTurnsRevision()` is unchanged | Alexander Guy | This ledger (#reactor-ts-skip-unchanged-history) | Next vendored sync | | reactor-ts-compact-publish-then-memory | Persist compact blobs, stage `writeTurns`, commit, then `replaceTurns` so memory stays on the old generation until publication | Alexander Guy | This ledger (#reactor-ts-compact-publish-then-memory) | Next vendored sync | | reactor-ts-after-checkpoint-director-only | Gate `afterCheckpoint` on `hasOverride` so auto-commits do not emit it | Alexander Guy | This ledger (#reactor-ts-after-checkpoint-director-only) | Next vendored sync | diff --git a/vendor/intx-inference/src/reactor.test.ts b/vendor/intx-inference/src/reactor.test.ts index 296568a55..dc8ca4e13 100644 --- a/vendor/intx-inference/src/reactor.test.ts +++ b/vendor/intx-inference/src/reactor.test.ts @@ -2435,6 +2435,91 @@ describe("createReactor — tool runner failures", () => { ); expect(hasUserText).toBe(true); }); + + test("tool cycles write turns without a per-batch commit; the terminal commits once", async () => { + // CL-10667 coalescing: each tool batch touches the store's segments only + // (writeTurns); the full commitCycle defers to the done terminal. Counts + // the behavior a regressed per-batch commit would break. + let commits = 0; + let turnWrites = 0; + const countingStore: ContextStore = { + async load() { + return { + turns: [], + pendingOperations: [], + tokenUsage: emptyUsage(), + connectorState: null, + }; + }, + setConnectorState() { + /* noop */ + }, + async commit(options) { + commits += 1; + return { hash: "abc", message: options.message, timestamp: Date.now() }; + }, + async branch() { + /* noop */ + }, + async log() { + return []; + }, + async readAt() { + return []; + }, + async writeBlob() { + throw new Error("not implemented"); + }, + async readBlob() { + throw new Error("not implemented"); + }, + async writePrompt() { + /* noop */ + }, + async writeResponse() { + throw new Error("not implemented"); + }, + async writeManifest() { + /* noop */ + }, + async writeTurns() { + turnWrites += 1; + }, + async writeMetadata() { + /* noop */ + }, + async readManifestHistory() { + throw new Error("not implemented"); + }, + }; + + let batches = 0; + const { reactor, waitFor } = createTestReactor({ + contextStore: countingStore, + toolRunner: makeToolRunner(async (call) => ({ + callId: call.id, + content: "ok", + })), + director: directorFromTable({ + "message.received": (_e, _s, caps) => + caps.executeTools([{ id: "c1", name: "tool" }], true, true), + "tool.done": (_e, _s, caps) => { + batches += 1; + return batches === 1 + ? [caps.executeTools([{ id: "c2", name: "tool" }], true, true)] + : caps.done(); + }, + }), + }); + + reactor.start(); + reactor.deliver(makeInboundMessage()); + await waitFor("reactor.done"); + + // One segment write per tool batch; exactly one commit, at the terminal. + expect(turnWrites).toBe(2); + expect(commits).toBe(1); + }); }); // --------------------------------------------------------------------------- diff --git a/vendor/intx-inference/src/reactor.ts b/vendor/intx-inference/src/reactor.ts index 50c769e9c..2ebba0980 100644 --- a/vendor/intx-inference/src/reactor.ts +++ b/vendor/intx-inference/src/reactor.ts @@ -1142,17 +1142,26 @@ export function createReactor(config: ReactorConfig): Reactor { enqueue({ type: "tool.done", result }); } - // Checkpoint the completed tool cycle (the assistant tool_call turn plus - // its results) so an interrupt that rebuilds the agent from the store - // reloads the full exchange. Otherwise context commits only at cycle - // terminals and an uncommitted tool turn vanishes on rebuild. Guarded on - // addToHistory: only then does history end with the tool_result turn, so - // the persisted prefix is well-formed rather than an assistant turn with - // unanswered tool calls. + // CL-10667 turn-persistence coalescing: a tool cycle appends to history + // into the store's on-disk segments only (writeTurns, no index touch). + // The segments are the crash-durability story: an interrupt that rebuilds + // the agent from the store reads them through load(), and the full cycle + // commit (manifest, metadata, git index+commit) is deferred to the next + // reply/wait/done/suspend terminal. Keeps the durability the old + // per-batch commitCycle call carried while collapsing K tool cycles on an + // agentic turn to one deferred commit. // - // Locally patched — see vendor/intx-inference/PATCHES.md#reactor-ts-checkpoint-after-tool-cycle - if (addToHistory) { - await commitCycle(); + // Locally patched — see vendor/intx-inference/PATCHES.md#reactor-ts-tool-cycle-turns-only + if (addToHistory && pendingCompactOutput === null) { + const revision = stateManager?.getTurnsRevision(); + if ( + stateManager !== null && + revision !== undefined && + revision !== lastWrittenTurnsRevision + ) { + await contextStore.writeTurns(stateManager.getTurns()); + lastWrittenTurnsRevision = revision; + } } }