From 2befc71be191adc28c10fd1b274334a7391f39d7 Mon Sep 17 00:00:00 2001 From: Roomote Date: Wed, 21 Oct 2026 04:06:19 +0000 Subject: [PATCH 01/14] fix(persistence): keep ui_messages readable when a write is interrupted safeWriteJson replaced a file with two renames (target to backup, then replacement to target). A process exit between the renames left the canonical path absent, so readers saw a permanent ENOENT that no retry could repair. The replacement is now committed with a single atomic rename. Only a Windows-style EPERM (target held open by a reader) falls back to the two-step sequence, and a recovery pass under the advisory lock restores the newest orphaned backup and removes leftover temp files before any write. Task-message saves emit trace points with the task ID and process ID, the marker check and shutdown are traced, and a failed restart-persistence scenario now preserves phase results, VS Code logs, and task files for CI artifact upload. --- .github/workflows/e2e.yml | 12 ++ .gitignore | 1 + .../src/restart/scenarioWorkspace.ts | 53 +++++ apps/vscode-e2e/src/runTest.ts | 22 +- .../__tests__/persistenceTrace.spec.ts | 59 ++++++ .../__tests__/taskMessages.spec.ts | 41 +++- src/core/task-persistence/persistenceTrace.ts | 60 ++++++ .../readFileWithMissingRetry.ts | 8 +- src/core/task-persistence/taskMessages.ts | 39 ++-- src/extension.ts | 9 + src/extension/api.ts | 6 +- .../safeWriteJson.interruption.test.ts | 166 +++++++++++++++ src/utils/__tests__/safeWriteJson.test.ts | 186 +++++++++++++--- src/utils/safeWriteJson.ts | 199 +++++++++++++++--- 14 files changed, 780 insertions(+), 81 deletions(-) create mode 100644 src/core/task-persistence/__tests__/persistenceTrace.spec.ts create mode 100644 src/core/task-persistence/persistenceTrace.ts create mode 100644 src/utils/__tests__/safeWriteJson.interruption.test.ts diff --git a/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index 4b33fc678b..ba78065550 100644 --- a/.github/workflows/e2e.yml +++ b/.github/workflows/e2e.yml @@ -156,6 +156,18 @@ jobs: if: github.event_name != 'pull_request' || steps.e2e-marker.outputs.cache-hit != 'true' run: TEST_FILE=restart-persistence.test USE_MOCK=true xvfb-run -a pnpm --filter @roo-code/vscode-e2e exec node ./out/runTest.js + - name: Upload restart-persistence failure artifacts + # runTest.js preserves a failed scenario workspace (phase results, + # VS Code logs, task files) under apps/vscode-e2e/test-failures/ + # instead of deleting it, so the interrupted-write state from + # issue #2130-style failures stays inspectable. + if: failure() + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 + with: + name: restart-persistence-failure + path: apps/vscode-e2e/test-failures/ + if-no-files-found: ignore + - name: Explain skipped mocked E2E pass marker if: steps.e2e-marker.outputs.cache-hit != 'true' && steps.run-e2e.outcome == 'success' && steps.vscode-fallback.outputs.used == 'true' run: echo "Skipping mocked E2E pass marker because tests ran against a stale cached VS Code binary (VS Code download endpoints unreachable)." diff --git a/.gitignore b/.gitignore index 3961778d5e..a6ad55ed8a 100644 --- a/.gitignore +++ b/.gitignore @@ -27,6 +27,7 @@ AGENTS.local.md .vscode-test/ apps/vscode-e2e/playwright-report-electron/ apps/vscode-e2e/test-results-electron/ +apps/vscode-e2e/test-failures/ # Docs docs/_site/ diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts index 9ce49deaf0..b8b768ef31 100644 --- a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts @@ -56,3 +56,56 @@ export async function removeScenarioWorkspace(scenarioWorkspace: ScenarioWorkspa await fs.rm(root, { recursive: true, force: true }) } + +const FAILURE_ARTIFACTS_DIR = "test-failures" + +/** + * Copies the diagnosable parts of a failed scenario workspace into a stable + * directory inside the checkout, then removes the temporary scenario root. + * CI uploads that directory as a run artifact, so the failure that used to be + * deleted in the cleanup path stays inspectable: phase results, VS Code logs, + * and the extension's global storage with the task files. + * + * The directory is keyed by the unique scenario root name and cleared before + * copying, so retried runs cannot mix artifacts from different failures. + */ +export async function preserveScenarioWorkspace(scenarioWorkspace: ScenarioWorkspace): Promise { + const destinationRoot = path.resolve( + __dirname, + "../../", + FAILURE_ARTIFACTS_DIR, + path.basename(scenarioWorkspace.root), + ) + await fs.rm(destinationRoot, { recursive: true, force: true }) + await fs.mkdir(destinationRoot, { recursive: true }) + + const selections: Array<{ label: string; source: string; destination: string }> = [ + { + label: "phase results", + source: scenarioWorkspace.results, + destination: path.join(destinationRoot, "phase-results"), + }, + { + label: "VS Code logs", + source: path.join(scenarioWorkspace.userData, "logs"), + destination: path.join(destinationRoot, "vscode-logs"), + }, + { + label: "task files", + source: path.join(scenarioWorkspace.userData, "User", "globalStorage"), + destination: path.join(destinationRoot, "global-storage"), + }, + ] + + for (const selection of selections) { + try { + await fs.cp(selection.source, selection.destination, { recursive: true, force: true }) + } catch (error) { + // A missing subdirectory must not hide the other artifacts. + console.error(`Failed to preserve ${selection.label} from ${selection.source}:`, error) + } + } + + await removeScenarioWorkspace(scenarioWorkspace) + return destinationRoot +} diff --git a/apps/vscode-e2e/src/runTest.ts b/apps/vscode-e2e/src/runTest.ts index 88c687bc76..f24f37d388 100644 --- a/apps/vscode-e2e/src/runTest.ts +++ b/apps/vscode-e2e/src/runTest.ts @@ -21,7 +21,11 @@ import { addSearchFilesResultFixtures } from "./fixtures/search-files" import { addSubtaskFixtures } from "./fixtures/subtasks" import { addUseMcpToolResultFixtures } from "./fixtures/use-mcp-tool" import { addWriteToFileResultFixtures } from "./fixtures/write-to-file" -import { createScenarioWorkspace, removeScenarioWorkspace } from "./restart/scenarioWorkspace" +import { + createScenarioWorkspace, + preserveScenarioWorkspace, + removeScenarioWorkspace, +} from "./restart/scenarioWorkspace" import { runRestartScenario } from "./restart/vscodeCoordinator" function getCliFlagValue(flag: string) { @@ -95,6 +99,7 @@ async function main() { let testWorkspace: string | undefined let scenarioWorkspace: Awaited> | undefined + let runFailed = false try { // Create a temporary workspace folder for regular tests. Restart scenarios own @@ -218,6 +223,7 @@ async function main() { }) } } catch (error) { + runFailed = true console.error("Failed to run tests", error) process.exitCode = 1 } finally { @@ -225,7 +231,19 @@ async function main() { await fs.rm(testWorkspace, { recursive: true, force: true }) } if (scenarioWorkspace) { - await removeScenarioWorkspace(scenarioWorkspace) + // A failed restart scenario must stay inspectable: the phase + // results, VS Code logs, and task files are copied to a stable + // directory for CI artifact upload before the temp root goes away. + if (runFailed) { + try { + const preservedAt = await preserveScenarioWorkspace(scenarioWorkspace) + console.error(`Restart scenario workspace preserved for failure inspection: ${preservedAt}`) + } catch (preserveError) { + console.error("Failed to preserve the restart scenario workspace:", preserveError) + } + } else { + await removeScenarioWorkspace(scenarioWorkspace) + } } await mock?.stop() } diff --git a/src/core/task-persistence/__tests__/persistenceTrace.spec.ts b/src/core/task-persistence/__tests__/persistenceTrace.spec.ts new file mode 100644 index 0000000000..c4a58afce4 --- /dev/null +++ b/src/core/task-persistence/__tests__/persistenceTrace.spec.ts @@ -0,0 +1,59 @@ +import { describe, it, expect, vi, afterEach } from "vitest" + +import { setPersistenceTraceSink, tracePersistenceEvent } from "../persistenceTrace" + +function parseTraceLine(line: string): Record { + return JSON.parse(line.replace("[persistence-trace] ", "")) as Record +} + +describe("persistenceTrace", () => { + afterEach(() => { + setPersistenceTraceSink(undefined) + vi.restoreAllMocks() + }) + + it("emits a JSON line with the timestamp, process ID, stage, and fields to the sink", () => { + const lines: string[] = [] + setPersistenceTraceSink((line) => lines.push(line)) + + tracePersistenceEvent("ui-messages-write-start", { taskId: "task-1", filePath: "/tmp/ui_messages.json" }) + + expect(lines).toHaveLength(1) + const event = parseTraceLine(lines[0]) + expect(event.stage).toBe("ui-messages-write-start") + expect(event.taskId).toBe("task-1") + expect(event.pid).toBe(process.pid) + expect(typeof event.ts).toBe("string") + expect(event.filePath).toBe("/tmp/ui_messages.json") + }) + + it("marks the marker-check result", () => { + const lines: string[] = [] + setPersistenceTraceSink((line) => lines.push(line)) + + tracePersistenceEvent("ui-messages-marker-check", { taskId: "task-2", result: "match" }) + + const event = parseTraceLine(lines[0]) + expect(event.stage).toBe("ui-messages-marker-check") + expect(event.result).toBe("match") + }) + + it("falls back to the console when no sink is installed", () => { + const consoleSpy = vi.spyOn(console, "log").mockImplementation(() => {}) + + tracePersistenceEvent("shutdown") + + expect(consoleSpy).toHaveBeenCalledTimes(1) + const line = String(consoleSpy.mock.calls[0]?.[0]) + expect(line).toContain("[persistence-trace]") + expect(parseTraceLine(line).stage).toBe("shutdown") + }) + + it("never lets a failing sink break the caller", () => { + setPersistenceTraceSink(() => { + throw new Error("sink failed") + }) + + expect(() => tracePersistenceEvent("ui-messages-marker-check", { result: "match" })).not.toThrow() + }) +}) diff --git a/src/core/task-persistence/__tests__/taskMessages.spec.ts b/src/core/task-persistence/__tests__/taskMessages.spec.ts index 6b968fe96c..5917997931 100644 --- a/src/core/task-persistence/__tests__/taskMessages.spec.ts +++ b/src/core/task-persistence/__tests__/taskMessages.spec.ts @@ -21,6 +21,7 @@ vi.mock("../../../utils/safeWriteJson", () => ({ // Import after mocks import { saveTaskMessages, readTaskMessages } from "../taskMessages" import { formatErrorDetail } from "../readFileWithMissingRetry" +import { setPersistenceTraceSink } from "../persistenceTrace" let tmpBaseDir: string @@ -35,6 +36,7 @@ beforeEach(async () => { afterEach(() => { vi.useRealTimers() vi.restoreAllMocks() + setPersistenceTraceSink(undefined) }) describe("taskMessages.saveTaskMessages", () => { @@ -63,7 +65,11 @@ describe("taskMessages.saveTaskMessages", () => { expect(hoisted.safeWriteJsonMock).toHaveBeenCalledTimes(1) const [, persisted] = hoisted.safeWriteJsonMock.mock.calls[0] expect(persisted).toEqual(messages) - expect(hoisted.safeWriteJsonMock.mock.calls[0][2]).toBeUndefined() + const options = hoisted.safeWriteJsonMock.mock.calls[0][2] as { merge?: unknown; trace?: unknown } | undefined + expect(options?.merge).toBeUndefined() + // The trace callback is always installed so restart logs can follow + // the write stages. + expect(options?.trace).toBeTypeOf("function") }) it("persists messages without modification when no metadata", async () => { @@ -101,6 +107,39 @@ describe("taskMessages.saveTaskMessages", () => { ]) }) + it("emits persistence trace events with the task ID for the write stages", async () => { + const traceLines: string[] = [] + hoisted.safeWriteJsonMock.mockImplementationOnce(async (_path, _data, options) => { + for (const stage of ["recover", "write-start", "backup-rename", "replacement-rename", "write-complete"]) { + options.trace({ stage, detail: stage === "backup-rename" ? "eperm-fallback" : undefined }) + } + }) + setPersistenceTraceSink((line) => traceLines.push(line)) + + await saveTaskMessages({ + messages: [{ ts: 1, type: "say", say: "text", text: "traced" }], + taskId: "task-trace", + globalStoragePath: tmpBaseDir, + }) + + const events = traceLines.map( + (line) => JSON.parse(line.replace("[persistence-trace] ", "")) as Record, + ) + expect(events.map((event) => event.stage)).toEqual([ + "ui-messages-recovery", + "ui-messages-write-start", + "ui-messages-backup-rename", + "ui-messages-replacement-rename", + "ui-messages-write-complete", + ]) + for (const event of events) { + expect(event.taskId).toBe("task-trace") + expect(event.pid).toBe(process.pid) + } + const backupRename = events.find((event) => event.stage === "ui-messages-backup-rename") + expect(backupRename?.detail).toBe("eperm-fallback") + }) + it("propagates a forced write failure without swallowing or replacing it", async () => { // Fault injection: simulate an interrupted/failed final write (e.g. the // extension host quitting mid-save or the disk refusing the write). The diff --git a/src/core/task-persistence/persistenceTrace.ts b/src/core/task-persistence/persistenceTrace.ts new file mode 100644 index 0000000000..06b85716e8 --- /dev/null +++ b/src/core/task-persistence/persistenceTrace.ts @@ -0,0 +1,60 @@ +/** + * Structured trace points for task-persistence file writes and shutdown. + * + * The restart-persistence investigation in issue #2130 could not tell which + * writer touched ui_messages.json or when, because nothing logged the + * replacement-protocol steps. These trace lines record the write stages, the + * marker check, and shutdown with the task ID and the process ID, so CI logs + * and extension logs can order writer activity across a restart. + * + * The default sink is the console. Extension activation installs a sink that + * also mirrors every line into the extension output channel; tests can + * install their own sink to capture events. Tracing must never break + * persistence, so sink failures are swallowed. + */ + +export type PersistenceTraceStage = + | "ui-messages-recovery" + | "ui-messages-write-start" + | "ui-messages-backup-rename" + | "ui-messages-replacement-rename" + | "ui-messages-write-complete" + | "ui-messages-marker-check" + | "shutdown" + +export type PersistenceTraceFields = { + taskId?: string + filePath?: string + result?: string + detail?: string +} + +type PersistenceTraceSink = (line: string) => void + +let traceSink: PersistenceTraceSink | undefined + +/** + * Installs the sink used for every subsequent trace event. Pass undefined to + * restore the default console sink. + */ +export function setPersistenceTraceSink(sink: PersistenceTraceSink | undefined): void { + traceSink = sink +} + +export function tracePersistenceEvent(stage: PersistenceTraceStage, fields: PersistenceTraceFields = {}): void { + const line = `[persistence-trace] ${JSON.stringify({ + ts: new Date().toISOString(), + pid: process.pid, + stage, + ...fields, + })}` + try { + if (traceSink) { + traceSink(line) + } else { + console.log(line) + } + } catch { + // A failing sink must never break the write, read, or shutdown path. + } +} diff --git a/src/core/task-persistence/readFileWithMissingRetry.ts b/src/core/task-persistence/readFileWithMissingRetry.ts index 1036049470..67db76d0d0 100644 --- a/src/core/task-persistence/readFileWithMissingRetry.ts +++ b/src/core/task-persistence/readFileWithMissingRetry.ts @@ -1,8 +1,10 @@ import * as fs from "fs/promises" -// safeWriteJson replaces a file in two renames (target to backup, new file to -// target) because a single rename over an open file fails with EPERM on -// Windows. A reader can see ENOENT between the two renames, so retry once. +// safeWriteJson commits a replacement with a single atomic rename. Only the +// Windows EPERM fallback replaces a file in two renames (target to backup, +// new file to target), because a single rename over an open file fails with +// EPERM on Windows. A reader can see ENOENT between those two renames, so +// retry once. const READ_RETRY_MIN_MS = 1 const READ_RETRY_MAX_MS = 10 const READ_RETRY_RANGE_MS = READ_RETRY_MAX_MS - READ_RETRY_MIN_MS + 1 diff --git a/src/core/task-persistence/taskMessages.ts b/src/core/task-persistence/taskMessages.ts index b67ad2b7f8..bb89bbf4f2 100644 --- a/src/core/task-persistence/taskMessages.ts +++ b/src/core/task-persistence/taskMessages.ts @@ -2,11 +2,20 @@ import * as path from "path" import type { ClineMessage } from "@roo-code/types" -import { safeWriteJson } from "../../utils/safeWriteJson" +import { safeWriteJson, type SafeWriteJsonTraceStage } from "../../utils/safeWriteJson" import { GlobalFileNames } from "../../shared/globalFileNames" import { getTaskDirectoryPath } from "../../utils/storage" import { ensureMessageIdentifiers, mergeClineMessageSnapshots } from "./mergeMessageSnapshots" import { formatErrorDetail, getErrorCode, readFileWithMissingRetry } from "./readFileWithMissingRetry" +import { tracePersistenceEvent, type PersistenceTraceStage } from "./persistenceTrace" + +const uiMessagesTraceStages: Record = { + recover: "ui-messages-recovery", + "write-start": "ui-messages-write-start", + "backup-rename": "ui-messages-backup-rename", + "replacement-rename": "ui-messages-replacement-rename", + "write-complete": "ui-messages-write-complete", +} export type TaskMessagesReadErrorKind = "not_found" | "invalid" | "io_error" @@ -83,17 +92,21 @@ export async function saveTaskMessages({ const taskDir = await getTaskDirectoryPath(globalStoragePath, taskId) const filePath = path.join(taskDir, GlobalFileNames.uiMessages) let savedMessages = messages - await safeWriteJson( - filePath, - messages, - merge - ? { - merge: (existing, incoming) => { - savedMessages = mergeClineMessageSnapshots(existing, incoming) as ClineMessage[] - return savedMessages - }, - } - : undefined, - ) + await safeWriteJson(filePath, messages, { + ...(merge && { + merge: (existing, incoming) => { + savedMessages = mergeClineMessageSnapshots(existing, incoming) as ClineMessage[] + return savedMessages + }, + }), + // Trace the replacement-protocol stages with the task ID so restart + // logs can order UI-message writer activity across processes. + trace: (event) => + tracePersistenceEvent(uiMessagesTraceStages[event.stage], { + taskId, + filePath, + detail: event.detail, + }), + }) return savedMessages } diff --git a/src/extension.ts b/src/extension.ts index 6ce42aacd5..e6dce2f668 100644 --- a/src/extension.ts +++ b/src/extension.ts @@ -27,6 +27,7 @@ import { initializeNetworkProxy } from "./utils/networkProxy" import { Package } from "./shared/package" import { formatLanguage } from "./shared/language" import { ContextProxy } from "./core/config/ContextProxy" +import { setPersistenceTraceSink, tracePersistenceEvent } from "./core/task-persistence/persistenceTrace" import { ClineProvider } from "./core/webview/ClineProvider" import { registerCopilotModelBroadcast } from "./services/language-models/copilotModelBroadcast" import { ClineProviderFactory } from "./core/webview/ClineProviderFactory" @@ -125,6 +126,13 @@ export async function activate(context: vscode.ExtensionContext) { extensionContext = context outputChannel = vscode.window.createOutputChannel(Package.outputChannel) context.subscriptions.push(outputChannel) + // Mirror persistence trace lines (task ID + process ID) into the output + // channel and the console, so a restart-persistence investigation can + // order UI-message writer activity across extension-host restarts. + setPersistenceTraceSink((line) => { + outputChannel.appendLine(line) + console.log(line) + }) outputChannel.appendLine(`${Package.name} extension activated - ${JSON.stringify(Package)}`) // Initialize network proxy configuration early, before any network requests. @@ -402,6 +410,7 @@ export async function activate(context: vscode.ExtensionContext) { // This method is called when your extension is deactivated. export async function deactivate() { + tracePersistenceEvent("shutdown") outputChannel.appendLine(`${Package.name} extension deactivated`) if (cloudService && CloudService.hasInstance()) { diff --git a/src/extension/api.ts b/src/extension/api.ts index 3a33510346..4c808fe97f 100644 --- a/src/extension/api.ts +++ b/src/extension/api.ts @@ -33,6 +33,7 @@ import type { Mode } from "../shared/modes" import type { ClineProvider } from "../core/webview/ClineProvider" import type { ClineProviderFactory } from "../core/webview/ClineProviderFactory" import { readTaskMessages } from "../core/task-persistence/taskMessages" +import { tracePersistenceEvent } from "../core/task-persistence/persistenceTrace" import { Terminal } from "../integrations/terminal/Terminal" import { TerminalRegistry } from "../integrations/terminal/TerminalRegistry" import { getCommands } from "../services/command/commands" @@ -361,9 +362,12 @@ export class API extends EventEmitter implements RooCodeAPI { globalStoragePath: this.sidebarProvider.contextProxy.globalStorageUri.fsPath, }) } catch { + tracePersistenceEvent("ui-messages-marker-check", { taskId, result: "read-error" }) return false } - return uiMessages.some((message) => message.text?.includes(text)) + const hasText = uiMessages.some((message) => message.text?.includes(text)) + tracePersistenceEvent("ui-messages-marker-check", { taskId, result: hasText ? "match" : "no-match" }) + return hasText } public getCurrentTaskStack() { diff --git a/src/utils/__tests__/safeWriteJson.interruption.test.ts b/src/utils/__tests__/safeWriteJson.interruption.test.ts new file mode 100644 index 0000000000..9dc142941c --- /dev/null +++ b/src/utils/__tests__/safeWriteJson.interruption.test.ts @@ -0,0 +1,166 @@ +import { spawn, type ChildProcess } from "child_process" +import { createRequire } from "module" +import { fileURLToPath } from "url" +import * as fs from "fs/promises" +import * as os from "os" +import * as path from "path" + +import { safeWriteJson } from "../safeWriteJson" +import { readFileWithMissingRetry } from "../../core/task-persistence/readFileWithMissingRetry" + +const requireFromTest = createRequire(import.meta.url) +const esbuildPath = requireFromTest.resolve("esbuild") +const safeWriteJsonEntryPath = fileURLToPath(new URL("../safeWriteJson.ts", import.meta.url)) + +// The child performs a real safeWriteJson from this repository. The source is +// bundled to CommonJS at child startup, so the bundle's require("fs/promises") +// resolves to the same exports object the script patched above, and the +// patched rename is the one the writer actually calls. +const CHILD_SCRIPT = `"use strict" +const fs = require("fs") +const path = require("path") + +const targetPath = path.resolve(process.env.INTERRUPTION_TARGET_PATH) +const fsPromises = require("fs/promises") +const actualRename = fsPromises.rename + +// Fault injection: die with code 0 before the replacement lands. Any rename +// whose destination is the canonical path is the commit step, whatever +// replacement protocol the writer uses; exit before performing it. +fsPromises.rename = function interruptionRename(oldPath, newPath) { + if (path.resolve(String(newPath)) === targetPath) { + fs.writeSync(1, "EXIT_BEFORE_REPLACEMENT_RENAME\\n") + process.exit(0) + } + return actualRename.apply(fsPromises, arguments) +} + +require(process.env.ESBUILD_PATH).buildSync({ + entryPoints: [process.env.SAFE_WRITE_JSON_ENTRY], + bundle: true, + platform: "node", + format: "cjs", + target: "node22", + outfile: process.env.INTERRUPTION_BUNDLE_PATH, + logLevel: "silent", +}) + +const payload = JSON.parse(process.env.INTERRUPTION_PAYLOAD) +require(process.env.INTERRUPTION_BUNDLE_PATH) + .safeWriteJson(targetPath, payload) + .then(() => { + fs.writeSync(1, "WRITE_COMPLETED\\n") + process.exit(0) + }) + .catch((error) => { + fs.writeSync(2, "WRITE_FAILED: " + ((error && error.message) || String(error)) + "\\n") + process.exit(1) + }) +` + +async function waitForChildExit(child: ChildProcess): Promise<{ code: number | null; stdout: string; stderr: string }> { + const stdoutChunks: Buffer[] = [] + const stderrChunks: Buffer[] = [] + child.stdout?.on("data", (chunk: Buffer) => stdoutChunks.push(chunk)) + child.stderr?.on("data", (chunk: Buffer) => stderrChunks.push(chunk)) + return new Promise((resolve, reject) => { + const timeout = setTimeout(() => { + child.kill("SIGKILL") + reject(new Error("Interruption child did not exit within 20 seconds")) + }, 20_000) + child.once("error", reject) + child.once("close", (code) => { + clearTimeout(timeout) + resolve({ + code, + stdout: Buffer.concat(stdoutChunks).toString("utf8"), + stderr: Buffer.concat(stderrChunks).toString("utf8"), + }) + }) + }) +} + +describe("safeWriteJson subprocess interruption fault injection", () => { + let tempDir: string + let storageDir: string + let childDir: string + let targetPath: string + let childScriptPath: string + let childBundlePath: string + + beforeEach(async () => { + tempDir = await fs.mkdtemp(path.join(os.tmpdir(), "safe-write-interruption-")) + storageDir = path.join(tempDir, "storage") + childDir = path.join(tempDir, "child") + await fs.mkdir(storageDir) + await fs.mkdir(childDir) + targetPath = path.join(storageDir, "ui_messages.json") + childScriptPath = path.join(childDir, "interrupted-writer.cjs") + childBundlePath = path.join(childDir, "safeWriteJson.bundle.cjs") + await fs.writeFile(childScriptPath, CHILD_SCRIPT, "utf8") + }) + + afterEach(async () => { + await fs.rm(tempDir, { recursive: true, force: true }) + }) + + it.each([1, 2, 3])( + "keeps the committed file readable when the writer dies before the replacement lands (run %i)", + async (run) => { + // A previously committed write contains the restart marker. + const committed = { ui_messages: [{ ts: 1, type: "say", text: "RESTART_PERSISTENCE_MARKER" }] } + await fs.writeFile(targetPath, JSON.stringify(committed), "utf8") + + // The condition introduced by the previous fix: the committed + // content is readable before the interrupted write starts. + const before = await readFileWithMissingRetry(targetPath) + expect(before).toContain("RESTART_PERSISTENCE_MARKER") + + // A real child process writes the same path and terminates right + // before the replacement rename, mirroring the reported crash + // window between the two renames of the old protocol. + const child = spawn(process.execPath, [childScriptPath], { + env: { + ...process.env, + INTERRUPTION_TARGET_PATH: targetPath, + INTERRUPTION_PAYLOAD: JSON.stringify({ + ui_messages: [{ ts: 2, type: "say", text: `INTERRUPTED_WRITE_${run}` }], + }), + ESBUILD_PATH: esbuildPath, + SAFE_WRITE_JSON_ENTRY: safeWriteJsonEntryPath, + INTERRUPTION_BUNDLE_PATH: childBundlePath, + }, + stdio: ["ignore", "pipe", "pipe"], + }) + const exit = await waitForChildExit(child) + + expect(exit.stdout).toContain("EXIT_BEFORE_REPLACEMENT_RENAME") + expect(exit.stdout).not.toContain("WRITE_COMPLETED") + expect(exit.stderr).not.toContain("WRITE_FAILED") + expect(exit.code).toBe(0) + + // The writer terminated before the replacement rename, so the + // canonical path must still hold the last committed content. This + // is the permanent-ENOENT regression: with the old two-rename + // protocol the committed target was already renamed away, and no + // read retry could bring it back. + const after = JSON.parse(await readFileWithMissingRetry(targetPath)) + expect(after).toEqual(committed) + + // Restart recovery: remove the advisory lock file orphaned by the + // dead writer (proper-lockfile would only treat it as stale after + // 31 seconds), then a fresh write must succeed and consume the + // interrupted write's leftovers. + await fs.rm(`${targetPath}.lock`, { force: true }) + const recovered = { ui_messages: [{ ts: 3, type: "say", text: "RECOVERED_AFTER_RESTART" }] } + await safeWriteJson(targetPath, recovered) + + expect(JSON.parse(await readFileWithMissingRetry(targetPath))).toEqual(recovered) + const leftovers = (await fs.readdir(storageDir)).filter( + (entry) => entry.includes(".new_") || entry.includes(".bak_"), + ) + expect(leftovers).toEqual([]) + }, + 30_000, + ) +}) diff --git a/src/utils/__tests__/safeWriteJson.test.ts b/src/utils/__tests__/safeWriteJson.test.ts index 0ebdea281d..3bb22da3f1 100644 --- a/src/utils/__tests__/safeWriteJson.test.ts +++ b/src/utils/__tests__/safeWriteJson.test.ts @@ -158,26 +158,33 @@ describe("safeWriteJson", () => { expect(content).toEqual({ initial: "content" }) }) - test("should handle failure when renaming filePath to tempBackupFilePath (filePath exists)", async () => { - const initialData = { message: "Initial content, should remain" } - const newData = { message: "New content, should not be written" } + test("should fall back to the two-step replacement when the commit rename fails with EPERM", async () => { + const initialData = { message: "Initial content" } + const newData = { message: "Windows-style EPERM replacement" } // Overwrite the pre-created file with specific initial data await fsPromisesActuals.writeFile!(currentTestFilePath, JSON.stringify(initialData)) // fs.rename is already vi.fn() — use vi.mocked to avoid double-wrapping via vi.spyOn + // First call: the single-rename commit fails with the Windows-style EPERM + // (a reader holds the target open). The fallback then renames the target + // to a backup and the replacement into place, using real renames. vi.mocked(fs.rename).mockImplementationOnce(async () => { - throw new Error("Rename to backup failed") + throw Object.assign(new Error("EPERM: operation not permitted"), { code: "EPERM" }) }) - await expect(safeWriteJson(currentTestFilePath, newData)).rejects.toThrow("Rename to backup failed") + await safeWriteJson(currentTestFilePath, newData) - // Verify the original file still exists with initial content + // Verify the new content was committed by the fallback const content = await readFileContent(currentTestFilePath) - expect(content).toEqual(initialData) + expect(content).toEqual(newData) + + // Verify the fallback backup was cleaned up + const leftovers = (await fs.readdir(tempDir)).filter((entry) => entry.includes(".bak_")) + expect(leftovers).toEqual([]) }) - test("should handle failure when renaming tempNewFilePath to filePath (filePath exists, backup succeeded)", async () => { + test("should restore the committed file when the EPERM fallback's replacement rename fails", async () => { const initialData = { message: "Initial content, should be restored" } const newData = { message: "New content" } @@ -191,20 +198,21 @@ describe("safeWriteJson", () => { vi.mocked(fs.rename).mockImplementation(async (oldPath, newPath) => { renameCallCount++ if (renameCallCount === 1) { - // First call: filePath -> tempBackupFilePath (should succeed) - return fsPromisesActuals.rename!(oldPath, newPath) + // First call: the single-rename commit fails with EPERM, which + // triggers the two-step fallback. + throw Object.assign(new Error("EPERM: operation not permitted"), { code: "EPERM" }) } else if (renameCallCount === 2) { - // Second call: tempNewFilePath -> filePath (should fail) - throw new Error("Rename from temp to final failed") - } else if (renameCallCount === 3) { - // Third call: tempBackupFilePath -> filePath (rollback, should succeed) + // Second call: filePath -> tempBackupFilePath (fallback backup, succeeds) return fsPromisesActuals.rename!(oldPath, newPath) + } else if (renameCallCount === 3) { + // Third call: tempNewFilePath -> filePath (fallback replacement, fails) + throw new Error("Fallback replacement rename failed") } - // Default: use original implementation + // Fourth call: tempBackupFilePath -> filePath (rollback, succeeds) return fsPromisesActuals.rename!(oldPath, newPath) }) - await expect(safeWriteJson(currentTestFilePath, newData)).rejects.toThrow("Rename from temp to final failed") + await expect(safeWriteJson(currentTestFilePath, newData)).rejects.toThrow("Fallback replacement rename failed") // Verify the file was restored to initial content const content = await readFileContent(currentTestFilePath) @@ -292,13 +300,18 @@ describe("safeWriteJson", () => { expect(content).toEqual(data) }) - test("should handle failure when deleting tempBackupFilePath (filePath exists, all renames succeed)", async () => { + test("should handle failure when deleting tempBackupFilePath (EPERM fallback, all renames succeed)", async () => { const initialData = { message: "Initial content" } const newData = { message: "Successfully written new content" } // Overwrite the pre-created file with specific initial data await fsPromisesActuals.writeFile!(currentTestFilePath, JSON.stringify(initialData)) + // Force the two-step fallback so a backup exists, then let its deletion fail + vi.mocked(fs.rename).mockImplementationOnce(async () => { + throw Object.assign(new Error("EPERM: operation not permitted"), { code: "EPERM" }) + }) + // fs.unlink is already vi.fn() — use vi.mocked to avoid double-wrapping via vi.spyOn vi.mocked(fs.unlink).mockImplementationOnce(async () => { throw new Error("Failed to delete backup file") @@ -320,6 +333,11 @@ describe("safeWriteJson", () => { await fsPromisesActuals.writeFile!(currentTestFilePath, JSON.stringify(initialData)) + // Force the two-step fallback so a backup exists, then fail its deletion + vi.mocked(fs.rename).mockImplementationOnce(async () => { + throw Object.assign(new Error("EPERM: operation not permitted"), { code: "EPERM" }) + }) + // fs.unlink is already vi.fn() — use vi.mocked to avoid double-wrapping via vi.spyOn vi.mocked(fs.unlink).mockImplementation(async (filePath: any) => { if (filePath.toString().includes(".bak_")) { @@ -338,7 +356,7 @@ describe("safeWriteJson", () => { }) // The expected error message might need to change if the mock behaves differently. - test("should handle failure when renaming tempNewFilePath to filePath (filePath initially exists)", async () => { + test("should keep the committed file when the commit rename fails with a non-EPERM error", async () => { // currentTestFilePath exists due to beforeEach. const initialData = { message: "Initial content" } const newData = { message: "New content" } @@ -346,20 +364,14 @@ describe("safeWriteJson", () => { await fsPromisesActuals.writeFile!(currentTestFilePath, JSON.stringify(initialData)) // fs.rename is already vi.fn() — use vi.mocked to avoid double-wrapping via vi.spyOn - let renameCallCount = 0 - vi.mocked(fs.rename).mockImplementation(async (oldPath, newPath) => { - renameCallCount++ - if (renameCallCount === 2) { - // Second call: tempNewFilePath -> filePath (should fail) - throw new Error("Rename failed") - } - // For all other calls, use the original implementation - return fsPromisesActuals.rename!(oldPath, newPath) + vi.mocked(fs.rename).mockImplementationOnce(async () => { + throw new Error("Rename failed") }) await expect(safeWriteJson(currentTestFilePath, newData)).rejects.toThrow("Rename failed") - // The file should be restored to its initial content + // No backup is made on the single-rename path, and the committed file + // keeps its previous content const content = await readFileContent(currentTestFilePath) expect(content).toEqual(initialData) }) @@ -447,18 +459,26 @@ describe("safeWriteJson", () => { let renameCallCount = 0 vi.mocked(fs.rename).mockImplementation(async (oldPath, newPath) => { renameCallCount++ - if (renameCallCount === 2) { - // Second call: tempNewFilePath -> filePath (fail) - throw new Error("Primary rename failed") + if (renameCallCount === 1) { + // First call: the single-rename commit fails with EPERM, which + // triggers the two-step fallback. + throw Object.assign(new Error("Primary rename failed"), { code: "EPERM" }) + } else if (renameCallCount === 2) { + // Second call: filePath -> tempBackupFilePath (fallback backup, succeeds) + return fsPromisesActuals.rename!(oldPath, newPath) } else if (renameCallCount === 3) { - // Third call: tempBackupFilePath -> filePath (rollback, also fail) + // Third call: tempNewFilePath -> filePath (fallback replacement, fails) + throw new Error("Fallback replacement rename failed") + } else if (renameCallCount === 4) { + // Fourth call: tempBackupFilePath -> filePath (rollback, also fails) throw new Error("Rollback rename failed") } return fsPromisesActuals.rename!(oldPath, newPath) }) - // Should throw the original error, not the rollback error - await expect(safeWriteJson(currentTestFilePath, newData)).rejects.toThrow("Primary rename failed") + // The fallback's replacement error rejects the write; the rollback error + // is only logged. + await expect(safeWriteJson(currentTestFilePath, newData)).rejects.toThrow("Fallback replacement rename failed") // Verify console.error was called for the rollback failure expect(consoleErrorSpy).toHaveBeenCalledWith( @@ -542,4 +562,102 @@ describe("safeWriteJson", () => { const content = await readFileContent(currentTestFilePath) expect(content).toEqual({ c: 3 }) }) + + // Interrupted-write recovery tests + test("should restore an orphaned backup when the canonical path is missing after an interrupted write", async () => { + const committedData = { message: "Committed before the interruption" } + + // Simulate the crash state of the two-step replacement: the target was + // renamed to a backup, the replacement never landed, and the + // replacement temp file was left behind. The canonical path is absent. + await fsPromisesActuals.unlink!(currentTestFilePath) + const backupPath = path.join(tempDir, `.${path.basename(currentTestFilePath)}.bak_1_abc.tmp`) + const orphanedNewPath = path.join(tempDir, `.${path.basename(currentTestFilePath)}.new_1_def.tmp`) + await fsPromisesActuals.writeFile!(backupPath, JSON.stringify(committedData)) + await fsPromisesActuals.writeFile!(orphanedNewPath, "{}") + + // A merge write must observe the restored committed content, not null. + const incoming = { message: "New content" } + let mergedWith: unknown + await safeWriteJson(currentTestFilePath, incoming, { + merge: (existing) => { + mergedWith = existing + return incoming + }, + }) + + expect(mergedWith).toEqual(committedData) + const content = await readFileContent(currentTestFilePath) + expect(content).toEqual(incoming) + + // The restored backup is consumed and the leftover replacement file is + // garbage collected. + const leftovers = (await fs.readdir(tempDir)).filter( + (entry) => entry.includes(".new_") || entry.includes(".bak_"), + ) + expect(leftovers).toEqual([]) + }) + + test("should garbage collect orphaned replacement files when the canonical path exists", async () => { + const initialData = { message: "Initial content" } + + await fsPromisesActuals.writeFile!(currentTestFilePath, JSON.stringify(initialData)) + + // Leftovers from an interrupted write whose commit rename never ran. + const backupPath = path.join(tempDir, `.${path.basename(currentTestFilePath)}.bak_1_abc.tmp`) + const orphanedNewPath = path.join(tempDir, `.${path.basename(currentTestFilePath)}.new_1_def.tmp`) + await fsPromisesActuals.writeFile!(backupPath, JSON.stringify({ message: "stale backup" })) + await fsPromisesActuals.writeFile!(orphanedNewPath, "{}") + + const newData = { message: "New content" } + await safeWriteJson(currentTestFilePath, newData) + + const content = await readFileContent(currentTestFilePath) + expect(content).toEqual(newData) + + const leftovers = (await fs.readdir(tempDir)).filter( + (entry) => entry.includes(".new_") || entry.includes(".bak_"), + ) + expect(leftovers).toEqual([]) + }) + + test("should report replacement-protocol trace events when a trace callback is provided", async () => { + const traceEvents: Array<{ stage: string; detail?: string }> = [] + const newData = { message: "traced write" } + + await safeWriteJson(currentTestFilePath, newData, { + trace: (event) => traceEvents.push(event), + }) + + expect(traceEvents.map((event) => event.stage)).toEqual(["write-start", "replacement-rename", "write-complete"]) + const content = await readFileContent(currentTestFilePath) + expect(content).toEqual(newData) + }) + + test("should trace the EPERM fallback backup rename", async () => { + const traceEvents: Array<{ stage: string; detail?: string }> = [] + const initialData = { message: "Initial content" } + const newData = { message: "Traced fallback write" } + + await fsPromisesActuals.writeFile!(currentTestFilePath, JSON.stringify(initialData)) + + vi.mocked(fs.rename).mockImplementationOnce(async () => { + throw Object.assign(new Error("EPERM: operation not permitted"), { code: "EPERM" }) + }) + + await safeWriteJson(currentTestFilePath, newData, { + trace: (event) => traceEvents.push(event), + }) + + expect(traceEvents.map((event) => event.stage)).toEqual([ + "write-start", + "replacement-rename", + "backup-rename", + "replacement-rename", + "write-complete", + ]) + expect(traceEvents.find((event) => event.stage === "backup-rename")?.detail).toBe("eperm-fallback") + const content = await readFileContent(currentTestFilePath) + expect(content).toEqual(newData) + }) }) diff --git a/src/utils/safeWriteJson.ts b/src/utils/safeWriteJson.ts index 7da68b2a7a..b7274125bf 100644 --- a/src/utils/safeWriteJson.ts +++ b/src/utils/safeWriteJson.ts @@ -5,6 +5,17 @@ import { JsonStreamStringify } from "json-stream-stringify" import { acquireFileLock } from "./fileLock" +/** + * Stages reported through the optional `trace` callback. They mark the + * replacement-protocol steps that matter when diagnosing interrupted or + * failing writes: the recovery pass, the temp-file write, the backup rename + * of the EPERM fallback, the commit rename, and completion. + */ +export type SafeWriteJsonTraceStage = + "recover" | "write-start" | "backup-rename" | "replacement-rename" | "write-complete" + +export type SafeWriteJsonTrace = (event: { stage: SafeWriteJsonTraceStage; detail?: string }) => void + /** * Options for safeWriteJson function */ @@ -26,14 +37,118 @@ export interface SafeWriteJsonOptions { * cannot be parsed. */ merge?: (existing: unknown, incoming: unknown) => unknown + + /** + * When provided, receives one event per replacement-protocol step (see + * SafeWriteJsonTraceStage). Callers such as the task-message save use it + * to emit diagnostic trace lines; it never influences the write itself. + */ + trace?: SafeWriteJsonTrace +} + +function createTempFilePath(absoluteFilePath: string, kind: "new" | "bak"): string { + return path.join( + path.dirname(absoluteFilePath), + `.${path.basename(absoluteFilePath)}.${kind}_${Date.now()}_${Math.random().toString(36).substring(2)}.tmp`, + ) +} + +function getTempFilePrefix(absoluteFilePath: string, kind: "new" | "bak"): string { + return `.${path.basename(absoluteFilePath)}.${kind}_` +} + +/** + * Heals the canonical path after an interrupted previous write. Must run + * under the advisory lock and before any data is read or written: temp and + * backup files are only ever created while that lock is held, so anything + * matching their name patterns belongs to a writer that can no longer + * commit or clean it up (a crashed process, or a stale lock that was + * stolen). + * + * The two-step replacement used by the EPERM fallback (and by versions + * before the single-rename commit) can be interrupted after the target was + * renamed to its backup but before the replacement landed. A process exit + * at that point leaves the canonical path absent, which readers see as a + * permanent ENOENT that no retry can repair, so the newest backup is + * restored first. Leftover replacement and backup files are garbage + * collected afterwards. + * + * @returns Whether leftover files were found, and the backup path that was + * restored, if any. + */ +async function recoverInterruptedReplacement( + absoluteFilePath: string, +): Promise<{ foundLeftovers: boolean; restoredFrom: string | null }> { + const dirPath = path.dirname(absoluteFilePath) + const newPrefix = getTempFilePrefix(absoluteFilePath, "new") + const backupPrefix = getTempFilePrefix(absoluteFilePath, "bak") + + let entries: string[] + try { + entries = await fs.readdir(dirPath) + } catch { + // The directory is unreadable or was removed; the write itself + // reports that error below. + return { foundLeftovers: false, restoredFrom: null } + } + + const orphanedPaths = entries + .filter((entry) => entry.endsWith(".tmp") && (entry.startsWith(newPrefix) || entry.startsWith(backupPrefix))) + .map((entry) => path.join(dirPath, entry)) + + if (orphanedPaths.length === 0) { + return { foundLeftovers: false, restoredFrom: null } + } + + let restoredFrom: string | null = null + + try { + await fs.access(absoluteFilePath) + } catch { + // The canonical path is absent. An interrupted two-step replacement + // leaves the committed content in the newest backup, so restore it + // and keep readers on the last committed state. + const backupStats = await Promise.all( + orphanedPaths + .filter((orphanPath) => path.basename(orphanPath).startsWith(backupPrefix)) + .map(async (backupPath) => ({ backupPath, mtimeMs: (await fs.stat(backupPath)).mtimeMs })), + ) + if (backupStats.length > 0) { + backupStats.sort((a, b) => b.mtimeMs - a.mtimeMs) + const newestBackupPath = backupStats[0].backupPath + try { + await fs.rename(newestBackupPath, absoluteFilePath) + restoredFrom = newestBackupPath + } catch (restoreError) { + console.error( + `Failed to restore interrupted-write backup ${newestBackupPath} to ${absoluteFilePath}:`, + restoreError, + ) + } + } + } + + for (const orphanPath of orphanedPaths) { + if (orphanPath === restoredFrom) { + continue + } + try { + await fs.unlink(orphanPath) + } catch (cleanupError) { + console.error(`Failed to clean up interrupted-write leftover ${orphanPath}:`, cleanupError) + } + } + + return { foundLeftovers: true, restoredFrom } } /** * Safely writes JSON data to a file. * - Creates parent directories if they don't exist * - Uses 'proper-lockfile' for inter-process advisory locking to prevent concurrent writes to the same path. - * - Writes to a temporary file first. - * - If the target file exists, it's backed up before being replaced. + * - Recovers an interrupted previous write before touching the file: restores an orphaned backup when the canonical path is absent, and removes leftover temp files. + * - Writes to a temporary file first, then commits it with a single atomic rename, so the committed target stays readable through an interrupted write. + * - When a single rename over the target fails with EPERM (a reader holds the file open on Windows), falls back to backing the target up before replacing it. * - Attempts to roll back and clean up in case of errors. * - Supports pretty-printing with indentation while maintaining streaming efficiency. * @@ -76,6 +191,14 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso let actualTempBackupFilePath: string | null = null try { + // Heal any state an interrupted previous write left behind: an absent + // canonical path with an orphaned backup, or leftover replacement + // files. Runs first so a merge callback reads the restored content. + const recovery = await recoverInterruptedReplacement(absoluteFilePath) + if (recovery.foundLeftovers) { + options?.trace?.({ stage: "recover", detail: recovery.restoredFrom ?? "cleaned-leftovers" }) + } + // If a merge callback was provided, read the current file under the lock // and let the caller merge before we write. Must be inside try/finally // so a throwing merge still releases the lock. @@ -93,43 +216,46 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso data = options.merge(existing, data) } - // Step 1: Write data to a new temporary file. - actualTempNewFilePath = path.join( - path.dirname(absoluteFilePath), - `.${path.basename(absoluteFilePath)}.new_${Date.now()}_${Math.random().toString(36).substring(2)}.tmp`, - ) + // Step 1: Write data to a new temporary file and flush it to storage, + // so the replacement content is durable before it is committed. + options?.trace?.({ stage: "write-start" }) + actualTempNewFilePath = createTempFilePath(absoluteFilePath, "new") await _streamDataToFile(actualTempNewFilePath, data, options?.prettyPrint) + await _flushFileToDisk(actualTempNewFilePath) - // Step 2: Check if the target file exists. If so, rename it to a backup path. + // Step 2: Commit the replacement with a single atomic rename. The + // committed target stays in place until this rename lands, so a + // process exit before or during the commit can no longer leave the + // canonical path absent. try { - // Check for target file existence - await fs.access(absoluteFilePath) - // Target exists, create a backup path and rename. - actualTempBackupFilePath = path.join( - path.dirname(absoluteFilePath), - `.${path.basename(absoluteFilePath)}.bak_${Date.now()}_${Math.random().toString(36).substring(2)}.tmp`, - ) - await fs.rename(absoluteFilePath, actualTempBackupFilePath) - } catch (accessError: any) { - // Explicitly type accessError - if (accessError.code !== "ENOENT") { - // An error other than "file not found" occurred during access check. - throw accessError + options?.trace?.({ stage: "replacement-rename" }) + await fs.rename(actualTempNewFilePath, absoluteFilePath) + } catch (renameError: any) { + if (renameError?.code !== "EPERM") { + throw renameError } - // Target file does not exist, so no backup is made. actualTempBackupFilePath remains null. - } - // Step 3: Rename the new temporary file to the target file path. - // This is the main "commit" step. - await fs.rename(actualTempNewFilePath, absoluteFilePath) + // A single rename over a file that a reader holds open fails with + // EPERM on Windows, so fall back to the two-step replacement: + // rename the target to a backup, then the replacement into place. + // The rollback in the catch below restores the backup when the + // second rename fails, and the recovery pass at the start of the + // next write repairs a crash between the two renames. + options?.trace?.({ stage: "backup-rename", detail: "eperm-fallback" }) + actualTempBackupFilePath = createTempFilePath(absoluteFilePath, "bak") + await fs.rename(absoluteFilePath, actualTempBackupFilePath) + options?.trace?.({ stage: "replacement-rename", detail: "eperm-fallback" }) + await fs.rename(actualTempNewFilePath, absoluteFilePath) + } // If we reach here, the new file is successfully in place. // The original actualTempNewFilePath is now the main file, so we shouldn't try to clean it up as "temp". // Mark as "used" or "committed" actualTempNewFilePath = null + options?.trace?.({ stage: "write-complete" }) - // Step 4: If a backup was created, attempt to delete it. + // Step 3: If a backup was created, attempt to delete it. if (actualTempBackupFilePath) { try { await fs.unlink(actualTempBackupFilePath) @@ -230,4 +356,23 @@ async function _streamDataToFile(targetPath: string, data: any, prettyPrint = fa }) } +/** + * Flushes a fully written temp file to storage before it is committed. + * Best effort: durability against power loss is a bonus here, process-crash + * safety comes from the rename protocol itself, and a filesystem that + * refuses fsync must not block the write. + */ +async function _flushFileToDisk(targetPath: string): Promise { + try { + const handle = await fs.open(targetPath, "r") + try { + await handle.sync() + } finally { + await handle.close() + } + } catch (flushError) { + console.error(`Failed to flush ${targetPath} to storage before commit:`, flushError) + } +} + export { safeWriteJson } From 2d6979e620171bf626e4ce47a9f66435e020a012 Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Fri, 23 Oct 2026 22:29:22 +0000 Subject: [PATCH 02/14] fix(persistence): preserve committed backups and recover history on reads --- .github/workflows/e2e.yml | 1 + .../src/restart/scenarioWorkspace.ts | 12 +- .../src/restart/vscodeCoordinator.ts | 6 + .../src/suite/restart-persistence.test.ts | 50 ++++- docs/architecture/json-persistence-audit.md | 46 ++++ src/core/task-persistence/TaskHistoryStore.ts | 12 +- .../TaskHistoryStore.crossInstance.spec.ts | 3 +- .../TaskHistoryStore.realConcurrency.spec.ts | 60 ++--- .../__tests__/TaskHistoryStore.spec.ts | 3 +- .../__tests__/taskMessages.spec.ts | 3 +- src/core/task-persistence/persistenceTrace.ts | 67 +----- .../readFileWithMissingRetry.ts | 13 +- src/core/webview/ClineProvider.ts | 22 +- .../webview/__tests__/ClineProvider.spec.ts | 40 +++- src/eslint-suppressions.json | 2 +- src/extension.ts | 5 +- src/extension/api.ts | 9 +- .../safeWriteJson.interruption.test.ts | 79 ++++--- .../__tests__/safeWriteJson.recovery.test.ts | 211 ++++++++++++++++++ src/utils/persistenceTrace.ts | 64 ++++++ src/utils/safeWriteJson.ts | 148 +++++++----- 21 files changed, 643 insertions(+), 213 deletions(-) create mode 100644 docs/architecture/json-persistence-audit.md create mode 100644 src/utils/__tests__/safeWriteJson.recovery.test.ts create mode 100644 src/utils/persistenceTrace.ts diff --git a/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index ba78065550..2e3ef75824 100644 --- a/.github/workflows/e2e.yml +++ b/.github/workflows/e2e.yml @@ -165,6 +165,7 @@ jobs: uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 with: name: restart-persistence-failure + retention-days: 7 path: apps/vscode-e2e/test-failures/ if-no-files-found: ignore diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts index b8b768ef31..d184dab052 100644 --- a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts @@ -64,7 +64,7 @@ const FAILURE_ARTIFACTS_DIR = "test-failures" * directory inside the checkout, then removes the temporary scenario root. * CI uploads that directory as a run artifact, so the failure that used to be * deleted in the cleanup path stays inspectable: phase results, VS Code logs, - * and the extension's global storage with the task files. + * and the extension's task files. Global state databases are excluded. * * The directory is keyed by the unique scenario root name and cleared before * copying, so retried runs cannot mix artifacts from different failures. @@ -92,8 +92,14 @@ export async function preserveScenarioWorkspace(scenarioWorkspace: ScenarioWorks }, { label: "task files", - source: path.join(scenarioWorkspace.userData, "User", "globalStorage"), - destination: path.join(destinationRoot, "global-storage"), + source: path.join( + scenarioWorkspace.userData, + "User", + "globalStorage", + "zoocodeorganization.zoo-code", + "tasks", + ), + destination: path.join(destinationRoot, "tasks"), }, ] diff --git a/apps/vscode-e2e/src/restart/vscodeCoordinator.ts b/apps/vscode-e2e/src/restart/vscodeCoordinator.ts index 9400aaaaf4..cddab1f029 100644 --- a/apps/vscode-e2e/src/restart/vscodeCoordinator.ts +++ b/apps/vscode-e2e/src/restart/vscodeCoordinator.ts @@ -27,6 +27,12 @@ function phaseEnvironment(options: RestartCoordinatorOptions, phase: RestartPhas E2E_PHASE: phase, E2E_SCENARIO: options.scenario, E2E_RESULTS_DIR: options.workspace.results, + E2E_GLOBAL_STORAGE_PATH: path.join( + options.workspace.userData, + "User", + "globalStorage", + "zoocodeorganization.zoo-code", + ), } } diff --git a/apps/vscode-e2e/src/suite/restart-persistence.test.ts b/apps/vscode-e2e/src/suite/restart-persistence.test.ts index 0d508273e3..6068defd05 100644 --- a/apps/vscode-e2e/src/suite/restart-persistence.test.ts +++ b/apps/vscode-e2e/src/suite/restart-persistence.test.ts @@ -1,4 +1,6 @@ import * as assert from "assert" +import * as fs from "fs/promises" +import * as path from "path" import * as vscode from "vscode" import { RooCodeEventName, type RooCodeAPI } from "@roo-code/types" @@ -60,6 +62,28 @@ async function runCreate(api: RooCodeAPI): Promise { // never reads a task directory whose final write has not landed yet. const createdTaskId: string = taskId await waitFor(() => api.hasTaskUiMessageText(createdTaskId, MARKER)) + const globalStoragePath = process.env.E2E_GLOBAL_STORAGE_PATH + if (!globalStoragePath) throw new Error("E2E_GLOBAL_STORAGE_PATH is required") + // The public history API reads the cache; check the committed file + // before quitting so the fresh host has both history and messages. + await waitFor(async () => { + try { + const persisted: unknown = JSON.parse( + await fs.readFile( + path.join(globalStoragePath, "tasks", createdTaskId, "history_item.json"), + "utf8", + ), + ) + return ( + typeof persisted === "object" && + persisted !== null && + "id" in persisted && + persisted.id === createdTaskId + ) + } catch { + return false + } + }) const result: PhaseResult = { version: PHASE_RESULT_VERSION, @@ -103,7 +127,31 @@ async function runVerify(api: RooCodeAPI): Promise { const historyItem = await api.getTaskHistoryItem(taskId) assert.ok(historyItem, "Task history item should be available after restart") assert.ok(historyItem.task.includes("RESTART_PERSISTENCE_SMOKE"), "History title should persist after restart") + + // No task is running in this fresh host yet. Recreate the on-disk + // state left by an interrupted two-step replacement, then require + // public reads to recover it before resume can write anything. + const globalStoragePath = process.env.E2E_GLOBAL_STORAGE_PATH + if (!globalStoragePath) throw new Error("E2E_GLOBAL_STORAGE_PATH is required") + const taskDir = path.join(globalStoragePath, "tasks", taskId) + const interruptedFiles = [] + for (const file of ["ui_messages.json", "api_conversation_history.json"]) { + const canonical = path.join(taskDir, file) + const backup = path.join(taskDir, `.${file}.bak_restart_e2e.tmp`) + const committed = await fs.readFile(canonical, "utf8") + await fs.rename(canonical, backup) + interruptedFiles.push({ canonical, backup, committed }) + } + assert.strictEqual(await api.hasTaskUiMessageText(taskId, MARKER), true, "Read should recover the UI marker") await waitForMarkedCompletion(api, taskId) + for (const { canonical, backup, committed } of interruptedFiles) { + assert.strictEqual( + await fs.readFile(canonical, "utf8"), + committed, + "Read recovery must retain committed bytes", + ) + await assert.rejects(fs.access(backup), { code: "ENOENT" }, "Recovery should consume the backup") + } await api.resumeTask(taskId) await waitFor(() => taskMessages.some(({ type, ask }) => type === "ask" && ask === "resume_completed_task")) @@ -137,7 +185,7 @@ async function runVerify(api: RooCodeAPI): Promise { } suite("Restart persistence", () => { - test("persists completed task across a fresh extension host", async () => { + test("persists and recovers completed task history across a fresh extension host", async () => { const api = globalThis.api if (process.env.E2E_PHASE === "create") { await runCreate(api) diff --git a/docs/architecture/json-persistence-audit.md b/docs/architecture/json-persistence-audit.md new file mode 100644 index 0000000000..be86142ac1 --- /dev/null +++ b/docs/architecture/json-persistence-audit.md @@ -0,0 +1,46 @@ +# JSON persistence audit for PR #2136 + +This is a source audit of the working tree, not a claim of power-loss durability or exhaustive filesystem fault testing. There are 19 executable `safeWriteJson` calls in 10 consumer files; the earlier review's count of 11 sibling callers did not identify its counting unit. Tests, the writer declaration, and the built-in command's textual example are excluded. + +## Shared contract + +Every call acquires the canonical file's advisory lock before recovery, merge, streaming, or replacement. Recovery only interprets ENOENT as absence. A failed restore or rollback retains committed backups. No fsync or durability option remains; replacement protects against process interruption, not arbitrary power loss. Read recovery checks for a matching backup before acquiring the same lock and rechecks the filesystem under it. + +All rejected recovery attempts, including read-side lock acquisition and directory inspection failures, emit `json-recovery-failed` with the canonical path, process ID, timestamp, and error code through the shared persistence trace sink. UI-message writes additionally retain their task-specific stage callbacks. Sink exceptions cannot replace the filesystem error. This trace does not log file contents. Best-effort leftover-unlink failures still use the existing console error logging and do not reject an otherwise successful recovery. + +A fresh-looking lock left by SIGKILL still rejects a writer or a reader attempting backup recovery with ELOCKED after the configured retries. This is intentional: lock freshness cannot distinguish a dead process from a paused owner. The subprocess test verifies rejection, backup preservation, and recovery after aging the lock past `LOCK_STALE_MS` (31 seconds). It does not wait 31 real seconds or establish Windows filesystem semantics. + +## Consumer inventory + +Paths in this table are relative to `src/`. + +| Consumer | Calls | Data and semantics | Error/read behavior | +| ---------------------------------------------- | ----: | ---------------------------------------------------------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | +| `api/providers/fetchers/modelEndpointCache.ts` | 1 | Replace fetched endpoint cache | Disk reader checks existence; cache can be refetched. Writer rejection propagates to cache refresh handling. | +| `api/providers/fetchers/modelCache.ts` | 1 | Replace fetched model cache | Includes a synchronous disk reader; missing cache can be refetched. Refresh paths catch/log write failures. | +| `services/mcp/McpHub.ts` | 4 | Create global settings with a preserving merge; replace settings for updates, removal, and tool configuration | Creation preserves recovered settings. Other operations read before entering the writer's lock; their entire read-modify-write is not made atomic by this PR. | +| `services/code-index/cache-manager.ts` | 2 | Save or clear file hashes | Initialization uses VS Code filesystem reads and resets a missing cache; writes catch/log and emit telemetry. Hashes are rebuildable. | +| `core/config/importExport.ts` | 1 | Replace a user-selected settings export | Export catches/logs failures. Import reads the selected canonical file directly. | +| `core/webview/webviewMessageHandler.ts` | 1 | Initialize project MCP settings when the canonical file appears absent | Uses an existence check and blind default write. An orphaned backup can be restored and then replaced by defaults. This is a remaining initialization gap, not covered by task-message recovery tests. | +| `core/task-persistence/taskMessages.ts` | 1 | Save UI messages; optional snapshot merge | Reads use missing-file retry and backup recovery. Save failures propagate to Task, whose existing save helper catches them. Adds task-specific write traces. | +| `core/task-persistence/apiMessages.ts` | 2 | Migrate legacy history with merge; save API messages with optional merge | Current and legacy readers use recovery. Genuine absence maps to no history; other I/O failures throw. Migration removes the legacy source only after the write succeeds. | +| `core/task-persistence/TaskHistoryStore.ts` | 5 | Repair intent; legacy migration; history delta merge; authoritative replacement; conditional pending-action settlement | Deletion removes backups under the same file lock. Settlement rejects missing disk state. Store history reads and repair-intent reads still read canonical paths directly: orphaned history/intent backups are healed on writes, not on these readers. | +| `core/context-tracking/FileContextTracker.ts` | 1 | Replace task file-context metadata | Reads check canonical existence and otherwise return an empty context. Saves catch/log failures. Read-side backup healing is not provided here. | + +`ClineProvider.getTaskWithId` is an additional API-history reader, not a writer. It now uses the recovery reader. SyntaxError and ENOENT retain their previous empty-history behavior; other filesystem/recovery failures propagate. Task loading and parent reopening also use the message readers. The advisory-file-lock owners are the JSON writer/recovery and history deletion; the inspected call paths do not invoke message recovery while already holding the same file lock. Provider delegation locks and store host mutexes are distinct from that file lock. + +## Writes outside the shared protocol + +The production source scan covered `src/`, `packages/`, and `apps/cli`, excluding tests, generated output, dependencies, and fixtures. These paths do not acquire protection merely because other writes use `safeWriteJson`: + +- Task-history import copies files into a unique staging directory, validates `history_item.json`, and promotes the directory by rename. It does not rewrite existing canonical message files through the JSON writer. Its directory-level publication protocol is separate. +- TaskHistoryStore also renames repair intents into quarantine and unlinks completed intents. These are removal/quarantine operations, not JSON replacements. +- `services/marketplace/SimpleInstaller.ts` writes and removes MCP entries with direct JSON file writes to project/global MCP settings. It can share files with McpHub and is outside its advisory-lock protocol. Concurrent marketplace/McpHub updates and interruption safety need separate work. +- Qwen credential refresh writes its credentials JSON directly. The CLI's VS Code shim writes Memento and SecretStorage JSON synchronously. None of these writes gains crash recovery from this PR. +- Other direct writes found are workspace edits, generated images, YAML modes and settings migration, rule/skill installation, exported markdown, logs, shell scripts, terminal artifacts, managed-binary staging, build output, and test/coverage tooling. The scan found no additional direct production replacement of `ui_messages.json`, `api_conversation_history.json`, or `history_item.json` outside task-history import's staging protocol. + +## Validation and limits + +Focused tests cover failed recovery/rollback, filesystem errors, backup ordering, neighboring files, missing-file reads, fresh-lock rejection, stale-lock takeover, trace delivery, and history deletion. The existing real-window restart E2E additionally moves UI/API histories to orphaned backups in a fresh extension host before resume and requires public reads to restore their exact bytes. + +The E2E runner and CI workflow inspected run VS Code on Linux. That is real extension-host/window coverage, not evidence for Windows open-handle rename behavior. The Windows EPERM branch is fault-injected in unit/subprocess tests. The remaining reader and MCP-writer gaps above are explicitly outside the verified UI/API history contract. diff --git a/src/core/task-persistence/TaskHistoryStore.ts b/src/core/task-persistence/TaskHistoryStore.ts index 346d697d9a..fc9f2f5afa 100644 --- a/src/core/task-persistence/TaskHistoryStore.ts +++ b/src/core/task-persistence/TaskHistoryStore.ts @@ -8,7 +8,7 @@ import { historyItemSchema, type HistoryItem } from "@roo-code/types" import { GlobalFileNames } from "../../shared/globalFileNames" import { LOCK_STALE_MS, withFileLock } from "../../utils/fileLock" -import { safeWriteJson } from "../../utils/safeWriteJson" +import { safeWriteJson, removeJsonBackups } from "../../utils/safeWriteJson" import { getStorageBasePath } from "../../utils/storage" import { assertValidTransition, settleRejectedCreateSubtaskAction, type HistoryItemStatus } from "./taskLifecycle" import { computeHistoryDelta, DeltaRejectedError, mergeHistoryDelta } from "./taskStoreConcurrency" @@ -280,7 +280,10 @@ export class TaskHistoryStore { // Remove per-task file (best-effort) try { const filePath = await this.getTaskFilePath(taskId) - await withFileLock(filePath, (absoluteFilePath) => fs.unlink(absoluteFilePath)) + await withFileLock(filePath, async (absoluteFilePath) => { + await removeJsonBackups(absoluteFilePath) + await fs.unlink(absoluteFilePath) + }) } catch { // File may already be deleted } @@ -308,7 +311,10 @@ export class TaskHistoryStore { // Remove per-task file (best-effort) try { const filePath = await this.getTaskFilePath(taskId) - await withFileLock(filePath, (absoluteFilePath) => fs.unlink(absoluteFilePath)) + await withFileLock(filePath, async (absoluteFilePath) => { + await removeJsonBackups(absoluteFilePath) + await fs.unlink(absoluteFilePath) + }) } catch { // File may already be deleted } diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.crossInstance.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.crossInstance.spec.ts index 5b85c9b4e2..4e6a888ed7 100644 --- a/src/core/task-persistence/__tests__/TaskHistoryStore.crossInstance.spec.ts +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.crossInstance.spec.ts @@ -16,7 +16,8 @@ vi.mock("../../../utils/storage", () => ({ })) // Mock safeWriteJson to use plain fs writes but honor the merge callback. -vi.mock("../../../utils/safeWriteJson", () => ({ +vi.mock("../../../utils/safeWriteJson", async (importOriginal) => ({ + ...(await importOriginal()), safeWriteJson: vi .fn() .mockImplementation( diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.realConcurrency.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.realConcurrency.spec.ts index d35dfc49cf..cd1b43e3c1 100644 --- a/src/core/task-persistence/__tests__/TaskHistoryStore.realConcurrency.spec.ts +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.realConcurrency.spec.ts @@ -292,32 +292,40 @@ describe("TaskHistoryStore real cross-host locking", () => { } }) - it("does not recreate a task deleted by another host before settlement", async () => { - const storagePath = await fs.mkdtemp(path.join(os.tmpdir(), "task-history-deleted-settlement-")) - const storeA = new TaskHistoryStore(storagePath) - const storeB = new TaskHistoryStore(storagePath) - const actionA = createAction("action-a", "action A") - - try { - await storeA.initialize() - await storeA.upsert({ ...item("shared-task"), pendingAction: actionA }) - await storeB.initialize() - - await storeB.delete("shared-task") - expect(storeA.get("shared-task")?.pendingAction).toEqual(actionA) - - await expect(storeA.clearPendingActionIfMatching("shared-task", actionA.actionId)).rejects.toThrow( - "task shared-task not found", - ) - expect(storeA.get("shared-task")).toBeUndefined() - await storeB.invalidate("shared-task") - expect(storeB.get("shared-task")).toBeUndefined() - } finally { - storeA.dispose() - storeB.dispose() - await fs.rm(storagePath, { recursive: true, force: true }) - } - }) + it.each(["delete", "deleteMany"] as const)( + "does not resurrect a backup after %s before settlement", + async (method) => { + const storagePath = await fs.mkdtemp(path.join(os.tmpdir(), "task-history-deleted-settlement-")) + const storeA = new TaskHistoryStore(storagePath) + const storeB = new TaskHistoryStore(storagePath) + const actionA = createAction("action-a", "action A") + + try { + await storeA.initialize() + await storeA.upsert({ ...item("shared-task"), pendingAction: actionA }) + await storeB.initialize() + + const canonical = path.join(storagePath, "tasks", "shared-task", "history_item.json") + const backup = path.join(path.dirname(canonical), ".history_item.json.bak_1_test.tmp") + await fs.copyFile(canonical, backup) + if (method === "delete") await storeB.delete("shared-task") + else await storeB.deleteMany(["shared-task"]) + await expect(fs.access(backup)).rejects.toMatchObject({ code: "ENOENT" }) + expect(storeA.get("shared-task")?.pendingAction).toEqual(actionA) + + await expect(storeA.clearPendingActionIfMatching("shared-task", actionA.actionId)).rejects.toThrow( + "task shared-task not found", + ) + expect(storeA.get("shared-task")).toBeUndefined() + await storeB.invalidate("shared-task") + expect(storeB.get("shared-task")).toBeUndefined() + } finally { + storeA.dispose() + storeB.dispose() + await fs.rm(storagePath, { recursive: true, force: true }) + } + }, + ) it("serializes deletion after settlement reads disk without recreating the record", async () => { const storagePath = await fs.mkdtemp(path.join(os.tmpdir(), "task-history-delete-during-settlement-")) diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.spec.ts index 3e277ac867..5dfd6f7d0f 100644 --- a/src/core/task-persistence/__tests__/TaskHistoryStore.spec.ts +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.spec.ts @@ -17,7 +17,8 @@ vi.mock("../../../utils/storage", () => ({ })) // Mock safeWriteJson to use plain fs writes in tests (avoids proper-lockfile issues) -vi.mock("../../../utils/safeWriteJson", () => ({ +vi.mock("../../../utils/safeWriteJson", async (importOriginal) => ({ + ...(await importOriginal()), safeWriteJson: vi.fn().mockImplementation(async (filePath: string, data: any) => { await fs.mkdir(path.dirname(filePath), { recursive: true }) await fs.writeFile(filePath, JSON.stringify(data, null, "\t"), "utf8") diff --git a/src/core/task-persistence/__tests__/taskMessages.spec.ts b/src/core/task-persistence/__tests__/taskMessages.spec.ts index 5917997931..2486c7a52f 100644 --- a/src/core/task-persistence/__tests__/taskMessages.spec.ts +++ b/src/core/task-persistence/__tests__/taskMessages.spec.ts @@ -16,6 +16,7 @@ vi.mock("fs/promises", async (importOriginal) => ({ })) vi.mock("../../../utils/safeWriteJson", () => ({ safeWriteJson: hoisted.safeWriteJsonMock, + recoverJsonFile: vi.fn().mockResolvedValue(undefined), })) // Import after mocks @@ -221,7 +222,7 @@ describe("taskMessages.readTaskMessages", () => { originalError: missing, message: expect.stringContaining("(code: ENOENT)"), }) - expect(hoisted.readFileMock).toHaveBeenCalledTimes(2) + expect(hoisted.readFileMock).toHaveBeenCalledTimes(3) }) it("does not retry non-ENOENT read failures and surfaces the underlying code", async () => { diff --git a/src/core/task-persistence/persistenceTrace.ts b/src/core/task-persistence/persistenceTrace.ts index 06b85716e8..4067b8fb44 100644 --- a/src/core/task-persistence/persistenceTrace.ts +++ b/src/core/task-persistence/persistenceTrace.ts @@ -1,60 +1,7 @@ -/** - * Structured trace points for task-persistence file writes and shutdown. - * - * The restart-persistence investigation in issue #2130 could not tell which - * writer touched ui_messages.json or when, because nothing logged the - * replacement-protocol steps. These trace lines record the write stages, the - * marker check, and shutdown with the task ID and the process ID, so CI logs - * and extension logs can order writer activity across a restart. - * - * The default sink is the console. Extension activation installs a sink that - * also mirrors every line into the extension output channel; tests can - * install their own sink to capture events. Tracing must never break - * persistence, so sink failures are swallowed. - */ - -export type PersistenceTraceStage = - | "ui-messages-recovery" - | "ui-messages-write-start" - | "ui-messages-backup-rename" - | "ui-messages-replacement-rename" - | "ui-messages-write-complete" - | "ui-messages-marker-check" - | "shutdown" - -export type PersistenceTraceFields = { - taskId?: string - filePath?: string - result?: string - detail?: string -} - -type PersistenceTraceSink = (line: string) => void - -let traceSink: PersistenceTraceSink | undefined - -/** - * Installs the sink used for every subsequent trace event. Pass undefined to - * restore the default console sink. - */ -export function setPersistenceTraceSink(sink: PersistenceTraceSink | undefined): void { - traceSink = sink -} - -export function tracePersistenceEvent(stage: PersistenceTraceStage, fields: PersistenceTraceFields = {}): void { - const line = `[persistence-trace] ${JSON.stringify({ - ts: new Date().toISOString(), - pid: process.pid, - stage, - ...fields, - })}` - try { - if (traceSink) { - traceSink(line) - } else { - console.log(line) - } - } catch { - // A failing sink must never break the write, read, or shutdown path. - } -} +// Keep the task-persistence import path while sharing the sink with JSON I/O. +export { + setPersistenceTraceSink, + tracePersistenceEvent, + type PersistenceTraceStage, + type PersistenceTraceFields, +} from "../../utils/persistenceTrace" diff --git a/src/core/task-persistence/readFileWithMissingRetry.ts b/src/core/task-persistence/readFileWithMissingRetry.ts index 67db76d0d0..16b370d445 100644 --- a/src/core/task-persistence/readFileWithMissingRetry.ts +++ b/src/core/task-persistence/readFileWithMissingRetry.ts @@ -1,10 +1,13 @@ import * as fs from "fs/promises" +import { recoverJsonFile } from "../../utils/safeWriteJson" + // safeWriteJson commits a replacement with a single atomic rename. Only the // Windows EPERM fallback replaces a file in two renames (target to backup, // new file to target), because a single rename over an open file fails with // EPERM on Windows. A reader can see ENOENT between those two renames, so -// retry once. +// retry once. If the path is still absent, acquire the writer lock and +// recover any committed backup before trying the read again. const READ_RETRY_MIN_MS = 1 const READ_RETRY_MAX_MS = 10 const READ_RETRY_RANGE_MS = READ_RETRY_MAX_MS - READ_RETRY_MIN_MS + 1 @@ -43,6 +46,12 @@ export async function readFileWithMissingRetry(filePath: string): Promise setTimeout(resolve, retryDelay)) - return fs.readFile(filePath, "utf8") + try { + return await fs.readFile(filePath, "utf8") + } catch (retryError) { + if (getErrorCode(retryError) !== "ENOENT") throw retryError + await recoverJsonFile(filePath) + return fs.readFile(filePath, "utf8") + } } } diff --git a/src/core/webview/ClineProvider.ts b/src/core/webview/ClineProvider.ts index 3d88df632b..94eb31c2ab 100644 --- a/src/core/webview/ClineProvider.ts +++ b/src/core/webview/ClineProvider.ts @@ -98,7 +98,7 @@ import type { CodeIndexWorkspaceScope } from "../../services/code-index/code-ind import { MdmService } from "../../services/mdm/MdmService" import { SkillsManager } from "../../services/skills/SkillsManager" -import { fileExistsAtPath } from "../../utils/fs" +import { getErrorCode, readFileWithMissingRetry } from "../task-persistence/readFileWithMissingRetry" import { setTtsEnabled, setTtsSpeed } from "../../utils/tts" import { getWorkspaceGitInfo } from "../../utils/git" import { getWorkspacePath } from "../../utils/path" @@ -2385,21 +2385,15 @@ export class ClineProvider const taskDirPath = await getTaskDirectoryPath(globalStoragePath, id) const apiConversationHistoryFilePath = path.join(taskDirPath, GlobalFileNames.apiConversationHistory) const uiMessagesFilePath = path.join(taskDirPath, GlobalFileNames.uiMessages) - const fileExists = await fileExistsAtPath(apiConversationHistoryFilePath) - let apiConversationHistory: Anthropic.MessageParam[] = [] - - if (fileExists) { - try { - apiConversationHistory = JSON.parse(await fs.readFile(apiConversationHistoryFilePath, "utf8")) - } catch (error) { - console.warn( - `[getTaskWithId] api_conversation_history.json corrupted for task ${id}, returning empty history: ${error instanceof Error ? error.message : String(error)}`, - ) - } - } else { + try { + apiConversationHistory = JSON.parse(await readFileWithMissingRetry(apiConversationHistoryFilePath)) + } catch (error) { + // Preserve the existing missing/corrupt-history behavior, but never + // turn an I/O or recovery failure into an empty conversation. + if (!(error instanceof SyntaxError) && getErrorCode(error) !== "ENOENT") throw error console.warn( - `[getTaskWithId] api_conversation_history.json missing for task ${id}, returning empty history`, + `[getTaskWithId] API history unavailable for task ${id}, returning empty history: ${error instanceof Error ? error.message : String(error)}`, ) } diff --git a/src/core/webview/__tests__/ClineProvider.spec.ts b/src/core/webview/__tests__/ClineProvider.spec.ts index 93543435e2..8112c545a5 100644 --- a/src/core/webview/__tests__/ClineProvider.spec.ts +++ b/src/core/webview/__tests__/ClineProvider.spec.ts @@ -30,7 +30,7 @@ import { setTtsEnabled } from "../../../utils/tts" import { ContextProxy } from "../../config/ContextProxy" import { WorkspaceIndexingEnablementManager } from "../../../services/code-index/workspace-indexing-enablement-manager" import { Task, TaskOptions } from "../../task/Task" -import { safeWriteJson } from "../../../utils/safeWriteJson" +import { recoverJsonFile, safeWriteJson } from "../../../utils/safeWriteJson" import { ClineProvider } from "../ClineProvider" import { webviewMessageHandler } from "../webviewMessageHandler" @@ -5849,13 +5849,40 @@ describe("ClineProvider - Comprehensive Edit/Delete Edge Cases", () => { const deleteTaskSpy = vi.spyOn(provider, "deleteTaskFromState") - const result = await (provider as any).getTaskWithId("missing-api-file-task") + const result = await provider.getTaskWithId("missing-api-file-task") expect(result.historyItem).toEqual(historyItem) expect(result.apiConversationHistory).toEqual([]) expect(deleteTaskSpy).not.toHaveBeenCalled() }) + it("recovers API history through the shared reader before returning a task", async () => { + const historyItem = { id: "recover-api-task", task: "test task", ts: Date.now() } + vi.mocked(mockContext.globalState.get).mockImplementation((key: string) => + key === "taskHistory" ? [historyItem] : undefined, + ) + const fsp = await import("fs/promises") + const missing = Object.assign(new Error("missing"), { code: "ENOENT" }) + const messages = [{ role: "user", content: "committed" }] + vi.mocked(fsp.readFile) + .mockRejectedValueOnce(missing) + .mockRejectedValueOnce(missing) + .mockResolvedValueOnce(JSON.stringify(messages)) + const result = await provider.getTaskWithId(historyItem.id) + expect(result.apiConversationHistory).toEqual(messages) + expect(recoverJsonFile).toHaveBeenCalledWith(result.apiConversationHistoryFilePath) + }) + + it.each(["EIO", "EACCES", "ELOCKED"])("does not return empty history after a %s read failure", async (code) => { + const historyItem = { id: "failed-api-task", task: "test task", ts: Date.now() } + vi.mocked(mockContext.globalState.get).mockImplementation((key: string) => + key === "taskHistory" ? [historyItem] : undefined, + ) + const fsp = await import("fs/promises") + vi.mocked(fsp.readFile).mockRejectedValueOnce(Object.assign(new Error(code), { code })) + await expect(provider.getTaskWithId(historyItem.id)).rejects.toMatchObject({ code }) + }) + it("returns empty apiConversationHistory when file contains invalid JSON", async () => { const historyItem = { id: "corrupt-api-task", task: "test task", ts: Date.now() } vi.mocked(mockContext.globalState.get).mockImplementation((key: string) => { @@ -5865,24 +5892,17 @@ describe("ClineProvider - Comprehensive Edit/Delete Edge Cases", () => { return undefined }) - // Make fileExistsAtPath return true so the read path is exercised - const fsUtils = await import("../../../utils/fs") - vi.spyOn(fsUtils, "fileExistsAtPath").mockResolvedValue(true) - // Make readFile return corrupted JSON const fsp = await import("fs/promises") vi.mocked(fsp.readFile).mockResolvedValueOnce("{not valid json!!!" as never) const deleteTaskSpy = vi.spyOn(provider, "deleteTaskFromState") - const result = await (provider as any).getTaskWithId("corrupt-api-task") + const result = await provider.getTaskWithId("corrupt-api-task") expect(result.historyItem).toEqual(historyItem) expect(result.apiConversationHistory).toEqual([]) expect(deleteTaskSpy).not.toHaveBeenCalled() - - // Restore the spy - vi.mocked(fsUtils.fileExistsAtPath).mockRestore() }) }) diff --git a/src/eslint-suppressions.json b/src/eslint-suppressions.json index 0dd477ab2d..5ff2c94f7e 100644 --- a/src/eslint-suppressions.json +++ b/src/eslint-suppressions.json @@ -1016,7 +1016,7 @@ }, "core/webview/__tests__/ClineProvider.spec.ts": { "@typescript-eslint/no-explicit-any": { - "count": 196 + "count": 194 } }, "core/webview/__tests__/ClineProvider.sticky-mode.spec.ts": { diff --git a/src/extension.ts b/src/extension.ts index e6dce2f668..34865230c4 100644 --- a/src/extension.ts +++ b/src/extension.ts @@ -129,10 +129,7 @@ export async function activate(context: vscode.ExtensionContext) { // Mirror persistence trace lines (task ID + process ID) into the output // channel and the console, so a restart-persistence investigation can // order UI-message writer activity across extension-host restarts. - setPersistenceTraceSink((line) => { - outputChannel.appendLine(line) - console.log(line) - }) + setPersistenceTraceSink(createDualLogger(createOutputChannelLogger(outputChannel))) outputChannel.appendLine(`${Package.name} extension activated - ${JSON.stringify(Package)}`) // Initialize network proxy configuration early, before any network requests. diff --git a/src/extension/api.ts b/src/extension/api.ts index 4c808fe97f..76532848f2 100644 --- a/src/extension/api.ts +++ b/src/extension/api.ts @@ -33,6 +33,7 @@ import type { Mode } from "../shared/modes" import type { ClineProvider } from "../core/webview/ClineProvider" import type { ClineProviderFactory } from "../core/webview/ClineProviderFactory" import { readTaskMessages } from "../core/task-persistence/taskMessages" +import { formatErrorDetail } from "../core/task-persistence/readFileWithMissingRetry" import { tracePersistenceEvent } from "../core/task-persistence/persistenceTrace" import { Terminal } from "../integrations/terminal/Terminal" import { TerminalRegistry } from "../integrations/terminal/TerminalRegistry" @@ -361,8 +362,12 @@ export class API extends EventEmitter implements RooCodeAPI { taskId, globalStoragePath: this.sidebarProvider.contextProxy.globalStorageUri.fsPath, }) - } catch { - tracePersistenceEvent("ui-messages-marker-check", { taskId, result: "read-error" }) + } catch (error) { + tracePersistenceEvent("ui-messages-marker-check", { + taskId, + result: "read-error", + detail: formatErrorDetail(error), + }) return false } const hasText = uiMessages.some((message) => message.text?.includes(text)) diff --git a/src/utils/__tests__/safeWriteJson.interruption.test.ts b/src/utils/__tests__/safeWriteJson.interruption.test.ts index 9dc142941c..219e68b8d6 100644 --- a/src/utils/__tests__/safeWriteJson.interruption.test.ts +++ b/src/utils/__tests__/safeWriteJson.interruption.test.ts @@ -6,6 +6,8 @@ import * as os from "os" import * as path from "path" import { safeWriteJson } from "../safeWriteJson" +import { LOCK_STALE_MS } from "../fileLock" +import { setPersistenceTraceSink } from "../persistenceTrace" import { readFileWithMissingRetry } from "../../core/task-persistence/readFileWithMissingRetry" const requireFromTest = createRequire(import.meta.url) @@ -24,13 +26,18 @@ const targetPath = path.resolve(process.env.INTERRUPTION_TARGET_PATH) const fsPromises = require("fs/promises") const actualRename = fsPromises.rename -// Fault injection: die with code 0 before the replacement lands. Any rename +// Fault injection: SIGKILL before the replacement lands. Any rename // whose destination is the canonical path is the commit step, whatever -// replacement protocol the writer uses; exit before performing it. +// replacement protocol the writer uses; kill the process before performing it. +let rejectedCommit = false fsPromises.rename = function interruptionRename(oldPath, newPath) { if (path.resolve(String(newPath)) === targetPath) { + if (process.env.INTERRUPTION_EPERM === "1" && !rejectedCommit) { + rejectedCommit = true + return Promise.reject(Object.assign(new Error("injected EPERM"), { code: "EPERM" })) + } fs.writeSync(1, "EXIT_BEFORE_REPLACEMENT_RENAME\\n") - process.exit(0) + process.kill(process.pid, "SIGKILL") } return actualRename.apply(fsPromises, arguments) } @@ -50,7 +57,7 @@ require(process.env.INTERRUPTION_BUNDLE_PATH) .safeWriteJson(targetPath, payload) .then(() => { fs.writeSync(1, "WRITE_COMPLETED\\n") - process.exit(0) + process.kill(process.pid, "SIGKILL") }) .catch((error) => { fs.writeSync(2, "WRITE_FAILED: " + ((error && error.message) || String(error)) + "\\n") @@ -58,7 +65,9 @@ require(process.env.INTERRUPTION_BUNDLE_PATH) }) ` -async function waitForChildExit(child: ChildProcess): Promise<{ code: number | null; stdout: string; stderr: string }> { +async function waitForChildExit( + child: ChildProcess, +): Promise<{ signal: NodeJS.Signals | null; stdout: string; stderr: string }> { const stdoutChunks: Buffer[] = [] const stderrChunks: Buffer[] = [] child.stdout?.on("data", (chunk: Buffer) => stdoutChunks.push(chunk)) @@ -69,10 +78,10 @@ async function waitForChildExit(child: ChildProcess): Promise<{ code: number | n reject(new Error("Interruption child did not exit within 20 seconds")) }, 20_000) child.once("error", reject) - child.once("close", (code) => { + child.once("close", (_code, signal) => { clearTimeout(timeout) resolve({ - code, + signal, stdout: Buffer.concat(stdoutChunks).toString("utf8"), stderr: Buffer.concat(stderrChunks).toString("utf8"), }) @@ -101,12 +110,13 @@ describe("safeWriteJson subprocess interruption fault injection", () => { }) afterEach(async () => { + setPersistenceTraceSink(undefined) await fs.rm(tempDir, { recursive: true, force: true }) }) - it.each([1, 2, 3])( - "keeps the committed file readable when the writer dies before the replacement lands (run %i)", - async (run) => { + it.each([false, true])( + "recovers after SIGKILL before commit (EPERM fallback: %s)", + async (eperm) => { // A previously committed write contains the restart marker. const committed = { ui_messages: [{ ts: 1, type: "say", text: "RESTART_PERSISTENCE_MARKER" }] } await fs.writeFile(targetPath, JSON.stringify(committed), "utf8") @@ -123,8 +133,9 @@ describe("safeWriteJson subprocess interruption fault injection", () => { env: { ...process.env, INTERRUPTION_TARGET_PATH: targetPath, + INTERRUPTION_EPERM: eperm ? "1" : "0", INTERRUPTION_PAYLOAD: JSON.stringify({ - ui_messages: [{ ts: 2, type: "say", text: `INTERRUPTED_WRITE_${run}` }], + ui_messages: [{ ts: 2, type: "say", text: "INTERRUPTED_WRITE" }], }), ESBUILD_PATH: esbuildPath, SAFE_WRITE_JSON_ENTRY: safeWriteJsonEntryPath, @@ -137,21 +148,37 @@ describe("safeWriteJson subprocess interruption fault injection", () => { expect(exit.stdout).toContain("EXIT_BEFORE_REPLACEMENT_RENAME") expect(exit.stdout).not.toContain("WRITE_COMPLETED") expect(exit.stderr).not.toContain("WRITE_FAILED") - expect(exit.code).toBe(0) - - // The writer terminated before the replacement rename, so the - // canonical path must still hold the last committed content. This - // is the permanent-ENOENT regression: with the old two-rename - // protocol the committed target was already renamed away, and no - // read retry could bring it back. - const after = JSON.parse(await readFileWithMissingRetry(targetPath)) - expect(after).toEqual(committed) - - // Restart recovery: remove the advisory lock file orphaned by the - // dead writer (proper-lockfile would only treat it as stale after - // 31 seconds), then a fresh write must succeed and consume the - // interrupted write's leftovers. - await fs.rm(`${targetPath}.lock`, { force: true }) + expect(exit.signal).toBe("SIGKILL") + + // SIGKILL bypasses proper-lockfile's exit cleanup. A fresh writer + // must reject the live-looking lock rather than steal it early. + await expect(fs.stat(`${targetPath}.lock`)).resolves.toBeDefined() + await expect(safeWriteJson(targetPath, {})).rejects.toMatchObject({ code: "ELOCKED" }) + if (!eperm) { + expect(JSON.parse(await readFileWithMissingRetry(targetPath))).toEqual(committed) + } else { + await expect(fs.access(targetPath)).rejects.toMatchObject({ code: "ENOENT" }) + // A reader must fail closed while the dead writer's lock still + // appears fresh, rather than return empty or delete its backup. + const lines: string[] = [] + setPersistenceTraceSink((line) => lines.push(line)) + await expect(readFileWithMissingRetry(targetPath)).rejects.toMatchObject({ code: "ELOCKED" }) + expect(JSON.parse(lines[0].slice("[persistence-trace] ".length))).toMatchObject({ + stage: "json-recovery-failed", + filePath: targetPath, + detail: "ELOCKED", + }) + const backups = (await fs.readdir(storageDir)).filter((entry) => entry.includes(".bak_")) + expect(backups).toHaveLength(1) + expect(JSON.parse(await fs.readFile(path.join(storageDir, backups[0]), "utf8"))).toEqual(committed) + } + + // Advance the real lock's age, without waiting 31 seconds. Recovery + // uses proper-lockfile's production stale-lock takeover protocol. + const staleTime = new Date(Date.now() - LOCK_STALE_MS - 2_000) + await fs.utimes(`${targetPath}.lock`, staleTime, staleTime) + expect(JSON.parse(await readFileWithMissingRetry(targetPath))).toEqual(committed) + const recovered = { ui_messages: [{ ts: 3, type: "say", text: "RECOVERED_AFTER_RESTART" }] } await safeWriteJson(targetPath, recovered) diff --git a/src/utils/__tests__/safeWriteJson.recovery.test.ts b/src/utils/__tests__/safeWriteJson.recovery.test.ts new file mode 100644 index 0000000000..7c71d556df --- /dev/null +++ b/src/utils/__tests__/safeWriteJson.recovery.test.ts @@ -0,0 +1,211 @@ +import * as fs from "fs/promises" +import * as os from "os" +import * as path from "path" + +import * as fileLock from "../fileLock" +import { recoverJsonFile, safeWriteJson, type SafeWriteJsonTrace } from "../safeWriteJson" +import { readTaskMessages, saveTaskMessages } from "../../core/task-persistence/taskMessages" +import { readApiMessages } from "../../core/task-persistence/apiMessages" +import { setPersistenceTraceSink } from "../../core/task-persistence/persistenceTrace" +import { readFileWithMissingRetry } from "../../core/task-persistence/readFileWithMissingRetry" + +vi.mock("fs/promises", async () => { + const actual = await vi.importActual("fs/promises") + return { + ...actual, + access: vi.fn(actual.access), + rename: vi.fn(actual.rename), + stat: vi.fn(actual.stat), + readdir: vi.fn(actual.readdir), + } +}) + +const actual = await vi.importActual("fs/promises") +const ioError = (code: string) => Object.assign(new Error(code), { code }) + +describe("interrupted JSON recovery", () => { + let dir: string + let canonical: string + let backup: string + + beforeEach(async () => { + vi.mocked(fs.access).mockReset().mockImplementation(actual.access) + vi.mocked(fs.rename).mockReset().mockImplementation(actual.rename) + vi.mocked(fs.stat).mockReset().mockImplementation(actual.stat) + vi.mocked(fs.readdir).mockReset().mockImplementation(actual.readdir) + dir = await fs.mkdtemp(path.join(os.tmpdir(), "json-recovery-")) + canonical = path.join(dir, "history.json") + backup = path.join(dir, ".history.json.bak_1_old.tmp") + await fs.writeFile(backup, JSON.stringify({ committed: true })) + }) + + afterEach(async () => { + vi.restoreAllMocks() + setPersistenceTraceSink(undefined) + await fs.rm(dir, { recursive: true, force: true }) + }) + + it("preserves committed backups and aborts before merge when restoration fails", async () => { + vi.mocked(fs.rename).mockRejectedValueOnce(ioError("EIO")) + const merge = vi.fn() + const trace = vi.fn() + await expect(safeWriteJson(canonical, {}, { merge, trace })).rejects.toMatchObject({ code: "EIO" }) + expect(JSON.parse(await fs.readFile(backup, "utf8"))).toEqual({ committed: true }) + expect(merge).not.toHaveBeenCalled() + expect(trace).toHaveBeenCalledWith({ stage: "recover", detail: "failed: EIO" }) + await expect(fs.access(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + // Failure also releases the lock, allowing the next attempt to recover. + await expect(safeWriteJson(canonical, {})).resolves.toBeUndefined() + }) + + it.each(["EACCES", "EIO", "EBUSY"])("does not overwrite existing data after access fails with %s", async (code) => { + await fs.writeFile(canonical, JSON.stringify({ current: true })) + vi.mocked(fs.access).mockImplementation(async (file, mode) => { + if (file === canonical) throw ioError(code) + return actual.access(file, mode) + }) + await expect(safeWriteJson(canonical, {})).rejects.toMatchObject({ code }) + expect(JSON.parse(await fs.readFile(canonical, "utf8"))).toEqual({ current: true }) + expect(JSON.parse(await fs.readFile(backup, "utf8"))).toEqual({ committed: true }) + expect(fs.rename).not.toHaveBeenCalled() + }) + + it.each(["readdir", "stat"] as const)("preserves backups and stops a write after %s fails", async (operation) => { + vi.mocked(fs[operation]).mockRejectedValueOnce(ioError("EIO")) + await expect(safeWriteJson(canonical, {})).rejects.toMatchObject({ code: "EIO" }) + await expect(fs.access(backup)).resolves.toBeUndefined() + await expect(fs.access(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + }) + + it("ignores a vanished backup while restoring the newest available committed state", async () => { + const newer = path.join(dir, ".history.json.bak_2_new.tmp") + const vanished = path.join(dir, ".history.json.bak_3_gone.tmp") + await fs.writeFile(newer, JSON.stringify({ newest: true })) + await fs.writeFile(vanished, "{}") + await fs.utimes(backup, new Date(1_000), new Date(1_000)) + await fs.utimes(newer, new Date(2_000), new Date(2_000)) + // Make the vanished stat deterministic, regardless of directory order. + vi.mocked(fs.stat) + .mockReset() + .mockImplementation((...args) => { + if (args[0] === vanished) return Promise.reject(ioError("ENOENT")) + return actual.stat(...args) + }) + const merge = vi.fn((existing: unknown) => existing) + const trace = vi.fn() + await safeWriteJson(canonical, {}, { merge, trace }) + expect(merge).toHaveBeenCalledWith({ newest: true }, {}) + expect(trace).toHaveBeenCalledWith({ stage: "recover", detail: newer }) + expect(JSON.parse(await fs.readFile(canonical, "utf8"))).toEqual({ newest: true }) + }) + + it("passes the canonical content to merge and leaves neighboring file leftovers alone", async () => { + const neighbor = path.join(dir, ".history.json.other.bak_1_old.tmp") + await fs.writeFile(neighbor, "neighbor") + await fs.writeFile(canonical, JSON.stringify({ current: true })) + const merge = vi.fn((existing: unknown) => existing) + await safeWriteJson(canonical, {}, { merge }) + expect(merge).toHaveBeenCalledWith({ current: true }, {}) + expect(await fs.readFile(neighbor, "utf8")).toBe("neighbor") + }) + + it("heals a missing canonical file on a read without writing incoming data", async () => { + expect(JSON.parse(await readFileWithMissingRetry(canonical))).toEqual({ committed: true }) + await expect(fs.access(backup)).rejects.toMatchObject({ code: "ENOENT" }) + }) + + it.each([ + { name: "UI", file: "ui_messages.json", read: readTaskMessages }, + { name: "API", file: "api_conversation_history.json", read: readApiMessages }, + ])("restores orphaned $name history through the public reader", async ({ file, read }) => { + const taskId = "recovery-task" + const taskDir = path.join(dir, "tasks", taskId) + await fs.mkdir(taskDir, { recursive: true }) + const messages = [{ role: "user", content: "committed", ts: 1, type: "say", text: "committed" }] + await fs.writeFile(path.join(taskDir, `.${file}.bak_1_old.tmp`), JSON.stringify(messages)) + expect(await read({ taskId, globalStoragePath: dir })).toEqual(messages) + expect(JSON.parse(await fs.readFile(path.join(taskDir, file), "utf8"))).toEqual(messages) + }) + + it("emits recovery and write traces through the real task-message writer", async () => { + const taskId = "traced-task" + const taskDir = path.join(dir, "tasks", taskId) + await fs.mkdir(taskDir, { recursive: true }) + await fs.writeFile(path.join(taskDir, ".ui_messages.json.bak_1_old.tmp"), "[]") + const lines: string[] = [] + setPersistenceTraceSink((line) => lines.push(line)) + await saveTaskMessages({ taskId, globalStoragePath: dir, messages: [] }) + const events = lines.map( + (line) => JSON.parse(line.slice("[persistence-trace] ".length)) as { stage: string; taskId: string }, + ) + expect(events.map((event) => event.stage)).toEqual([ + "ui-messages-recovery", + "ui-messages-write-start", + "ui-messages-replacement-rename", + "ui-messages-write-complete", + ]) + expect(events.every((event) => event.taskId === taskId)).toBe(true) + }) + + it("does not acquire a recovery lock for a genuinely missing file", async () => { + await fs.unlink(backup) + const lock = vi.spyOn(fileLock, "withFileLock") + await expect(readFileWithMissingRetry(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + expect(lock).not.toHaveBeenCalled() + await expect(fs.access(`${canonical}.lock`)).rejects.toMatchObject({ code: "ENOENT" }) + }) + + it("preserves missing-file behavior while a first writer holds the lock", async () => { + await fs.unlink(backup) + const release = await fileLock.acquireFileLock(canonical) + try { + await expect(readFileWithMissingRetry(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + await expect(fs.access(`${canonical}.lock`)).resolves.toBeUndefined() + } finally { + await release() + } + }) + + it.each([readFileWithMissingRetry, recoverJsonFile])("propagates recovery failures to readers", async (read) => { + vi.mocked(fs.rename).mockRejectedValueOnce(ioError("EIO")) + await expect(read(canonical)).rejects.toMatchObject({ code: "EIO" }) + await expect(fs.access(backup)).resolves.toBeUndefined() + }) + + it("preserves the committed backup after both replacement and rollback fail", async () => { + await fs.rename(backup, canonical) + vi.mocked(fs.rename).mockClear() + vi.mocked(fs.rename) + .mockRejectedValueOnce(ioError("EPERM")) + .mockImplementationOnce(actual.rename) + .mockRejectedValueOnce(ioError("EIO")) + .mockRejectedValueOnce(ioError("EBUSY")) + await expect(safeWriteJson(canonical, { incoming: true })).rejects.toMatchObject({ code: "EIO" }) + const backups = (await fs.readdir(dir)).filter((entry) => entry.includes(".bak_")) + expect(backups).toHaveLength(1) + expect(JSON.parse(await fs.readFile(path.join(dir, backups[0]), "utf8"))).toEqual({ committed: true }) + expect(JSON.parse(await readFileWithMissingRetry(canonical))).toEqual({ committed: true }) + }) + + it("keeps the canonical file intact when the fallback backup rename fails", async () => { + await fs.rename(backup, canonical) + vi.mocked(fs.rename).mockRejectedValueOnce(ioError("EPERM")).mockRejectedValueOnce(ioError("EIO")) + await expect(safeWriteJson(canonical, {})).rejects.toMatchObject({ code: "EIO" }) + expect(JSON.parse(await fs.readFile(canonical, "utf8"))).toEqual({ committed: true }) + }) + + it.each(["write", "read"])("traces recovery failures for a %s without an optional callback", async (operation) => { + const lines: string[] = [] + setPersistenceTraceSink((line) => lines.push(line)) + vi.mocked(fs.rename).mockRejectedValueOnce(ioError("EIO")) + const pending = operation === "write" ? safeWriteJson(canonical, {}) : readFileWithMissingRetry(canonical) + await expect(pending).rejects.toMatchObject({ code: "EIO" }) + expect(lines).toHaveLength(1) + expect(JSON.parse(lines[0].slice("[persistence-trace] ".length))).toMatchObject({ + stage: "json-recovery-failed", + filePath: canonical, + detail: "EIO", + pid: process.pid, + }) + }) +}) diff --git a/src/utils/persistenceTrace.ts b/src/utils/persistenceTrace.ts new file mode 100644 index 0000000000..137c76add2 --- /dev/null +++ b/src/utils/persistenceTrace.ts @@ -0,0 +1,64 @@ +/** + * Structured trace points for task-persistence file writes and shutdown. + * + * The restart-persistence investigation in issue #2130 could not tell which + * writer touched ui_messages.json or when, because nothing logged the + * replacement-protocol steps. These trace lines record the write stages, the + * marker check, and shutdown with the task ID and the process ID, so CI logs + * and extension logs can order writer activity across a restart. + * + * Shared JSON recovery failures include the file path and error code even + * when the writer or reader has no task-specific trace callback. + * + * The default sink is the console. Extension activation installs a sink that + * also mirrors every line into the extension output channel; tests can + * install their own sink to capture events. Tracing must never break + * persistence, so sink failures are swallowed. + */ + +export type PersistenceTraceStage = + | "json-recovery-failed" + | "ui-messages-recovery" + | "ui-messages-write-start" + | "ui-messages-backup-rename" + | "ui-messages-replacement-rename" + | "ui-messages-write-complete" + | "ui-messages-marker-check" + | "shutdown" + +export type PersistenceTraceFields = { + taskId?: string + filePath?: string + result?: string + detail?: string +} + +type PersistenceTraceSink = (line: string) => void + +let traceSink: PersistenceTraceSink | undefined + +/** + * Installs the sink used for every subsequent trace event. Pass undefined to + * restore the default console sink. + */ +export function setPersistenceTraceSink(sink: PersistenceTraceSink | undefined): void { + traceSink = sink +} + +export function tracePersistenceEvent(stage: PersistenceTraceStage, fields: PersistenceTraceFields = {}): void { + const line = `[persistence-trace] ${JSON.stringify({ + ts: new Date().toISOString(), + pid: process.pid, + stage, + ...fields, + })}` + try { + if (traceSink) { + traceSink(line) + } else { + console.log(line) + } + } catch { + // A failing sink must never break the write, read, or shutdown path. + } +} diff --git a/src/utils/safeWriteJson.ts b/src/utils/safeWriteJson.ts index b7274125bf..b98f408d78 100644 --- a/src/utils/safeWriteJson.ts +++ b/src/utils/safeWriteJson.ts @@ -3,7 +3,8 @@ import * as fsSync from "fs" import * as path from "path" import { JsonStreamStringify } from "json-stream-stringify" -import { acquireFileLock } from "./fileLock" +import { acquireFileLock, withFileLock } from "./fileLock" +import { tracePersistenceEvent } from "./persistenceTrace" /** * Stages reported through the optional `trace` callback. They mark the @@ -76,7 +77,7 @@ function getTempFilePrefix(absoluteFilePath: string, kind: "new" | "bak"): strin * @returns Whether leftover files were found, and the backup path that was * restored, if any. */ -async function recoverInterruptedReplacement( +async function recoverInterruptedReplacementUnchecked( absoluteFilePath: string, ): Promise<{ foundLeftovers: boolean; restoredFrom: string | null }> { const dirPath = path.dirname(absoluteFilePath) @@ -86,9 +87,8 @@ async function recoverInterruptedReplacement( let entries: string[] try { entries = await fs.readdir(dirPath) - } catch { - // The directory is unreadable or was removed; the write itself - // reports that error below. + } catch (error) { + if (getErrorCode(error) !== "ENOENT") throw error return { foundLeftovers: false, restoredFrom: null } } @@ -104,27 +104,30 @@ async function recoverInterruptedReplacement( try { await fs.access(absoluteFilePath) - } catch { - // The canonical path is absent. An interrupted two-step replacement - // leaves the committed content in the newest backup, so restore it - // and keep readers on the last committed state. + } catch (error) { + if (getErrorCode(error) !== "ENOENT") throw error + // Ignore only backups removed since readdir. Other inspection failures + // must stop the write rather than discard uninspected committed data. const backupStats = await Promise.all( orphanedPaths .filter((orphanPath) => path.basename(orphanPath).startsWith(backupPrefix)) - .map(async (backupPath) => ({ backupPath, mtimeMs: (await fs.stat(backupPath)).mtimeMs })), + .map(async (backupPath) => { + try { + return { backupPath, mtimeMs: (await fs.stat(backupPath)).mtimeMs } + } catch (statError) { + if (getErrorCode(statError) !== "ENOENT") throw statError + return null + } + }), ) - if (backupStats.length > 0) { - backupStats.sort((a, b) => b.mtimeMs - a.mtimeMs) - const newestBackupPath = backupStats[0].backupPath - try { - await fs.rename(newestBackupPath, absoluteFilePath) - restoredFrom = newestBackupPath - } catch (restoreError) { - console.error( - `Failed to restore interrupted-write backup ${newestBackupPath} to ${absoluteFilePath}:`, - restoreError, - ) - } + const backups = backupStats.filter((backup) => backup !== null) + backups.sort((a, b) => b.mtimeMs - a.mtimeMs || b.backupPath.localeCompare(a.backupPath)) + if (backups.length > 0) { + const newestBackupPath = backups[0].backupPath + // A failed restore leaves every backup intact and aborts the write. + // In particular, a merge must never observe null in this state. + await fs.rename(newestBackupPath, absoluteFilePath) + restoredFrom = newestBackupPath } } @@ -142,6 +145,59 @@ async function recoverInterruptedReplacement( return { foundLeftovers: true, restoredFrom } } +async function withRecoveryTrace(absoluteFilePath: string, operation: () => Promise): Promise { + try { + return await operation() + } catch (error) { + tracePersistenceEvent("json-recovery-failed", { + filePath: absoluteFilePath, + detail: getErrorCode(error) ?? String(error), + }) + throw error + } +} + +function getErrorCode(error: unknown): string | undefined { + return typeof error === "object" && error !== null && "code" in error && typeof error.code === "string" + ? error.code + : undefined +} + +/** Recover a missing JSON file for a reader, serialized with writers and deletion. */ +export async function recoverJsonFile(filePath: string): Promise { + const absoluteFilePath = path.resolve(filePath) + return withRecoveryTrace(absoluteFilePath, async () => { + let entries: string[] + try { + entries = await fs.readdir(path.dirname(absoluteFilePath)) + } catch (error) { + if (getErrorCode(error) === "ENOENT") return + throw error + } + // A genuinely absent file has nothing to recover. Do not contend with a + // first writer (or create a lock directory) merely to report ENOENT. + const backupPrefix = getTempFilePrefix(absoluteFilePath, "bak") + if (!entries.some((entry) => entry.startsWith(backupPrefix) && entry.endsWith(".tmp"))) return + // This is only a hint: inspect the canonical file and backups again under + // the lock before restoring or cleaning anything. + await withFileLock(absoluteFilePath, recoverInterruptedReplacementUnchecked) + }) +} + +/** Called under the canonical file lock before deleting it, so backups cannot resurrect it. */ +export async function removeJsonBackups(absoluteFilePath: string): Promise { + const prefix = getTempFilePrefix(absoluteFilePath, "bak") + for (const entry of await fs.readdir(path.dirname(absoluteFilePath))) { + if (entry.startsWith(prefix) && entry.endsWith(".tmp")) { + try { + await fs.unlink(path.join(path.dirname(absoluteFilePath), entry)) + } catch (error) { + if (getErrorCode(error) !== "ENOENT") throw error + } + } + } +} + /** * Safely writes JSON data to a file. * - Creates parent directories if they don't exist @@ -194,7 +250,12 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso // Heal any state an interrupted previous write left behind: an absent // canonical path with an orphaned backup, or leftover replacement // files. Runs first so a merge callback reads the restored content. - const recovery = await recoverInterruptedReplacement(absoluteFilePath) + const recovery = await withRecoveryTrace(absoluteFilePath, () => + recoverInterruptedReplacementUnchecked(absoluteFilePath), + ).catch((error: unknown) => { + options?.trace?.({ stage: "recover", detail: `failed: ${getErrorCode(error) ?? String(error)}` }) + throw error + }) if (recovery.foundLeftovers) { options?.trace?.({ stage: "recover", detail: recovery.restoredFrom ?? "cleaned-leftovers" }) } @@ -216,13 +277,11 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso data = options.merge(existing, data) } - // Step 1: Write data to a new temporary file and flush it to storage, - // so the replacement content is durable before it is committed. + // Step 1: Stream the replacement to a temporary file before commit. options?.trace?.({ stage: "write-start" }) actualTempNewFilePath = createTempFilePath(absoluteFilePath, "new") await _streamDataToFile(actualTempNewFilePath, data, options?.prettyPrint) - await _flushFileToDisk(actualTempNewFilePath) // Step 2: Commit the replacement with a single atomic rename. The // committed target stays in place until this rename lands, so a @@ -243,8 +302,9 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso // second rename fails, and the recovery pass at the start of the // next write repairs a crash between the two renames. options?.trace?.({ stage: "backup-rename", detail: "eperm-fallback" }) - actualTempBackupFilePath = createTempFilePath(absoluteFilePath, "bak") - await fs.rename(absoluteFilePath, actualTempBackupFilePath) + const backupPath = createTempFilePath(absoluteFilePath, "bak") + await fs.rename(absoluteFilePath, backupPath) + actualTempBackupFilePath = backupPath options?.trace?.({ stage: "replacement-rename", detail: "eperm-fallback" }) await fs.rename(actualTempNewFilePath, absoluteFilePath) } @@ -303,17 +363,8 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso } } - // Cleanup the .bak file if it still needs to be (i.e., wasn't successfully restored) - if (actualTempBackupFilePath) { - try { - await fs.unlink(actualTempBackupFilePath) - } catch (cleanupError) { - console.error( - `[Catch] Failed to clean up temporary backup file ${actualTempBackupFilePath}:`, - cleanupError, - ) - } - } + // A failed rollback leaves the last committed copy in the backup. + // Preserve it so a subsequent read or write can recover it. throw originalError // This MUST be the error that rejects the promise. } finally { // Release the lock in the main finally block. @@ -356,23 +407,4 @@ async function _streamDataToFile(targetPath: string, data: any, prettyPrint = fa }) } -/** - * Flushes a fully written temp file to storage before it is committed. - * Best effort: durability against power loss is a bonus here, process-crash - * safety comes from the rename protocol itself, and a filesystem that - * refuses fsync must not block the write. - */ -async function _flushFileToDisk(targetPath: string): Promise { - try { - const handle = await fs.open(targetPath, "r") - try { - await handle.sync() - } finally { - await handle.close() - } - } catch (flushError) { - console.error(`Failed to flush ${targetPath} to storage before commit:`, flushError) - } -} - export { safeWriteJson } From ba03708433ef93255de34f9197c3d4031d766147 Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sat, 24 Oct 2026 03:44:01 +0000 Subject: [PATCH 03/14] fix(persistence): recover task history before startup repair --- docs/architecture/json-persistence-audit.md | 34 ++-- docs/architecture/task-lifecycle-model.md | 6 + src/core/task-persistence/TaskHistoryStore.ts | 145 +++++++++++++----- .../TaskHistoryStore.initialization.spec.ts | 124 +++++++++++++++ .../TaskHistoryStore.reconciliation.spec.ts | 5 +- .../TaskHistoryStore.recovery.spec.ts | 127 +++++++++++++++ .../safeWriteJson.interruption.test.ts | 11 +- .../__tests__/safeWriteJson.recovery.test.ts | 5 +- 8 files changed, 397 insertions(+), 60 deletions(-) create mode 100644 src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts create mode 100644 src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts diff --git a/docs/architecture/json-persistence-audit.md b/docs/architecture/json-persistence-audit.md index be86142ac1..f7a9564a9a 100644 --- a/docs/architecture/json-persistence-audit.md +++ b/docs/architecture/json-persistence-audit.md @@ -10,22 +10,30 @@ All rejected recovery attempts, including read-side lock acquisition and directo A fresh-looking lock left by SIGKILL still rejects a writer or a reader attempting backup recovery with ELOCKED after the configured retries. This is intentional: lock freshness cannot distinguish a dead process from a paused owner. The subprocess test verifies rejection, backup preservation, and recovery after aging the lock past `LOCK_STALE_MS` (31 seconds). It does not wait 31 real seconds or establish Windows filesystem semantics. +## Initialization availability + +Initialization retries transient `ELOCKED` and `EBUSY` failures with one timeout chain: delays of 1, 2, 4, 8, 8, and 8 seconds, after which the final error is returned. Concurrent calls share the same initialization promise, and disposal cancels a pending retry. Each attempt reruns the scan and startup sequence; delegation repair cannot run after a failed scan. Permanent errors such as EACCES or EIO are not retried. + +`initialized` resolves after success or terminal failure, not between transient attempts. `isHealthy` is true only after the startup sequence succeeds; it stays false after exhaustion or persistent failure. The provider's existing awaited initialization resumes migration on eventual success. The existing activation catch still logs terminal errors and allows extension activation to continue. + +Follow-up work, outside this PR: show a persistent-error warning and offer an explicit user retry action. There is no new UI action here. After a persistent error or exhaustion, history can remain partial and observers have not been started. The separate health flag makes that outcome distinguishable from successful initialization; it does not itself provide a user-facing warning. + ## Consumer inventory Paths in this table are relative to `src/`. -| Consumer | Calls | Data and semantics | Error/read behavior | -| ---------------------------------------------- | ----: | ---------------------------------------------------------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | -| `api/providers/fetchers/modelEndpointCache.ts` | 1 | Replace fetched endpoint cache | Disk reader checks existence; cache can be refetched. Writer rejection propagates to cache refresh handling. | -| `api/providers/fetchers/modelCache.ts` | 1 | Replace fetched model cache | Includes a synchronous disk reader; missing cache can be refetched. Refresh paths catch/log write failures. | -| `services/mcp/McpHub.ts` | 4 | Create global settings with a preserving merge; replace settings for updates, removal, and tool configuration | Creation preserves recovered settings. Other operations read before entering the writer's lock; their entire read-modify-write is not made atomic by this PR. | -| `services/code-index/cache-manager.ts` | 2 | Save or clear file hashes | Initialization uses VS Code filesystem reads and resets a missing cache; writes catch/log and emit telemetry. Hashes are rebuildable. | -| `core/config/importExport.ts` | 1 | Replace a user-selected settings export | Export catches/logs failures. Import reads the selected canonical file directly. | -| `core/webview/webviewMessageHandler.ts` | 1 | Initialize project MCP settings when the canonical file appears absent | Uses an existence check and blind default write. An orphaned backup can be restored and then replaced by defaults. This is a remaining initialization gap, not covered by task-message recovery tests. | -| `core/task-persistence/taskMessages.ts` | 1 | Save UI messages; optional snapshot merge | Reads use missing-file retry and backup recovery. Save failures propagate to Task, whose existing save helper catches them. Adds task-specific write traces. | -| `core/task-persistence/apiMessages.ts` | 2 | Migrate legacy history with merge; save API messages with optional merge | Current and legacy readers use recovery. Genuine absence maps to no history; other I/O failures throw. Migration removes the legacy source only after the write succeeds. | -| `core/task-persistence/TaskHistoryStore.ts` | 5 | Repair intent; legacy migration; history delta merge; authoritative replacement; conditional pending-action settlement | Deletion removes backups under the same file lock. Settlement rejects missing disk state. Store history reads and repair-intent reads still read canonical paths directly: orphaned history/intent backups are healed on writes, not on these readers. | -| `core/context-tracking/FileContextTracker.ts` | 1 | Replace task file-context metadata | Reads check canonical existence and otherwise return an empty context. Saves catch/log failures. Read-side backup healing is not provided here. | +| Consumer | Calls | Data and semantics | Error/read behavior | +| ---------------------------------------------- | ----: | ---------------------------------------------------------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `api/providers/fetchers/modelEndpointCache.ts` | 1 | Replace fetched endpoint cache | Disk reader checks existence; cache can be refetched. Writer rejection propagates to cache refresh handling. | +| `api/providers/fetchers/modelCache.ts` | 1 | Replace fetched model cache | Includes a synchronous disk reader; missing cache can be refetched. Refresh paths catch/log write failures. | +| `services/mcp/McpHub.ts` | 4 | Create global settings with a preserving merge; replace settings for updates, removal, and tool configuration | Creation preserves recovered settings. Other operations read before entering the writer's lock; their entire read-modify-write is not made atomic by this PR. | +| `services/code-index/cache-manager.ts` | 2 | Save or clear file hashes | Initialization uses VS Code filesystem reads and resets a missing cache; writes catch/log and emit telemetry. Hashes are rebuildable. | +| `core/config/importExport.ts` | 1 | Replace a user-selected settings export | Export catches/logs failures. Import reads the selected canonical file directly. | +| `core/webview/webviewMessageHandler.ts` | 1 | Initialize project MCP settings when the canonical file appears absent | Uses an existence check and blind default write. An orphaned backup can be restored and then replaced by defaults. This is a remaining initialization gap, not covered by task-message recovery tests. | +| `core/task-persistence/taskMessages.ts` | 1 | Save UI messages; optional snapshot merge | Reads use missing-file retry and backup recovery. Save failures propagate to Task, whose existing save helper catches them. Adds task-specific write traces. | +| `core/task-persistence/apiMessages.ts` | 2 | Migrate legacy history with merge; save API messages with optional merge | Current and legacy readers use recovery. Genuine absence maps to no history; other I/O failures throw. Migration removes the legacy source only after the write succeeds. | +| `core/task-persistence/TaskHistoryStore.ts` | 5 | Repair intent; legacy migration; history delta merge; authoritative replacement; conditional pending-action settlement | Deletion removes backups under the same file lock. Settlement rejects missing disk state. History reconcile and individual reads recover absent canonical files; failed recovery blocks delegation repair; transient initialization failures are retried and preserves cached records on refresh. Repair-intent reads still read the canonical path directly. | +| `core/context-tracking/FileContextTracker.ts` | 1 | Replace task file-context metadata | Reads check canonical existence and otherwise return an empty context. Saves catch/log failures. Read-side backup healing is not provided here. | `ClineProvider.getTaskWithId` is an additional API-history reader, not a writer. It now uses the recovery reader. SyntaxError and ENOENT retain their previous empty-history behavior; other filesystem/recovery failures propagate. Task loading and parent reopening also use the message readers. The advisory-file-lock owners are the JSON writer/recovery and history deletion; the inspected call paths do not invoke message recovery while already holding the same file lock. Provider delegation locks and store host mutexes are distinct from that file lock. @@ -43,4 +51,4 @@ The production source scan covered `src/`, `packages/`, and `apps/cli`, excludin Focused tests cover failed recovery/rollback, filesystem errors, backup ordering, neighboring files, missing-file reads, fresh-lock rejection, stale-lock takeover, trace delivery, and history deletion. The existing real-window restart E2E additionally moves UI/API histories to orphaned backups in a fresh extension host before resume and requires public reads to restore their exact bytes. -The E2E runner and CI workflow inspected run VS Code on Linux. That is real extension-host/window coverage, not evidence for Windows open-handle rename behavior. The Windows EPERM branch is fault-injected in unit/subprocess tests. The remaining reader and MCP-writer gaps above are explicitly outside the verified UI/API history contract. +The E2E runner and CI workflow inspected run VS Code on Linux. That is real extension-host/window coverage, not evidence for Windows open-handle rename behavior. The Windows EPERM branch is fault-injected in unit/subprocess tests. The remaining repair-intent/metadata reader and MCP-writer gaps above are explicitly outside the verified UI/API history contract. diff --git a/docs/architecture/task-lifecycle-model.md b/docs/architecture/task-lifecycle-model.md index eaeb61d987..360390aea9 100644 --- a/docs/architecture/task-lifecycle-model.md +++ b/docs/architecture/task-lifecycle-model.md @@ -88,6 +88,12 @@ The known-unsafe witnesses currently compare exact shortest action sequences. Th `TaskHistoryStore.realConcurrency.spec.ts` complements the abstract interleavings with real-filesystem checks through the real `proper-lockfile` and filesystem rename path, including stale-settlement compare-and-clear. History-file deletion holds the same per-file advisory lock as `safeWriteJson` around each unlink, and the real-filesystem suite covers a deletion that targets the settlement read-to-commit window plus schema and task-ID validation of the locked disk record before settlement (#1726). That lock serialization is best-effort: a lock acquisition or unlink failure is swallowed, so a deletion can proceed without the lock and the two sides serialize only when both acquire it. Restart recovery is covered by `Task.persistence.spec.ts`: it refreshes the persisted record first, treats a refreshed interrupted `create_subtask` action as rejected, settles that exact action before replay, adopts the authoritative pending action, blocks replay when an adopted action is missing from the loaded conversation, and stops replay on a failed refresh, lookup, or settlement rather than creating another child. Broader VS Code E2E remains reserved for other restart and extension-host behavior. +## History-file availability boundary + +Before startup delegation repair runs, `TaskHistoryStore.reconcile()` recovers an absent canonical history file from its interrupted-write backup under the file lock. Recovery failures prevent reducers from treating an unreadable child as missing; refresh failures retain the last cached record. Startup retries ELOCKED/EBUSY through one capped timeout chain and repeats the full scan before repair. The `initialized` promise settles only after success or terminal failure; `isHealthy` distinguishes these outcomes. `TaskHistoryStore.recovery.spec.ts` checks startup, reconciliation, invalidation, failed restore, fresh locks, and stale-lock takeover with real temporary files. `TaskHistoryStore.initialization.spec.ts` checks retry timing and exhaustion, persistent failures, shared concurrent initialization, health publication, and disposal cancellation. + +This boundary changes which persisted records can be supplied to the reducers, not their lifecycle transitions. The pure shared-store model has no file-name, backup, or filesystem-error states, so it cannot prove this recovery protocol. Its missing-record transitions must not be read as permission to infer deletion from an I/O failure. Existing genuine-deletion reducer semantics remain unchanged. + ## Task cleanup protocol model The umbrella command also runs a separate bounded child model for in-memory abort, disposal, and provider-shutdown ordering. It models cleanup settlement and rejection as environment transitions and makes no filesystem, editor Promise, fairness, or timing-liveness claim. See [Task cleanup protocol model check](./task-cleanup-protocol-model.md). diff --git a/src/core/task-persistence/TaskHistoryStore.ts b/src/core/task-persistence/TaskHistoryStore.ts index fc9f2f5afa..87bf4a019f 100644 --- a/src/core/task-persistence/TaskHistoryStore.ts +++ b/src/core/task-persistence/TaskHistoryStore.ts @@ -8,10 +8,11 @@ import { historyItemSchema, type HistoryItem } from "@roo-code/types" import { GlobalFileNames } from "../../shared/globalFileNames" import { LOCK_STALE_MS, withFileLock } from "../../utils/fileLock" -import { safeWriteJson, removeJsonBackups } from "../../utils/safeWriteJson" +import { safeWriteJson, removeJsonBackups, recoverJsonFile } from "../../utils/safeWriteJson" import { getStorageBasePath } from "../../utils/storage" import { assertValidTransition, settleRejectedCreateSubtaskAction, type HistoryItemStatus } from "./taskLifecycle" import { computeHistoryDelta, DeltaRejectedError, mergeHistoryDelta } from "./taskStoreConcurrency" +import { getErrorCode, readFileWithMissingRetry } from "./readFileWithMissingRetry" export { assertValidTransition, type HistoryItemStatus } from "./taskLifecycle" export { DeltaRejectedError } from "./taskStoreConcurrency" @@ -87,14 +88,26 @@ export class TaskHistoryStore { private fsWatcher: fsSync.FSWatcher | null = null private reconcileTimer: ReturnType | null = null private disposed = false + private initializationPromise: Promise | undefined + private initializationRetryTimer: ReturnType | null = null + private resolveInitializationRetry: (() => void) | undefined + private initializationHealthy = false /** - * Promise that resolves when initialization is complete. - * Callers can await this to ensure the store is ready before reading. + * Resolves after initialization succeeds or ends in terminal failure. + * Check isHealthy to distinguish readiness from an unsuccessful attempt. */ public readonly initialized: Promise private resolveInitialized!: () => void + /** Whether startup completed successfully with a full snapshot. */ + get isHealthy(): boolean { + return this.initializationHealthy + } + + // Six retries cover a stale crash lock without polling aggressively. + private static readonly INITIALIZATION_RETRY_DELAYS_MS = [1_000, 2_000, 4_000, 8_000, 8_000, 8_000] + /** Periodic reconciliation interval in milliseconds. */ private static readonly RECONCILE_INTERVAL_MS = 5 * 60 * 1000 @@ -111,37 +124,72 @@ export class TaskHistoryStore { /** * Scan task files, reconcile delegation state, start watchers. */ - async initialize(): Promise { - try { - const tasksDir = await this.getTasksDir() - await fs.mkdir(tasksDir, { recursive: true }) - - // 1. Scan task directories to populate the cache - await this.reconcile({ forceRefresh: true }) - // Capture which active tasks were present in persisted state before replay can - // change any statuses. Reconciliation must not treat a replay-repaired parent - // as an orphaned active child in the same startup pass. - const persistedActiveIds = this.getPersistedActiveIds() + initialize(): Promise { + if (this.initializationHealthy) return Promise.resolve() + if (!this.initializationPromise) { + this.initializationPromise = this.initializeWithRetry().finally(() => { + this.initializationPromise = undefined + }) + } + return this.initializationPromise + } - // 2. Complete any two-record repair interrupted after its intent was durable. - try { - await this.replayDelegationRepairIntent() - } catch (error) { - console.error("[TaskHistoryStore] Failed to replay delegation repair intent:", error) + private async initializeWithRetry(): Promise { + try { + for (let attempt = 0; ; attempt++) { + try { + if (this.disposed) throw new Error("TaskHistoryStore was disposed during initialization") + await this.initializeAttempt() + if (this.disposed) throw new Error("TaskHistoryStore was disposed during initialization") + this.initializationHealthy = true + return + } catch (error) { + const code = getErrorCode(error) + const delay = TaskHistoryStore.INITIALIZATION_RETRY_DELAYS_MS[attempt] + if (this.disposed || (code !== "ELOCKED" && code !== "EBUSY") || delay === undefined) throw error + console.warn(`[TaskHistoryStore] Initialization failed with ${code}; retrying in ${delay}ms`) + await new Promise((resolve) => { + this.resolveInitializationRetry = resolve + this.initializationRetryTimer = setTimeout(resolve, delay) + }) + this.initializationRetryTimer = null + this.resolveInitializationRetry = undefined + if (this.disposed) throw error + } } + } finally { + // Completion after exhaustion is distinct from a healthy snapshot. + // Activation can continue; callers inspect isHealthy for readiness. + this.resolveInitialized() + } + } - // 3. Repair delegation inconsistencies left by a previous crash - await this.reconcileDelegationState(persistedActiveIds) + private async initializeAttempt(): Promise { + const tasksDir = await this.getTasksDir() + await fs.mkdir(tasksDir, { recursive: true }) - // 4. Start fs.watch for cross-instance reactivity - this.startWatcher() + // 1. Scan task directories to populate the cache + await this.reconcile({ forceRefresh: true }) + // Capture which active tasks were present in persisted state before replay can + // change any statuses. Reconciliation must not treat a replay-repaired parent + // as an orphaned active child in the same startup pass. + const persistedActiveIds = this.getPersistedActiveIds() - // 5. Start periodic reconciliation as a defensive fallback - this.startPeriodicReconciliation() - } finally { - // Mark initialization as complete so callers awaiting `initialized` can proceed - this.resolveInitialized() + // 2. Complete any two-record repair interrupted after its intent was durable. + try { + await this.replayDelegationRepairIntent() + } catch (error) { + console.error("[TaskHistoryStore] Failed to replay delegation repair intent:", error) } + + // 3. Repair delegation inconsistencies left by a previous crash + await this.reconcileDelegationState(persistedActiveIds) + + // 4. Start fs.watch for cross-instance reactivity + this.startWatcher() + + // 5. Start periodic reconciliation as a defensive fallback + this.startPeriodicReconciliation() } /** @@ -149,6 +197,13 @@ export class TaskHistoryStore { */ dispose(): void { this.disposed = true + this.initializationHealthy = false + if (this.initializationRetryTimer) { + clearTimeout(this.initializationRetryTimer) + this.initializationRetryTimer = null + } + this.resolveInitializationRetry?.() + this.resolveInitializationRetry = undefined if (this.reconcileTimer) { clearTimeout(this.reconcileTimer) @@ -343,7 +398,8 @@ export class TaskHistoryStore { let dirEntries: string[] try { dirEntries = await fs.readdir(tasksDir) - } catch { + } catch (error) { + if (getErrorCode(error) !== "ENOENT") throw error return // tasks dir doesn't exist yet } @@ -357,7 +413,11 @@ export class TaskHistoryStore { for (const taskId of onDiskIds) { try { const taskFilePath = await this.getTaskFilePath(taskId) - const { mtimeMs } = await fs.stat(taskFilePath) + const { mtimeMs } = await fs.stat(taskFilePath).catch(async (error: unknown) => { + if (getErrorCode(error) !== "ENOENT") throw error + await recoverJsonFile(taskFilePath) + return fs.stat(taskFilePath) + }) liveIds.add(taskId) if ( !options.forceRefresh && @@ -375,7 +435,10 @@ export class TaskHistoryStore { this.cache.set(taskId, item) } } - } catch { + } catch (error) { + // An unavailable snapshot is not evidence of deletion. In + // particular, startup must not repair delegation from it. + if (getErrorCode(error) !== "ENOENT") throw error // File may be temporarily absent during a peer's atomic // rename window in safeWriteJson. The advisory lock is // held for the entire write, so its presence means a @@ -775,17 +838,14 @@ export class TaskHistoryStore { */ async invalidate(taskId: string): Promise { return this.withLock(async () => { - try { - const item = await this.readTaskFile(taskId) - if (item) { - this.cache.set(taskId, item) - } else { - this.cache.delete(taskId) - } - this.taskFileMtimes.delete(taskId) - } catch { + // A failed read must retain the last known record, not evict it. + const item = await this.readTaskFile(taskId) + if (item) { + this.cache.set(taskId, item) + } else { this.cache.delete(taskId) } + this.taskFileMtimes.delete(taskId) }) } @@ -894,10 +954,11 @@ export class TaskHistoryStore { const filePath = await this.getTaskFilePath(taskId) try { - const raw = await fs.readFile(filePath, "utf8") + const raw = await readFileWithMissingRetry(filePath) const item: HistoryItem = JSON.parse(raw) return item.id ? item : null - } catch { + } catch (error) { + if (!(error instanceof SyntaxError) && getErrorCode(error) !== "ENOENT") throw error return null } } diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts new file mode 100644 index 0000000000..d76dfeccce --- /dev/null +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts @@ -0,0 +1,124 @@ +import * as fs from "fs/promises" +import * as os from "os" +import * as path from "path" + +import { TaskHistoryStore } from "../TaskHistoryStore" + +vi.mock("fs/promises", async () => { + const actual = await vi.importActual("fs/promises") + return { ...actual, readdir: vi.fn(actual.readdir) } +}) +const actual = await vi.importActual("fs/promises") + +describe("TaskHistoryStore initialization retries", () => { + let root: string + let store: TaskHistoryStore + + beforeEach(async () => { + vi.mocked(fs.readdir).mockReset().mockImplementation(actual.readdir) + root = await fs.mkdtemp(path.join(os.tmpdir(), "history-initialization-")) + store = new TaskHistoryStore(root) + vi.useFakeTimers({ toFake: ["setTimeout", "clearTimeout"] }) + }) + + afterEach(async () => { + store.dispose() + vi.useRealTimers() + vi.restoreAllMocks() + await fs.rm(root, { recursive: true, force: true }) + }) + + async function waitForRetry() { + await vi.waitFor(() => expect(store["initializationRetryTimer"]).not.toBeNull()) + } + + it.each(["ELOCKED", "EBUSY"])( + "retries %s without publishing readiness or starting observers early", + async (code) => { + const reconcile = vi + .spyOn(store, "reconcile") + .mockRejectedValueOnce(Object.assign(new Error(code), { code })) + const settled = vi.fn() + void store.initialized.then(settled) + const pending = store.initialize() + expect(store.initialize()).toBe(pending) + await waitForRetry() + expect(store.isHealthy).toBe(false) + expect(settled).not.toHaveBeenCalled() + expect(store["fsWatcher"]).toBeNull() + expect(store["reconcileTimer"]).toBeNull() + expect(vi.getTimerCount()).toBe(1) + + await vi.advanceTimersByTimeAsync(1_000) + await pending + await store.initialized + expect(store.isHealthy).toBe(true) + expect(settled).toHaveBeenCalledTimes(1) + expect(reconcile).toHaveBeenCalledTimes(2) + await vi.waitFor(() => expect(store["fsWatcher"]).not.toBeNull()) + expect(store["reconcileTimer"]).not.toBeNull() + await store.initialize() + expect(reconcile).toHaveBeenCalledTimes(2) + }, + ) + + it.each(["EACCES", "EIO", "EISDIR"])("reports %s as unsuccessful without scheduling retries", async (code) => { + const reconcile = vi.spyOn(store, "reconcile").mockRejectedValueOnce(Object.assign(new Error(code), { code })) + await expect(store.initialize()).rejects.toMatchObject({ code }) + await store.initialized + expect(store.isHealthy).toBe(false) + expect(reconcile).toHaveBeenCalledTimes(1) + expect(vi.getTimerCount()).toBe(0) + expect(store["fsWatcher"]).toBeNull() + }) + + it("does not publish health when listing task directories fails persistently", async () => { + vi.mocked(fs.readdir).mockRejectedValueOnce(Object.assign(new Error("cannot list history"), { code: "EACCES" })) + await expect(store.initialize()).rejects.toMatchObject({ code: "EACCES" }) + await store.initialized + expect(store.isHealthy).toBe(false) + expect(vi.getTimerCount()).toBe(0) + }) + + it("retries a busy directory listing and then loads history normally", async () => { + vi.mocked(fs.readdir).mockRejectedValueOnce(Object.assign(new Error("busy history"), { code: "EBUSY" })) + const pending = store.initialize() + await waitForRetry() + expect(store.isHealthy).toBe(false) + await vi.advanceTimersByTimeAsync(1_000) + await pending + expect(store.isHealthy).toBe(true) + expect(fs.readdir).toHaveBeenCalledTimes(2) + }) + + it("caps backoff at eight seconds and gives up after six retries", async () => { + const error = Object.assign(new Error("busy"), { code: "EBUSY" }) + const reconcile = vi.spyOn(store, "reconcile").mockRejectedValue(error) + const result = store.initialize().catch((caught: unknown) => caught) + await waitForRetry() + for (const [index, delay] of [1_000, 2_000, 4_000, 8_000, 8_000, 8_000].entries()) { + await vi.advanceTimersByTimeAsync(delay) + await vi.waitFor(() => expect(reconcile).toHaveBeenCalledTimes(index + 2)) + if (index < 5) await waitForRetry() + } + expect(await result).toBe(error) + await store.initialized + expect(store.isHealthy).toBe(false) + expect(vi.getTimerCount()).toBe(0) + expect(store["fsWatcher"]).toBeNull() + }) + + it("cancels a pending retry on disposal and settles waiters without reporting health", async () => { + const error = Object.assign(new Error("locked"), { code: "ELOCKED" }) + const reconcile = vi.spyOn(store, "reconcile").mockRejectedValue(error) + const result = store.initialize().catch((caught: unknown) => caught) + await waitForRetry() + store.dispose() + expect(await result).toBe(error) + await store.initialized + await vi.advanceTimersByTimeAsync(60_000) + expect(store.isHealthy).toBe(false) + expect(reconcile).toHaveBeenCalledTimes(1) + expect(vi.getTimerCount()).toBe(0) + }) +}) diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.reconciliation.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.reconciliation.spec.ts index e37fd1a25e..866e27b698 100644 --- a/src/core/task-persistence/__tests__/TaskHistoryStore.reconciliation.spec.ts +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.reconciliation.spec.ts @@ -20,7 +20,10 @@ const writeJson = async (filePath: string, data: unknown): Promise => { const safeWriteJsonMock = vi.hoisted(() => vi.fn()) -vi.mock("../../../utils/safeWriteJson", () => ({ safeWriteJson: safeWriteJsonMock })) +vi.mock("../../../utils/safeWriteJson", async (importOriginal) => ({ + ...(await importOriginal()), + safeWriteJson: safeWriteJsonMock, +})) safeWriteJsonMock.mockImplementation(writeJson) diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts new file mode 100644 index 0000000000..488eadc5cd --- /dev/null +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts @@ -0,0 +1,127 @@ +import * as fs from "fs/promises" +import * as os from "os" +import * as path from "path" + +import type { HistoryItem } from "@roo-code/types" + +import { TaskHistoryStore } from "../TaskHistoryStore" +import { acquireFileLock, LOCK_STALE_MS } from "../../../utils/fileLock" + +vi.mock("fs/promises", async () => { + const actual = await vi.importActual("fs/promises") + return { ...actual, rename: vi.fn(actual.rename) } +}) +const actual = await vi.importActual("fs/promises") +const entryPoints = ["initialize", "reconcile", "invalidate"] as const + +describe("TaskHistoryStore interrupted history recovery", () => { + let root: string + let store: TaskHistoryStore + let parent: HistoryItem + let child: HistoryItem + let canonical: string + let backup: string + let parentPath: string + + beforeEach(async () => { + vi.mocked(fs.rename).mockReset().mockImplementation(actual.rename) + root = await fs.mkdtemp(path.join(os.tmpdir(), "history-recovery-")) + parent = { + id: "parent", + number: 1, + ts: 1, + task: "parent", + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + status: "delegated", + awaitingChildId: "child", + delegatedToId: "child", + childIds: ["child"], + } + child = { + ...parent, + id: "child", + task: "child", + status: "interrupted", + parentTaskId: "parent", + childIds: [], + awaitingChildId: undefined, + delegatedToId: undefined, + } + parentPath = path.join(root, "tasks", "parent", "history_item.json") + canonical = path.join(root, "tasks", "child", "history_item.json") + backup = path.join(path.dirname(canonical), ".history_item.json.bak_interrupted.tmp") + for (const [file, record] of [ + [parentPath, parent], + [canonical, child], + ] as const) { + await fs.mkdir(path.dirname(file), { recursive: true }) + await fs.writeFile(file, JSON.stringify(record)) + } + store = new TaskHistoryStore(root) + }) + + afterEach(async () => { + store.dispose() + vi.restoreAllMocks() + await fs.rm(root, { recursive: true, force: true }) + }) + + async function prepare(entry: (typeof entryPoints)[number]) { + if (entry !== "initialize") await store.initialize() + await fs.rename(canonical, backup) + } + + async function run(entry: (typeof entryPoints)[number]) { + if (entry === "invalidate") await store.invalidate(child.id) + else await store[entry]() + } + + it.each(entryPoints)("restores an orphaned child before %s can treat it as missing", async (entry) => { + await prepare(entry) + await run(entry) + expect(store.get(child.id)).toEqual(child) + expect(store.get(parent.id)).toEqual(parent) + expect(JSON.parse(await fs.readFile(parentPath, "utf8"))).toEqual(parent) + expect(JSON.parse(await fs.readFile(canonical, "utf8"))).toEqual(child) + await expect(fs.access(backup)).rejects.toMatchObject({ code: "ENOENT" }) + }) + + it.each(entryPoints)("fails %s closed when restoring a child fails", async (entry) => { + await prepare(entry) + vi.mocked(fs.rename).mockRejectedValueOnce(Object.assign(new Error("restore failed"), { code: "EIO" })) + await expect(run(entry)).rejects.toMatchObject({ code: "EIO" }) + expect(JSON.parse(await fs.readFile(parentPath, "utf8"))).toEqual(parent) + expect(JSON.parse(await fs.readFile(backup, "utf8"))).toEqual(child) + if (entry !== "initialize") expect(store.get(child.id)).toEqual(child) + }) + + it("retries a locked startup without repairing delegation from a partial snapshot", async () => { + await prepare("initialize") + const release = await acquireFileLock(canonical) + const pending = store.initialize() + try { + await vi.waitFor(() => expect(store["initializationRetryTimer"]).not.toBeNull(), { timeout: 5_000 }) + expect(store.isHealthy).toBe(false) + expect(JSON.parse(await fs.readFile(parentPath, "utf8"))).toEqual(parent) + await expect(fs.access(backup)).resolves.toBeUndefined() + } finally { + await release() + } + await pending + expect(store.isHealthy).toBe(true) + expect(store.get(child.id)).toEqual(child) + expect(store.get(parent.id)).toEqual(parent) + }) + + it("recovers orphaned history after taking over a stale crash lock", async () => { + await prepare("initialize") + await fs.mkdir(`${canonical}.lock`) + const stale = new Date(Date.now() - LOCK_STALE_MS - 2_000) + await fs.utimes(`${canonical}.lock`, stale, stale) + await store.initialize() + expect(store.get(child.id)).toEqual(child) + expect(store.get(parent.id)).toEqual(parent) + }) +}) diff --git a/src/utils/__tests__/safeWriteJson.interruption.test.ts b/src/utils/__tests__/safeWriteJson.interruption.test.ts index 219e68b8d6..a7851ad1cb 100644 --- a/src/utils/__tests__/safeWriteJson.interruption.test.ts +++ b/src/utils/__tests__/safeWriteJson.interruption.test.ts @@ -67,7 +67,7 @@ require(process.env.INTERRUPTION_BUNDLE_PATH) async function waitForChildExit( child: ChildProcess, -): Promise<{ signal: NodeJS.Signals | null; stdout: string; stderr: string }> { +): Promise<{ code: number | null; signal: NodeJS.Signals | null; stdout: string; stderr: string }> { const stdoutChunks: Buffer[] = [] const stderrChunks: Buffer[] = [] child.stdout?.on("data", (chunk: Buffer) => stdoutChunks.push(chunk)) @@ -78,9 +78,10 @@ async function waitForChildExit( reject(new Error("Interruption child did not exit within 20 seconds")) }, 20_000) child.once("error", reject) - child.once("close", (_code, signal) => { + child.once("close", (code, signal) => { clearTimeout(timeout) resolve({ + code, signal, stdout: Buffer.concat(stdoutChunks).toString("utf8"), stderr: Buffer.concat(stderrChunks).toString("utf8"), @@ -148,7 +149,11 @@ describe("safeWriteJson subprocess interruption fault injection", () => { expect(exit.stdout).toContain("EXIT_BEFORE_REPLACEMENT_RENAME") expect(exit.stdout).not.toContain("WRITE_COMPLETED") expect(exit.stderr).not.toContain("WRITE_FAILED") - expect(exit.signal).toBe("SIGKILL") + // A self-kill uses TerminateProcess(..., 1) on Windows, so the + // parent receives exit code 1 without a POSIX signal name. + expect({ code: exit.code, signal: exit.signal }).toEqual( + process.platform === "win32" ? { code: 1, signal: null } : { code: null, signal: "SIGKILL" }, + ) // SIGKILL bypasses proper-lockfile's exit cleanup. A fresh writer // must reject the live-looking lock rather than steal it early. diff --git a/src/utils/__tests__/safeWriteJson.recovery.test.ts b/src/utils/__tests__/safeWriteJson.recovery.test.ts index 7c71d556df..3ac97f06d4 100644 --- a/src/utils/__tests__/safeWriteJson.recovery.test.ts +++ b/src/utils/__tests__/safeWriteJson.recovery.test.ts @@ -166,7 +166,10 @@ describe("interrupted JSON recovery", () => { } }) - it.each([readFileWithMissingRetry, recoverJsonFile])("propagates recovery failures to readers", async (read) => { + it.each([ + { name: "retrying reader", read: readFileWithMissingRetry }, + { name: "recovery helper", read: recoverJsonFile }, + ])("propagates recovery failures through the $name", async ({ read }) => { vi.mocked(fs.rename).mockRejectedValueOnce(ioError("EIO")) await expect(read(canonical)).rejects.toMatchObject({ code: "EIO" }) await expect(fs.access(backup)).resolves.toBeUndefined() From f46cef292bf6b52ca97f4c4fdbb13f401d883e74 Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sat, 24 Oct 2026 04:28:53 +0000 Subject: [PATCH 04/14] fix(persistence): isolate history mocks and log deletion failures --- src/core/task-persistence/TaskHistoryStore.ts | 10 +++--- .../webview/__tests__/ClineProvider.spec.ts | 32 +++++++++++++++---- 2 files changed, 32 insertions(+), 10 deletions(-) diff --git a/src/core/task-persistence/TaskHistoryStore.ts b/src/core/task-persistence/TaskHistoryStore.ts index 87bf4a019f..9b575c8448 100644 --- a/src/core/task-persistence/TaskHistoryStore.ts +++ b/src/core/task-persistence/TaskHistoryStore.ts @@ -339,8 +339,9 @@ export class TaskHistoryStore { await removeJsonBackups(absoluteFilePath) await fs.unlink(absoluteFilePath) }) - } catch { - // File may already be deleted + } catch (error) { + if (getErrorCode(error) !== "ENOENT") + console.warn(`[TaskHistoryStore] Failed to delete task ${taskId}:`, error) } // Call onWrite callback inside the lock for serialized write-through @@ -370,8 +371,9 @@ export class TaskHistoryStore { await removeJsonBackups(absoluteFilePath) await fs.unlink(absoluteFilePath) }) - } catch { - // File may already be deleted + } catch (error) { + if (getErrorCode(error) !== "ENOENT") + console.warn(`[TaskHistoryStore] Failed to delete task ${taskId}:`, error) } } diff --git a/src/core/webview/__tests__/ClineProvider.spec.ts b/src/core/webview/__tests__/ClineProvider.spec.ts index 8112c545a5..73662526f0 100644 --- a/src/core/webview/__tests__/ClineProvider.spec.ts +++ b/src/core/webview/__tests__/ClineProvider.spec.ts @@ -5808,6 +5808,18 @@ describe("ClineProvider - Comprehensive Edit/Delete Edge Cases", () => { }) describe("getTaskWithId", () => { + const apiHistoryPath = path.join("/test/task/path", "api_conversation_history.json") + + beforeEach(async () => { + const fsp = await import("fs/promises") + vi.mocked(fsp.readFile).mockReset().mockResolvedValue("") + }) + + afterEach(async () => { + const fsp = await import("fs/promises") + vi.mocked(fsp.readFile).mockReset().mockResolvedValue("") + }) + it("does not restore a deleted file-backed task from legacy history", async () => { const historyItem = { id: "deleted-task", @@ -5864,12 +5876,15 @@ describe("ClineProvider - Comprehensive Edit/Delete Edge Cases", () => { const fsp = await import("fs/promises") const missing = Object.assign(new Error("missing"), { code: "ENOENT" }) const messages = [{ role: "user", content: "committed" }] - vi.mocked(fsp.readFile) - .mockRejectedValueOnce(missing) - .mockRejectedValueOnce(missing) - .mockResolvedValueOnce(JSON.stringify(messages)) + let historyReads = 0 + vi.mocked(fsp.readFile).mockImplementation(async (filePath) => { + if (filePath !== apiHistoryPath) return "" + if (++historyReads <= 2) throw missing + return JSON.stringify(messages) + }) const result = await provider.getTaskWithId(historyItem.id) expect(result.apiConversationHistory).toEqual(messages) + expect(historyReads).toBe(3) expect(recoverJsonFile).toHaveBeenCalledWith(result.apiConversationHistoryFilePath) }) @@ -5879,7 +5894,10 @@ describe("ClineProvider - Comprehensive Edit/Delete Edge Cases", () => { key === "taskHistory" ? [historyItem] : undefined, ) const fsp = await import("fs/promises") - vi.mocked(fsp.readFile).mockRejectedValueOnce(Object.assign(new Error(code), { code })) + vi.mocked(fsp.readFile).mockImplementation(async (filePath) => { + if (filePath === apiHistoryPath) throw Object.assign(new Error(code), { code }) + return "" + }) await expect(provider.getTaskWithId(historyItem.id)).rejects.toMatchObject({ code }) }) @@ -5894,7 +5912,9 @@ describe("ClineProvider - Comprehensive Edit/Delete Edge Cases", () => { // Make readFile return corrupted JSON const fsp = await import("fs/promises") - vi.mocked(fsp.readFile).mockResolvedValueOnce("{not valid json!!!" as never) + vi.mocked(fsp.readFile).mockImplementation(async (filePath) => + filePath === apiHistoryPath ? "{not valid json!!!" : "", + ) const deleteTaskSpy = vi.spyOn(provider, "deleteTaskFromState") From 8699afdec534c7ccb56e4803efe4bfe887f58b8d Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sat, 24 Oct 2026 14:28:16 +0000 Subject: [PATCH 05/14] docs(persistence): simplify JSON contract and caller inventory --- docs/architecture/json-persistence-audit.md | 176 ++++++++++++++++---- docs/architecture/task-lifecycle-model.md | 39 ++++- 2 files changed, 178 insertions(+), 37 deletions(-) diff --git a/docs/architecture/json-persistence-audit.md b/docs/architecture/json-persistence-audit.md index f7a9564a9a..bcfc3b37d8 100644 --- a/docs/architecture/json-persistence-audit.md +++ b/docs/architecture/json-persistence-audit.md @@ -1,54 +1,162 @@ -# JSON persistence audit for PR #2136 +# JSON persistence contract and caller inventory -This is a source audit of the working tree, not a claim of power-loss durability or exhaustive filesystem fault testing. There are 19 executable `safeWriteJson` calls in 10 consumer files; the earlier review's count of 11 sibling callers did not identify its counting unit. Tests, the writer declaration, and the built-in command's textual example are excluded. +Update this file when you add a `safeWriteJson` caller. + +The canonical file is the committed JSON file. +A backup file contains the previous committed data. +This contract covers the shared JSON writer and its consumers. +It does not guarantee recovery after power loss. + +## Find callers + +Run this command from the repository root: + +```sh +rg -n 'safeWriteJson\(' src --glob '!**/__tests__/**' +``` + +The results also include the function declaration and text examples. ## Shared contract -Every call acquires the canonical file's advisory lock before recovery, merge, streaming, or replacement. Recovery only interprets ENOENT as absence. A failed restore or rollback retains committed backups. No fsync or durability option remains; replacement protects against process interruption, not arbitrary power loss. Read recovery checks for a matching backup before acquiring the same lock and rechecks the filesystem under it. +- The writer takes the canonical file's advisory lock before recovery, merge, write, or replacement. +- Recovery treats only `ENOENT` as a missing file. +- A failed backup restore stops the write. +- A failed restore or rollback keeps the committed backup. +- The normal commit uses one rename operation. +- The Windows `EPERM` fallback uses two rename operations. +- The writer does not call `fsync`. +- Read recovery searches for a matching backup before it takes the file lock. +- Read recovery checks the canonical file and backups again under that lock. + +A fresh lock can belong to a paused writer. +The protocol does not remove that lock before the stale interval expires. +The stale interval is 31 seconds. +Lock acquisition also has its own retries. +See [fileLock.ts](../../src/utils/fileLock.ts) for the lock configuration. + +See [History-file availability](task-lifecycle-model.md#history-file-availability-boundary) for initialization retries and health state. + +## Failure reports + +A rejected recovery attempt emits `json-recovery-failed` through the shared trace sink. +The event includes the canonical path, process ID, timestamp, and error code. +The event does not include file contents. +UI-message writes also emit task-specific events. +A trace sink failure does not replace the filesystem error. + +Leftover-file cleanup errors go to the console. +These errors do not reject a write that otherwise succeeded. + +## Consumers + +The paths below start at `src/`. +Each consumer uses the shared writer's recovery and lock protocol. +Its read path can have different behavior. + +### `api/providers/fetchers/modelEndpointCache.ts` + +- Replaces the endpoint cache with fetched data. +- Reads the canonical file directly. +- Fetches data again when the cache is missing. +- Returns write errors to the cache refresh handler. + +### `api/providers/fetchers/modelCache.ts` + +- Replaces the model cache with fetched data. +- Includes a synchronous reader for the canonical file. +- Fetches data again when the cache is missing. +- Logs refresh write errors. + +### `services/mcp/McpHub.ts` + +- Creates global settings with a merge that preserves existing settings. +- Preserves settings restored from a backup during creation. +- Reads settings before it takes the write lock for other changes. +- Can lose a concurrent change during these read-modify-write operations. +- This transaction gap is tracked in [#2173](https://github.com/Zoo-Code-Org/Zoo-Code/issues/2173). + +### `services/code-index/cache-manager.ts` + +- Saves or clears the file-hash cache. +- Reads through the VS Code filesystem API. +- Rebuilds the cache when the file is missing. +- Logs write errors and emits telemetry. + +### `core/config/importExport.ts` + +- Writes a settings snapshot to the file that the user selects. +- Reads the selected import file directly. +- Logs export errors. + +### `core/webview/webviewMessageHandler.ts` + +- Creates project MCP settings when the canonical file appears absent. +- Can replace restored settings with defaults during creation. +- This creation gap is tracked in [#2175](https://github.com/Zoo-Code-Org/Zoo-Code/issues/2175). + +### `core/task-persistence/taskMessages.ts` -All rejected recovery attempts, including read-side lock acquisition and directory inspection failures, emit `json-recovery-failed` with the canonical path, process ID, timestamp, and error code through the shared persistence trace sink. UI-message writes additionally retain their task-specific stage callbacks. Sink exceptions cannot replace the filesystem error. This trace does not log file contents. Best-effort leftover-unlink failures still use the existing console error logging and do not reject an otherwise successful recovery. +- Saves UI messages, with an optional snapshot merge. +- Uses read retries and backup recovery. +- Emits task-specific write events. +- Returns save errors to the Task save helper, which logs them. -A fresh-looking lock left by SIGKILL still rejects a writer or a reader attempting backup recovery with ELOCKED after the configured retries. This is intentional: lock freshness cannot distinguish a dead process from a paused owner. The subprocess test verifies rejection, backup preservation, and recovery after aging the lock past `LOCK_STALE_MS` (31 seconds). It does not wait 31 real seconds or establish Windows filesystem semantics. +### `core/task-persistence/apiMessages.ts` -## Initialization availability +- Saves API messages, with an optional snapshot merge. +- Uses backup recovery for current and legacy history reads. +- Returns an empty history only when both history files are missing. +- Throws other read errors. +- Deletes legacy history only after it saves the new file. -Initialization retries transient `ELOCKED` and `EBUSY` failures with one timeout chain: delays of 1, 2, 4, 8, 8, and 8 seconds, after which the final error is returned. Concurrent calls share the same initialization promise, and disposal cancels a pending retry. Each attempt reruns the scan and startup sequence; delegation repair cannot run after a failed scan. Permanent errors such as EACCES or EIO are not retried. +### `core/task-persistence/TaskHistoryStore.ts` -`initialized` resolves after success or terminal failure, not between transient attempts. `isHealthy` is true only after the startup sequence succeeds; it stays false after exhaustion or persistent failure. The provider's existing awaited initialization resumes migration on eventual success. The existing activation catch still logs terminal errors and allows extension activation to continue. +- Writes task history, repair intents, merged changes, and conditional action settlement. +- Recovers missing history files during reconciliation and individual reads. +- Blocks delegation repair when the history scan fails. +- Keeps cached records when a refresh fails. +- Removes backups under the file lock before it deletes canonical history. +- Logs deletion errors other than `ENOENT`. +- Reads repair intents directly from the canonical path. +- The repair-intent recovery gap is tracked in [#2176](https://github.com/Zoo-Code-Org/Zoo-Code/issues/2176). -Follow-up work, outside this PR: show a persistent-error warning and offer an explicit user retry action. There is no new UI action here. After a persistent error or exhaustion, history can remain partial and observers have not been started. The separate health flag makes that outcome distinguishable from successful initialization; it does not itself provide a user-facing warning. +### `core/context-tracking/FileContextTracker.ts` -## Consumer inventory +- Saves file-context metadata. +- Returns an empty context when the canonical file appears absent. +- Does not recover metadata backups during reads. +- Logs save errors. +- The metadata recovery gap is tracked in [#2177](https://github.com/Zoo-Code-Org/Zoo-Code/issues/2177). -Paths in this table are relative to `src/`. +## Other readers and write paths -| Consumer | Calls | Data and semantics | Error/read behavior | -| ---------------------------------------------- | ----: | ---------------------------------------------------------------------------------------------------------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `api/providers/fetchers/modelEndpointCache.ts` | 1 | Replace fetched endpoint cache | Disk reader checks existence; cache can be refetched. Writer rejection propagates to cache refresh handling. | -| `api/providers/fetchers/modelCache.ts` | 1 | Replace fetched model cache | Includes a synchronous disk reader; missing cache can be refetched. Refresh paths catch/log write failures. | -| `services/mcp/McpHub.ts` | 4 | Create global settings with a preserving merge; replace settings for updates, removal, and tool configuration | Creation preserves recovered settings. Other operations read before entering the writer's lock; their entire read-modify-write is not made atomic by this PR. | -| `services/code-index/cache-manager.ts` | 2 | Save or clear file hashes | Initialization uses VS Code filesystem reads and resets a missing cache; writes catch/log and emit telemetry. Hashes are rebuildable. | -| `core/config/importExport.ts` | 1 | Replace a user-selected settings export | Export catches/logs failures. Import reads the selected canonical file directly. | -| `core/webview/webviewMessageHandler.ts` | 1 | Initialize project MCP settings when the canonical file appears absent | Uses an existence check and blind default write. An orphaned backup can be restored and then replaced by defaults. This is a remaining initialization gap, not covered by task-message recovery tests. | -| `core/task-persistence/taskMessages.ts` | 1 | Save UI messages; optional snapshot merge | Reads use missing-file retry and backup recovery. Save failures propagate to Task, whose existing save helper catches them. Adds task-specific write traces. | -| `core/task-persistence/apiMessages.ts` | 2 | Migrate legacy history with merge; save API messages with optional merge | Current and legacy readers use recovery. Genuine absence maps to no history; other I/O failures throw. Migration removes the legacy source only after the write succeeds. | -| `core/task-persistence/TaskHistoryStore.ts` | 5 | Repair intent; legacy migration; history delta merge; authoritative replacement; conditional pending-action settlement | Deletion removes backups under the same file lock. Settlement rejects missing disk state. History reconcile and individual reads recover absent canonical files; failed recovery blocks delegation repair; transient initialization failures are retried and preserves cached records on refresh. Repair-intent reads still read the canonical path directly. | -| `core/context-tracking/FileContextTracker.ts` | 1 | Replace task file-context metadata | Reads check canonical existence and otherwise return an empty context. Saves catch/log failures. Read-side backup healing is not provided here. | +`ClineProvider.getTaskWithId` reads API history through the recovery reader. +It returns an empty history for `SyntaxError` or `ENOENT`. +It throws other read errors. +Task loading and parent reopening also use the message readers. +These read paths do not already hold the same file lock. +Provider delegation locks and store mutexes are separate locks. -`ClineProvider.getTaskWithId` is an additional API-history reader, not a writer. It now uses the recovery reader. SyntaxError and ENOENT retain their previous empty-history behavior; other filesystem/recovery failures propagate. Task loading and parent reopening also use the message readers. The advisory-file-lock owners are the JSON writer/recovery and history deletion; the inspected call paths do not invoke message recovery while already holding the same file lock. Provider delegation locks and store host mutexes are distinct from that file lock. +Task-history import copies files into a private staging directory. +It validates `history_item.json` before it renames the directory into place. +This directory publication uses a separate protocol. -## Writes outside the shared protocol +Repair-intent quarantine and removal use rename or unlink operations. +These operations do not replace JSON content. -The production source scan covered `src/`, `packages/`, and `apps/cli`, excluding tests, generated output, dependencies, and fixtures. These paths do not acquire protection merely because other writes use `safeWriteJson`: +`services/marketplace/SimpleInstaller.ts` changes MCP settings with direct file writes. +It does not share the JSON writer's lock. +This writer gap is tracked in [#2174](https://github.com/Zoo-Code-Org/Zoo-Code/issues/2174). -- Task-history import copies files into a unique staging directory, validates `history_item.json`, and promotes the directory by rename. It does not rewrite existing canonical message files through the JSON writer. Its directory-level publication protocol is separate. -- TaskHistoryStore also renames repair intents into quarantine and unlinks completed intents. These are removal/quarantine operations, not JSON replacements. -- `services/marketplace/SimpleInstaller.ts` writes and removes MCP entries with direct JSON file writes to project/global MCP settings. It can share files with McpHub and is outside its advisory-lock protocol. Concurrent marketplace/McpHub updates and interruption safety need separate work. -- Qwen credential refresh writes its credentials JSON directly. The CLI's VS Code shim writes Memento and SecretStorage JSON synchronously. None of these writes gains crash recovery from this PR. -- Other direct writes found are workspace edits, generated images, YAML modes and settings migration, rule/skill installation, exported markdown, logs, shell scripts, terminal artifacts, managed-binary staging, build output, and test/coverage tooling. The scan found no additional direct production replacement of `ui_messages.json`, `api_conversation_history.json`, or `history_item.json` outside task-history import's staging protocol. +Workspace edits, credential files, and CLI state use other write paths. +This contract does not cover those paths. -## Validation and limits +## Validation limits -Focused tests cover failed recovery/rollback, filesystem errors, backup ordering, neighboring files, missing-file reads, fresh-lock rejection, stale-lock takeover, trace delivery, and history deletion. The existing real-window restart E2E additionally moves UI/API histories to orphaned backups in a fresh extension host before resume and requires public reads to restore their exact bytes. +The [writer tests](../../src/utils/__tests__/safeWriteJson.recovery.test.ts) cover restore failures, backup selection, read recovery, and error reports. +The [subprocess tests](../../src/utils/__tests__/safeWriteJson.interruption.test.ts) cover forced termination, fresh locks, and stale-lock recovery. +The [restart E2E test](../../apps/vscode-e2e/src/suite/restart-persistence.test.ts) checks recovery through a fresh extension host. -The E2E runner and CI workflow inspected run VS Code on Linux. That is real extension-host/window coverage, not evidence for Windows open-handle rename behavior. The Windows EPERM branch is fault-injected in unit/subprocess tests. The remaining repair-intent/metadata reader and MCP-writer gaps above are explicitly outside the verified UI/API history contract. +Injected `EPERM` failures do not prove native Windows behavior. +Native Windows open-handle checks are tracked in [#2178](https://github.com/Zoo-Code-Org/Zoo-Code/issues/2178). diff --git a/docs/architecture/task-lifecycle-model.md b/docs/architecture/task-lifecycle-model.md index 360390aea9..c8486ea315 100644 --- a/docs/architecture/task-lifecycle-model.md +++ b/docs/architecture/task-lifecycle-model.md @@ -90,9 +90,42 @@ The known-unsafe witnesses currently compare exact shortest action sequences. Th ## History-file availability boundary -Before startup delegation repair runs, `TaskHistoryStore.reconcile()` recovers an absent canonical history file from its interrupted-write backup under the file lock. Recovery failures prevent reducers from treating an unreadable child as missing; refresh failures retain the last cached record. Startup retries ELOCKED/EBUSY through one capped timeout chain and repeats the full scan before repair. The `initialized` promise settles only after success or terminal failure; `isHealthy` distinguishes these outcomes. `TaskHistoryStore.recovery.spec.ts` checks startup, reconciliation, invalidation, failed restore, fresh locks, and stale-lock takeover with real temporary files. `TaskHistoryStore.initialization.spec.ts` checks retry timing and exhaustion, persistent failures, shared concurrent initialization, health publication, and disposal cancellation. - -This boundary changes which persisted records can be supplied to the reducers, not their lifecycle transitions. The pure shared-store model has no file-name, backup, or filesystem-error states, so it cannot prove this recovery protocol. Its missing-record transitions must not be read as permission to infer deletion from an I/O failure. Existing genuine-deletion reducer semantics remain unchanged. +`TaskHistoryStore.reconcile()` recovers a missing canonical history file from its backup under the file lock. +A failed scan blocks delegation repair. +A failed refresh keeps the last cached record. + +### Initialization and availability + +Initialization retries only `ELOCKED` and `EBUSY`. +It uses one timeout chain with delays of 1, 2, 4, 8, 8, and 8 seconds. +Each retry repeats the full scan before delegation repair. +Lock acquisition has separate retries, which add time to this sequence. + +Concurrent `initialize()` calls share one promise. +A healthy store does not repeat initialization. +Disposal cancels a pending retry. + +`initialize()` rejects after a persistent error or exhausted retries. +The provider therefore skips legacy migration after initialization failure. +`initialized` resolves after success or terminal failure. +`isHealthy` is true only after a successful attempt. + +Activation can continue after terminal failure. +The cache can remain incomplete, and observers do not start. +The provider logs the error. +A persistent warning and manual retry action are tracked in [#2179](https://github.com/Zoo-Code-Org/Zoo-Code/issues/2179). + +### Tests and model limits + +`TaskHistoryStore.recovery.spec.ts` checks startup, reconciliation, invalidation, failed restores, fresh locks, and stale-lock recovery. +`TaskHistoryStore.initialization.spec.ts` checks retries, persistent failures, shared initialization, health state, and disposal. +These tests use temporary files or controlled timers. + +This boundary controls which records reach the lifecycle reducers. +It does not change their transitions. +The pure shared-store model does not represent filenames, backups, or filesystem errors. +A failed read is not evidence of deletion. +The filesystem tests cover this distinction. ## Task cleanup protocol model From 1027320645655b7f4893283474715a13441db015 Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sat, 24 Oct 2026 15:17:51 +0000 Subject: [PATCH 06/14] test(persistence): add parallel JSON crash-point checks --- docs/architecture/task-lifecycle-model.md | 68 +++- package.json | 3 +- scripts/check-json-replacement.test.ts | 33 ++ scripts/check-json-replacement.ts | 443 ++++++++++++++++++++++ src/utils/safeWriteJson.ts | 5 +- 5 files changed, 546 insertions(+), 6 deletions(-) create mode 100644 scripts/check-json-replacement.test.ts create mode 100644 scripts/check-json-replacement.ts diff --git a/docs/architecture/task-lifecycle-model.md b/docs/architecture/task-lifecycle-model.md index c8486ea315..f674bcdaa2 100644 --- a/docs/architecture/task-lifecycle-model.md +++ b/docs/architecture/task-lifecycle-model.md @@ -6,7 +6,7 @@ Zoo Code checks task lifecycle protocols through one umbrella command for indepe pnpm lifecycle:model-check ``` -The baseline command runs eight independent bounded checks in sequence: +The baseline command runs nine independent bounded checks in sequence: 1. the persisted task delegation lifecycle; 2. shared-store concurrency across task-history hosts; @@ -14,8 +14,9 @@ The baseline command runs eight independent bounded checks in sequence: 4. the task cleanup protocol; 5. request-stream parser scoping; 6. completion persistence; -7. delegated-mode reader refinement; and -8. tool-turn continuation. +7. delegated-mode reader refinement; +8. tool-turn continuation; and +9. production JSON replacement crash points. The planned two-sibling fan-out protocol is intentionally outside the baseline and CI umbrella. Run it explicitly with `pnpm fanout-protocol:model-check`; it describes optional future functionality, not current production coverage. @@ -301,3 +302,64 @@ Parser request scoping is one such independent bounded submodel within the umbre Keep reducer permutations in this model and focused Vitest suites. The real VS Code extension-host suite using a mocked provider in `apps/vscode-e2e/src/suite/subtasks.test.ts` already covers the boundaries the pure explorer cannot: task creation and rehydration, persisted parent-child state, cancellation during a delayed provider stream, interrupted-child resume, abandonment followed by a real resume/save/completion cycle, pending approvals across leave/return, and scheduler-driven resume. `restart-persistence.test.ts` separately verifies completion history through a fresh extension host. Add E2E coverage only when a lifecycle change crosses one of those runtime boundaries or introduces a new one. For example, #1453 persistence-readiness semantics require a controlled fresh-host test, and #369/#372 fan-out requires scheduler permit, live-parent routing, orphan cleanup, and task-scoping E2E. Do not add E2E cases solely to replay reducer orderings already exhausted here; they increase fixture and timing cost without strengthening the proof claim. + +## JSON replacement crash points + +Run `pnpm json-replacement:model-check` for the production-backed filesystem check. +The umbrella command also runs this check and its three negative controls. +This check enumerates call boundaries, rather than actor interleavings. + +The harness bundles production code and runs it in child processes against real temporary directories. +It patches filesystem calls to record boundaries and inject faults. +It substitutes only the VS Code storage-path adapter. +It does not add a production injection interface or copy the replacement protocol. + +| Scenario or follow-up | Production function | +| ---------------------------------------------------------- | ------------------------------------------------- | +| Normal, EPERM fallback, rollback, or orphaned-backup write | `safeWriteJson` | +| Missing or newer-canonical read | `readFileWithMissingRetry` and `recoverJsonFile` | +| Delete followed by recovery read | `TaskHistoryStore.delete` and `removeJsonBackups` | +| Cold initialization and repair guard | `TaskHistoryStore.initialize` and `reconcile` | + +Each scenario starts with a committed child record and its parent. +Some scenarios also contain an orphaned backup and an incomplete replacement. +The baseline records stream, filesystem, and advisory-lock calls. +Each recorded call gets a SIGKILL before and after it. +Each call also gets one injected EPERM, EBUSY, EACCES, or EIO error. +Each resulting state gets four isolated follow-ups: read, write, delete, and cold initialization. +A bounded pool runs four cases concurrently by default. +Set `JSON_REPLACEMENT_WORKERS` to an integer from 1 to 8 to change the pool size. +Each case uses its own directory and child processes. +After a failure, the pool stops new cases and waits for active cases before cleanup. +It reports the earliest failing case in enumeration order. +The harness ages leftover locks before those follow-ups. +It therefore checks recovery after the stale interval, rather than fresh-lock availability. + +The checker observes canonical and backup bytes at each boundary. +The newest complete committed value must remain available until replacement. +A successful write must publish the incoming value. +Recovery must return complete committed bytes. +A reader must preserve an existing canonical value. +Deletion followed by recovery must leave the child absent. +Failed initialization must not enter delegation repair. +Successful cold initialization must report a healthy store. + +A successful rename can publish a new value before the write promise resolves. +The checker treats that value as committed. +Deletion follow-ups run without injected faults. +The best-effort delete API can resolve after an I/O failure; this check does not strengthen that contract. + +The bounds are seven baseline scenarios, 128 filesystem calls per execution, and 2,000 injected cases. +Budget exhaustion fails the command. +A violation prints the observed trace through the first failing boundary. +This prefix is replayable, but it is not a shortest interleaving counterexample. +Three source mutations must fail with their named invariants: + +- Swallowing a failed backup restore must violate backup preservation, invariant 2. +- Omitting backup removal from deletion must violate no resurrection, invariant 4. +- Ignoring an existing canonical file during reader recovery must violate reader preservation, invariant 6. + +Coverage excludes concurrent actors, stale takeover of a paused owner, and crashes inside fault-induced rollback paths. +It also excludes native Windows open-handle semantics and power-loss durability. +The existing subprocess SIGKILL tests and extension-host restart tests remain separate checks. +See the [JSON persistence contract](./json-persistence-audit.md) for caller coverage and remaining gaps. diff --git a/package.json b/package.json index cff60a205b..2c48751b81 100644 --- a/package.json +++ b/package.json @@ -20,7 +20,8 @@ "test:agent-evals:unit": "node --import tsx --test scripts/agent-evals/*.test.ts", "agent-evals:check-types": "tsc -p scripts/agent-evals/tsconfig.json", "test:mutation-ci": "node --test scripts/stryker-diff.test.mjs", - "lifecycle:model-check": "tsx scripts/check-task-lifecycle.ts && tsx scripts/check-task-store-concurrency.ts && tsx scripts/check-provider-handoff-scheduler.ts && pnpm cleanup-protocol:model-check && pnpm parser-scope:model-check && tsx scripts/check-completion-persistence.ts && tsx scripts/check-delegated-mode-readers.ts && pnpm tool-turn:model-check", + "lifecycle:model-check": "tsx scripts/check-task-lifecycle.ts && tsx scripts/check-task-store-concurrency.ts && tsx scripts/check-provider-handoff-scheduler.ts && pnpm cleanup-protocol:model-check && pnpm parser-scope:model-check && tsx scripts/check-completion-persistence.ts && tsx scripts/check-delegated-mode-readers.ts && pnpm tool-turn:model-check && pnpm json-replacement:model-check", + "json-replacement:model-check": "tsx scripts/check-json-replacement.ts && node --import tsx --test scripts/check-json-replacement.test.ts", "fanout-protocol:model-check": "tsx scripts/check-task-fanout-protocol.ts", "cleanup-protocol:model-check": "tsx scripts/check-task-cleanup-protocol.ts", "tool-turn:model-check": "tsx scripts/check-tool-turn-continuation.ts", diff --git a/scripts/check-json-replacement.test.ts b/scripts/check-json-replacement.test.ts new file mode 100644 index 0000000000..8c928555d6 --- /dev/null +++ b/scripts/check-json-replacement.test.ts @@ -0,0 +1,33 @@ +import assert from "node:assert/strict" +import { spawnSync } from "node:child_process" +import { test } from "node:test" + +for (const [mutation, invariant] of [ + ["restore-backup-loss", 2], + ["delete-keeps-backup", 4], + ["reader-overwrites-newer", 6], +] as const) { + test(`checker rejects ${mutation} with invariant ${invariant}`, () => { + const result = spawnSync( + process.execPath, + ["--import", "tsx", "scripts/check-json-replacement.ts", `--mutation=${mutation}`], + { encoding: "utf8", timeout: 30_000 }, + ) + assert.ifError(result.error) + assert.equal(result.status, 1, result.stderr) + assert.match(result.stderr, new RegExp(`JSON replacement invariant ${invariant}:`)) + }) +} + +for (const workers of ["0", "9", "1.5", "invalid"]) { + test(`checker rejects invalid worker count ${workers}`, () => { + const result = spawnSync(process.execPath, ["--import", "tsx", "scripts/check-json-replacement.ts"], { + encoding: "utf8", + timeout: 30_000, + env: { ...process.env, JSON_REPLACEMENT_WORKERS: workers }, + }) + assert.ifError(result.error) + assert.equal(result.status, 1, result.stderr) + assert.match(result.stderr, /JSON_REPLACEMENT_WORKERS must be an integer from 1 to 8/) + }) +} diff --git a/scripts/check-json-replacement.ts b/scripts/check-json-replacement.ts new file mode 100644 index 0000000000..8dc2f403b4 --- /dev/null +++ b/scripts/check-json-replacement.ts @@ -0,0 +1,443 @@ +import assert from "node:assert/strict" +import * as fs from "node:fs" +import * as os from "node:os" +import * as path from "node:path" +import { execFile } from "node:child_process" +import { build } from "esbuild" + +// Real filesystem fallback: no production injection seam. Each cut kills a fresh +// process, so exception cleanup cannot masquerade as process-crash recovery. +const ROOT = process.cwd() +const MAX_STEPS = 128 +const MAX_CASES = 2_000 +const modes = ["write", "fallback", "rollback", "restore", "read", "newer", "cold"] as const +type Mode = (typeof modes)[number] +type Fault = { step: number; kind: "before" | "after" | "EPERM" | "EBUSY" | "EACCES" | "EIO" } +type Event = { n: number; phase: string; call: string; paths: string[]; copies: string[]; code?: string } +type Result = { op: string; ok: boolean; code?: string; value?: string; repairRuns: number; healthy?: boolean } + +const CHILD = String.raw` +const fs = require("fs"), fsp = require("fs/promises"), path = require("path") +const native = { ...fsp }, emit = (data) => fs.writeSync(1, JSON.stringify(data) + "\n") +let root = process.env.CHECK_ROOT, fault = JSON.parse(process.env.CHECK_FAULT || "null"), count = 0, forced = false, rolledBack = false, observing = true, pending = 0 +const canonical = () => path.join(root, "tasks", "child", "history_item.json") +const normalize = (p) => typeof p === "string" ? path.relative(root, p).replace(/\\/g, "/").replace(/\.(new|bak)_[^.]+\.tmp/g, ".$1.tmp") : "" +function copies() { + const dir = path.dirname(canonical()) + return fs.readdirSync(dir).filter((name) => name === "history_item.json" || (name.startsWith(".history_item.json.bak_") && name.endsWith(".tmp"))).map((name) => fs.readFileSync(path.join(dir, name), "utf8")) +} +console.error = console.warn = console.log = () => {} +Math.random = () => 0.5 +function cut(n, phase) { + if (fault && fault.step === n && fault.kind === phase) { + emit({ crash: true }); process.kill(process.pid, "SIGKILL") + } +} +function before(call, args) { + if (!observing) return { n: 0 } + const n = ++count + if (n > Number(process.env.CHECK_MAX_STEPS)) throw new Error("Filesystem-step budget exhausted") + emit({ n, phase: "before", call, copies: copies(), paths: args.filter((p) => typeof p === "string").slice(0, 2).map(normalize) }) + cut(n, "before") + let code = fault && fault.step === n && !["before", "after"].includes(fault.kind) ? fault.kind : undefined + if (!code && ["fallback", "rollback"].includes(process.env.CHECK_MODE) && call === "rename" && args[1] === canonical() && String(args[0]).includes(".new_")) { + if (!forced) { forced = true; code = "EPERM" } + else if (process.env.CHECK_MODE === "rollback" && !rolledBack) { rolledBack = true; code = "EIO" } + } + return { n, error: code && Object.assign(new Error("injected " + code), { code }) } +} +function after(n, call, error) { + if (!n) return + emit({ n, phase: "after", call, copies: copies(), paths: [], code: error && error.code }) + cut(n, "after") +} +for (const name of ["mkdir", "access", "readdir", "stat", "readFile", "rename", "unlink"]) { + fsp[name] = async (...args) => { + const { n, error } = before(name, args) + try { if (error) throw error; const value = await native[name](...args); after(n, name); return value } + catch (error) { after(n, name, error); throw error } + } +} +function callbacks(names, prefix) { + const result = { ...fs } + for (const name of names) result[name] = (...args) => { + const callback = args.pop(), { n, error } = before(prefix + name, args) + if (error) { after(n, prefix + name, error); return callback(error) } + pending++ + return fs[name](...args, (error, ...values) => { pending--; after(n, prefix + name, error); callback(error, ...values) }) + } + return result +} +const streamFs = callbacks(["open", "write", "writev", "close"], "stream.") +const createStream = fs.createWriteStream +fs.createWriteStream = (file, options) => createStream(file, { ...options, fs: streamFs }) +const lock = require("proper-lockfile"), acquire = lock.lock +lock.lock = (file, options) => acquire(file, { ...options, fs: callbacks(["mkdir", "rmdir", "stat", "utimes"], "lock.") }) +const production = require(process.env.CHECK_BUNDLE) +async function operation(op) { + let store, repairRuns = 0, value + try { + if (["write", "fallback", "rollback", "restore"].includes(op)) { + await production.safeWriteJson(canonical(), JSON.parse(process.env.CHECK_INCOMING)) + value = await native.readFile(canonical(), "utf8") + } + else if (["read", "newer", "newer-recovery"].includes(op)) { + if (op === "newer-recovery") await production.recoverJsonFile(canonical()) + value = await production.readFileWithMissingRetry(canonical()) + } + else { + store = new production.TaskHistoryStore(root) + const repair = store.reconcileDelegationState.bind(store) + store.reconcileDelegationState = (...args) => { repairRuns++; return repair(...args) } + if (op === "delete") { + await store.delete("child") + try { value = await production.readFileWithMissingRetry(canonical()) } catch (error) { if (error.code !== "ENOENT") throw error } + } else { + await store.initialize() + value = JSON.stringify(store.get("child")) + } + } + return { op, ok: true, value, repairRuns, healthy: store && store.isHealthy } + } catch (error) { return { op, ok: false, code: error.code, repairRuns } } + finally { if (store) store.dispose() } +} +async function ageLocks(dir) { + for (const entry of await native.readdir(dir, { withFileTypes: true })) { + const full = path.join(dir, entry.name) + if (!entry.isDirectory()) continue + if (entry.name.endsWith(".lock")) { + const old = new Date(Date.now() - 33000); await native.utimes(full, old, old) + } else await ageLocks(full) + } +} +async function run() { + if (process.env.CHECK_MODE !== "followups") return emit({ result: await operation(process.env.CHECK_MODE) }) + const source = root + for (const op of ["read", "write", "delete", "cold"]) { + root = path.join(path.dirname(source), "followup-" + op) + observing = false + await native.cp(source, root, { recursive: true }); await ageLocks(root) + observing = true + count = 0; fault = null + emit({ result: await operation(op) }) + } +} +run().then(async () => { while (pending) await new Promise((resolve) => setTimeout(resolve, 1)); process.exit(0) }).catch((error) => { emit({ harnessError: String(error.stack) }); process.exit(2) }) +` + +function value(cost: number) { + return { + id: "child", + number: 1, + ts: 1, + task: "child", + tokensIn: 0, + tokensOut: 0, + totalCost: cost, + status: "interrupted", + parentTaskId: "parent", + childIds: [], + } +} +const encoded = [JSON.stringify(value(0)), JSON.stringify(value(1)), JSON.stringify(value(2))] as const +const relativeCanonical = path.join("tasks", "child", "history_item.json") +function seed(root: string, mode: Mode | "delete") { + fs.mkdirSync(path.join(root, "tasks", "child"), { recursive: true }) + fs.mkdirSync(path.join(root, "tasks", "parent"), { recursive: true }) + fs.writeFileSync( + path.join(root, "tasks", "parent", "history_item.json"), + JSON.stringify({ + ...value(0), + id: "parent", + status: "delegated", + awaitingChildId: "child", + delegatedToId: "child", + parentTaskId: undefined, + childIds: ["child"], + }), + ) + if (!["restore", "read", "cold"].includes(mode)) + fs.writeFileSync(path.join(root, relativeCanonical), encoded[mode === "newer" ? 1 : 0]) + if (["restore", "read", "cold", "newer", "delete"].includes(mode)) { + fs.writeFileSync(path.join(root, "tasks", "child", ".history_item.json.bak_seed.tmp"), encoded[0]) + fs.writeFileSync(path.join(root, "tasks", "child", ".history_item.json.new_seed.tmp"), '{"partial":') + } +} +function committed(root: string): string[] { + const dir = path.join(root, "tasks", "child") + return fs + .readdirSync(dir) + .filter( + (name) => + name === "history_item.json" || (name.startsWith(".history_item.json.bak_") && name.endsWith(".tmp")), + ) + .map((name) => fs.readFileSync(path.join(dir, name), "utf8")) +} +async function runtime(bundle: string, root: string, mode: string, fault?: Fault) { + const child = await new Promise<{ status: number | null; stdout: string; stderr: string }>((resolve, reject) => { + execFile( + process.execPath, + ["-e", CHILD], + { + env: { + ...process.env, + NODE_PATH: [path.join(ROOT, "src/node_modules"), path.join(ROOT, "node_modules")].join( + path.delimiter, + ), + CHECK_BUNDLE: bundle, + CHECK_MAX_STEPS: String(MAX_STEPS), + CHECK_ROOT: root, + CHECK_MODE: mode, + CHECK_INCOMING: encoded[2], + CHECK_FAULT: JSON.stringify(fault ?? null), + }, + encoding: "utf8", + timeout: 20_000, + maxBuffer: 4_000_000, + }, + (error, stdout, stderr) => { + if (error && (typeof error.code === "string" || error.killed)) reject(error) + else + resolve({ + status: error ? (typeof error.code === "number" ? error.code : null) : 0, + stdout, + stderr, + }) + }, + ) + }) + const output = child.stdout + .trim() + .split("\n") + .filter(Boolean) + .map((line) => JSON.parse(line) as { n?: number; result?: Result; harnessError?: string; crash?: boolean }) + assert(!output.some((event) => event.harnessError), child.stdout + child.stderr) + assert(child.status === 0 || output.some((event) => event.crash), child.stderr) + if (fault && ["before", "after"].includes(fault.kind)) + assert( + output.some((event) => event.crash), + "Crash cutpoint was not reached", + ) + return { + events: output.filter((event) => event.n !== undefined) as Event[], + results: output.flatMap((event) => (event.result ? [event.result] : [])), + } +} +async function bundleAt(destination: string, mutation?: string) { + let applied = false + await build({ + stdin: { + contents: + 'export { safeWriteJson, recoverJsonFile } from "./src/utils/safeWriteJson"; export { readFileWithMissingRetry } from "./src/core/task-persistence/readFileWithMissingRetry"; export { TaskHistoryStore } from "./src/core/task-persistence/TaskHistoryStore"', + resolveDir: ROOT, + }, + bundle: true, + platform: "node", + format: "cjs", + target: "node22", + outfile: destination, + external: ["proper-lockfile"], + logLevel: "silent", + plugins: [ + { + name: "environment-and-mutations", + setup(build) { + build.onLoad({ filter: /[\\/]src[\\/]utils[\\/]storage\.ts$/ }, () => ({ + contents: "export async function getStorageBasePath(root: string) { return root }", + loader: "ts", + })) + if (mutation) + build.onLoad({ filter: /[\\/](safeWriteJson|TaskHistoryStore)\.ts$/ }, (args) => { + let source = fs.readFileSync(args.path, "utf8") + if (mutation === "restore-backup-loss" && args.path.endsWith("safeWriteJson.ts")) { + const original = + "await fs.rename(newestBackupPath, absoluteFilePath)\n\t\t\trestoredFrom = newestBackupPath" + assert(source.includes(original), "Restore mutation anchor changed") + source = source.replace(original, "try { " + original + " } catch {}") + applied = true + } + if (mutation === "reader-overwrites-newer" && args.path.endsWith("safeWriteJson.ts")) { + const original = "await fs.access(absoluteFilePath)" + assert(source.includes(original), "Reader mutation anchor changed") + source = source.replace( + original, + 'throw Object.assign(new Error("mutation: ignore canonical"), { code: "ENOENT" })', + ) + applied = true + } + if (mutation === "delete-keeps-backup" && args.path.endsWith("TaskHistoryStore.ts")) { + assert( + source.includes("await removeJsonBackups(absoluteFilePath)"), + "Deletion mutation anchor changed", + ) + applied = true + source = source.replaceAll( + "await removeJsonBackups(absoluteFilePath)", + "/* mutation: omit backup removal */", + ) + } + return { contents: source, loader: "ts" } + }) + }, + }, + ], + }) + assert(!mutation || applied, "Mutation was not applied") +} + +function violation(invariant: number, context: string, events: Event[]): never { + throw new Error( + `JSON replacement invariant ${invariant}: ${context}\n` + + events + .map( + (event) => + `${event.n}. ${event.phase} ${event.call} ${event.paths.join(" -> ")}${event.code ? " [" + event.code + "]" : ""}`, + ) + .join("\n"), + ) +} +async function runCase(bundle: string, dir: string, mode: Mode, fault?: Fault) { + const root = path.join(dir, "storage") + seed(root, mode) + const beforeCanonical = fs.existsSync(path.join(root, relativeCanonical)) + ? fs.readFileSync(path.join(root, relativeCanonical), "utf8") + : undefined + const run = await runtime(bundle, root, mode, fault) + const context = `${mode} ${JSON.stringify(fault ?? "no fault")}` + let latest = mode === "newer" ? 1 : 0 + for (const [index, event] of run.events.entries()) { + const version = Math.max(-1, ...event.copies.map((data) => encoded.findIndex((entry) => entry === data))) + if (version < latest) violation(2, context + " lost the latest committed copy", run.events.slice(0, index + 1)) + latest = version + } + assert(run.events.length <= MAX_STEPS * 2, "Replay filesystem-step budget exhausted") + if (fault) + assert( + run.events.some((event) => event.n === fault.step), + "Fault cutpoint was not reached", + ) + if (!committed(root).some((data) => encoded.some((entry) => entry === data))) + violation(2, context + " lost the only committed copy", run.events) + const result = run.results[0] + if ( + result?.ok && + ["write", "fallback", "rollback", "restore"].includes(mode) && + fs.readFileSync(path.join(root, relativeCanonical), "utf8") !== encoded[2] + ) + violation(1, context, run.events) + if ( + ["read", "newer"].includes(mode) && + beforeCanonical !== undefined && + fs.readFileSync(path.join(root, relativeCanonical), "utf8") !== beforeCanonical + ) + violation(6, context, run.events) + if (result?.ok && ["read", "newer"].includes(mode) && !encoded.some((entry) => entry === result.value)) + violation(3, context, run.events) + if (mode === "cold" && result && !result.ok && result.repairRuns !== 0) violation(5, context, run.events) + const followups = (await runtime(bundle, root, "followups")).results + assert.equal(followups.length, 4) + for (const followup of followups) { + if (!followup.ok) + violation(3, context + " follow-up " + followup.op + " rejected: " + followup.code, run.events) + if (followup.op === "delete" && followup.value !== undefined) + violation(4, context + " deleted file returned after recovery", run.events) + if (followup.op !== "delete" && followup.value !== encoded[followup.op === "write" ? 2 : latest]) + violation(3, context + " invalid follow-up value", run.events) + if (followup.op === "cold" && !followup.healthy) + violation(5, context + " cold-start snapshot unavailable", run.events) + } + return run.events +} +async function main() { + const work = fs.mkdtempSync(path.join(os.tmpdir(), "json-replacement-check-")) + try { + const mutation = process.argv.find((arg) => arg.startsWith("--mutation="))?.split("=")[1] + const bundle = path.join(work, "production.cjs") + await bundleAt(bundle, mutation) + if (mutation === "restore-backup-loss") { + const baseline = path.join(work, "baseline") + const events = await runCase(bundle, baseline, "restore") + const restore = events.find( + (event) => event.phase === "before" && event.call === "rename" && event.paths[0]?.includes(".bak"), + ) + assert(restore) + await runCase(bundle, path.join(work, "mutant"), "restore", { step: restore.n, kind: "EIO" }) + throw new Error("Restore mutant survived") + } + if (mutation === "delete-keeps-backup") { + const root = path.join(work, "delete", "storage") + seed(root, "delete") + const run = await runtime(bundle, root, "delete") + if (run.results[0]?.value !== undefined) violation(4, "deleted file returned after recovery", run.events) + throw new Error("Deletion mutant survived") + } + if (mutation === "reader-overwrites-newer") { + const root = path.join(work, "reader", "storage") + seed(root, "newer") + const run = await runtime(bundle, root, "newer-recovery") + assert(run.results[0]?.ok, "Mutant reader did not reach its recovery check") + if (fs.readFileSync(path.join(root, relativeCanonical), "utf8") !== encoded[1]) + violation(6, "reader replaced a newer canonical value", run.events) + throw new Error("Reader mutant survived") + } + assert(!mutation, "Unknown mutation") + const workers = Number(process.env.JSON_REPLACEMENT_WORKERS ?? 4) + assert( + Number.isInteger(workers) && workers >= 1 && workers <= 8, + "JSON_REPLACEMENT_WORKERS must be an integer from 1 to 8", + ) + const jobs: Array<() => Promise> = [] + let cases = 0, + steps = 0 + for (const mode of modes) { + const trace = await runCase(bundle, path.join(work, `${mode}-baseline`), mode) + const calls = trace.filter((event) => event.phase === "before") + assert(calls.length <= MAX_STEPS, "Filesystem-step budget exhausted") + steps += calls.length + console.log(`${mode}: ${calls.length} filesystem cutpoints`) + for (const call of calls) + for (const kind of ["before", "after", "EPERM", "EBUSY", "EACCES", "EIO"] as const) { + assert(++cases <= MAX_CASES, "Case budget exhausted") + const dir = path.join(work, `case-${cases}`) + jobs.push(async () => { + const replay = await runCase(bundle, dir, mode, { step: call.n, kind }) + assert.equal( + replay.find((event) => event.n === call.n)?.call, + call.call, + "Cutpoint order changed", + ) + fs.rmSync(dir, { recursive: true, force: true }) + }) + } + } + // Settle active workers before cleanup. Keep failures in case order, + // even when workers complete in a different order. + let next = 0 + const failures: Array<{ index: number; reason: unknown }> = [] + await Promise.all( + Array.from({ length: workers }, async () => { + while (!failures.length) { + const index = next++, + job = jobs[index] + if (!job) return + try { + await job() + } catch (reason: unknown) { + failures.push({ index, reason }) + } + } + }), + ) + failures.sort((a, b) => a.index - b.index) + if (failures[0]) throw failures[0].reason + console.log( + `JSON replacement check passed: ${steps} cutpoints, ${cases} fault/crash cases, ${workers} workers, four isolated follow-ups per case. No interleaving or Windows proof.`, + ) + } finally { + fs.rmSync(work, { recursive: true, force: true }) + } +} +void main().catch((error: unknown) => { + console.error(error) + process.exitCode = 1 +}) diff --git a/src/utils/safeWriteJson.ts b/src/utils/safeWriteJson.ts index b98f408d78..ae798530bf 100644 --- a/src/utils/safeWriteJson.ts +++ b/src/utils/safeWriteJson.ts @@ -122,8 +122,9 @@ async function recoverInterruptedReplacementUnchecked( ) const backups = backupStats.filter((backup) => backup !== null) backups.sort((a, b) => b.mtimeMs - a.mtimeMs || b.backupPath.localeCompare(a.backupPath)) - if (backups.length > 0) { - const newestBackupPath = backups[0].backupPath + const [newest] = backups + if (newest) { + const newestBackupPath = newest.backupPath // A failed restore leaves every backup intact and aborts the write. // In particular, a merge must never observe null in this state. await fs.rename(newestBackupPath, absoluteFilePath) From 62c7cd91c8c1474b083b4d5c241c374556a92e22 Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sat, 24 Oct 2026 20:31:34 +0000 Subject: [PATCH 07/14] fix(persistence): preserve safe failure diagnostics and refresh history --- .github/workflows/e2e.yml | 7 +- apps/vscode-e2e/package.json | 1 + .../src/restart/scenarioWorkspace.test.ts | 137 +++++++++++ .../src/restart/scenarioWorkspace.ts | 222 ++++++++++++++---- apps/vscode-e2e/src/runTest.ts | 7 +- src/__tests__/delegation-concurrent.spec.ts | 3 +- .../__tests__/FileContextTracker.spec.ts | 3 +- src/core/task-persistence/TaskHistoryStore.ts | 2 +- .../TaskHistoryStore.recovery.spec.ts | 8 + .../__tests__/taskMessages.spec.ts | 3 +- .../readFileWithMissingRetry.ts | 8 +- src/core/webview/ClineProvider.ts | 7 +- .../webview/__tests__/ClineProvider.spec.ts | 61 +++++ .../ClineProvider.taskHistory.spec.ts | 3 +- src/eslint-suppressions.json | 2 +- src/utils/__mocks__/safeWriteJson.ts | 9 + src/utils/__tests__/safeWriteJson.test.ts | 15 ++ src/utils/safeWriteJson.ts | 37 ++- 18 files changed, 456 insertions(+), 79 deletions(-) create mode 100644 apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts create mode 100644 src/utils/__mocks__/safeWriteJson.ts diff --git a/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index 2e3ef75824..4ab8ff735c 100644 --- a/.github/workflows/e2e.yml +++ b/.github/workflows/e2e.yml @@ -157,16 +157,13 @@ jobs: run: TEST_FILE=restart-persistence.test USE_MOCK=true xvfb-run -a pnpm --filter @roo-code/vscode-e2e exec node ./out/runTest.js - name: Upload restart-persistence failure artifacts - # runTest.js preserves a failed scenario workspace (phase results, - # VS Code logs, task files) under apps/vscode-e2e/test-failures/ - # instead of deleting it, so the interrupted-write state from - # issue #2130-style failures stays inspectable. + # Publish only generated metadata. Raw histories and logs are excluded. if: failure() uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 with: name: restart-persistence-failure retention-days: 7 - path: apps/vscode-e2e/test-failures/ + path: apps/vscode-e2e/test-failures/**/diagnostics.json if-no-files-found: ignore - name: Explain skipped mocked E2E pass marker diff --git a/apps/vscode-e2e/package.json b/apps/vscode-e2e/package.json index d19b5b765b..06ad0bec7b 100644 --- a/apps/vscode-e2e/package.json +++ b/apps/vscode-e2e/package.json @@ -7,6 +7,7 @@ "format": "prettier --write src", "test:ci": "pnpm -w bundle && pnpm --filter @roo-code/vscode-webview build && pnpm test:run", "test:ci:mock": "pnpm -w bundle && pnpm --filter @roo-code/vscode-webview build && USE_MOCK=true pnpm test:run", + "test:restart-artifacts": "tsc -p tsconfig.json && node ./out/restart/scenarioWorkspace.test.js", "test:record": "AIMOCK_RECORD=true pnpm test:ci", "test:run": "rimraf out && tsc -p tsconfig.json && dotenv -e .env.local -- node ./out/runTest.js", "themes:build": "pnpm -w bundle && pnpm --filter @roo-code/vscode-webview build && rimraf out && tsc -p tsconfig.json", diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts new file mode 100644 index 0000000000..db34b3a123 --- /dev/null +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts @@ -0,0 +1,137 @@ +import assert from "node:assert/strict" +import fs from "node:fs/promises" +import path from "node:path" +import test, { type TestContext } from "node:test" + +import { createScenarioWorkspace, preserveScenarioWorkspace, removeScenarioWorkspace } from "./scenarioWorkspace" + +async function scenario(t: TestContext) { + const workspace = await createScenarioWorkspace() + const destination = path.resolve(__dirname, "../../test-failures", path.basename(workspace.root)) + t.after(async () => { + await removeScenarioWorkspace(workspace) + await fs.rm(destination, { recursive: true, force: true }) + }) + return { workspace, destination } +} + +void test("publishes only metadata, including when raw copies would fail", async (t) => { + const { workspace, destination } = await scenario(t) + const secret = "private-prompt-and-api-key" + const tasks = path.join(workspace.userData, "User/globalStorage/zoocodeorganization.zoo-code/tasks", secret) + const logs = path.join(workspace.userData, "logs") + await fs.mkdir(tasks, { recursive: true }) + await fs.mkdir(logs, { recursive: true }) + for (const name of ["ui_messages.json", "api_conversation_history.json", ".ui_messages.json.bak_secret.tmp"]) { + await fs.writeFile(path.join(tasks, name), JSON.stringify({ text: secret })) + } + await fs.writeFile(path.join(logs, `${secret}.log`), secret) + await fs.writeFile( + path.join(workspace.results, "01-create.json"), + JSON.stringify({ + version: 1, + phase: "create", + status: "failed", + values: { secret }, + error: { message: secret, stack: secret }, + }), + ) + const copy = t.mock.method(fs, "cp", () => { + throw new Error("Raw copy must never run") + }) + assert.equal(await preserveScenarioWorkspace(workspace), destination) + assert.equal(copy.mock.callCount(), 0) + assert.deepEqual(await fs.readdir(destination), ["diagnostics.json"]) + const manifest = await fs.readFile(path.join(destination, "diagnostics.json"), "utf8") + assert(!manifest.includes(secret)) + assert(!manifest.includes(workspace.root)) + assert(manifest.includes('"sha256"')) + assert(manifest.includes('"status": "failed"')) + assert(manifest.includes('"ui_messages.json"')) + await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) +}) + +void test("classifies leftovers and publishes only validated trace fields", async (t) => { + const { workspace, destination } = await scenario(t) + const secret = "private-task-secret" + const tasks = path.join(workspace.userData, "User/globalStorage/zoocodeorganization.zoo-code/tasks", secret) + const logs = path.join(workspace.userData, "logs") + await fs.mkdir(tasks, { recursive: true }) + await fs.mkdir(logs, { recursive: true }) + for (const name of [ + ".ui_messages.json.bak_private.tmp", + ".api_conversation_history.json.new_private.tmp", + "other.json", + ]) { + await fs.writeFile(path.join(tasks, name), secret) + } + await fs.mkdir(path.join(tasks, "history_item.json.lock")) + const first = { stage: "ui-messages-write-start", pid: 101, ts: "2026-10-24T12:00:00.000Z" } + const second = { stage: "shutdown", pid: 202, ts: "2026-10-24T12:00:01.000Z" } + const line = (event: object) => `[prefix] [persistence-trace] ${JSON.stringify(event)}` + await fs.writeFile( + path.join(logs, "extension.log"), + [ + line({ ...second, taskId: secret, filePath: secret, detail: secret, result: secret }), + line({ ...first, taskId: secret, filePath: secret, detail: secret }), + line(first), // Console and output-channel copies must not duplicate events. + line({ ...first, stage: secret }), + line({ ...first, pid: secret }), + line({ ...first, ts: secret }), + "[persistence-trace] truncated {", + ].join("\n"), + ) + await preserveScenarioWorkspace(workspace) + const text = await fs.readFile(path.join(destination, "diagnostics.json"), "utf8") + assert(!text.includes(secret)) + assert(!text.includes(".bak_private")) + const diagnostic: { + sources: Array<{ + label: string + files?: Array<{ class: string; kind: string; directoryHash: string; target?: string; name?: string }> + }> + traces: unknown + } = JSON.parse(text) + assert.deepEqual(diagnostic.traces, [first, second]) + const files = diagnostic.sources.find((source) => source.label === "tasks")?.files + assert(files) + assert.deepEqual(files.map((file) => file.class).sort(), ["backup", "lock", "new-temp", "other"]) + assert.equal(new Set(files.map((file) => file.directoryHash)).size, 1) + assert.equal(files.find((file) => file.class === "backup")?.target, "ui_messages.json") + assert.equal(files.find((file) => file.class === "lock")?.kind, "directory") + assert(!files.some((file) => file.name === "ui_messages.json")) +}) + +void test("skips absent optional directories", async (t) => { + const { workspace, destination } = await scenario(t) + await preserveScenarioWorkspace(workspace) + const manifest = await fs.readFile(path.join(destination, "diagnostics.json"), "utf8") + assert.equal((manifest.match(/"status": "missing"/g) ?? []).length, 2) + await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) +}) + +void test("records collection failures without copying raw files and still cleans the workspace", async (t) => { + const { workspace, destination } = await scenario(t) + await fs.writeFile(path.join(workspace.results, "01-create.json"), "private phase contents") + const read = fs.readFile + t.mock.method(fs, "readFile", (async (...args: Parameters) => { + if (String(args[0]).endsWith("01-create.json")) + throw Object.assign(new Error("sensitive detail"), { code: "EIO" }) + return read(...args) + }) as typeof fs.readFile) + await preserveScenarioWorkspace(workspace) + const manifest = await read(path.join(destination, "diagnostics.json"), "utf8") + assert(manifest.includes('"code": "EIO"')) + assert(manifest.includes('"kind": "error"')) + assert(!manifest.includes("sensitive detail")) + await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) +}) + +void test("cleans the workspace even when writing the diagnostic artifact fails", async (t) => { + const { workspace } = await scenario(t) + t.mock.method(fs, "writeFile", async () => { + throw Object.assign(new Error("disk failed"), { code: "EIO" }) + }) + await assert.rejects(preserveScenarioWorkspace(workspace), { code: "EIO" }) + await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) +}) diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts index d184dab052..8da6694f42 100644 --- a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts @@ -1,6 +1,9 @@ import * as os from "os" import * as path from "path" import * as fs from "fs/promises" +import { createHash } from "crypto" + +import { readPhaseResult } from "./phaseProtocol" const SCENARIO_ROOT_PREFIX = "roo-vscode-e2e-restart-" @@ -59,16 +62,118 @@ export async function removeScenarioWorkspace(scenarioWorkspace: ScenarioWorkspa const FAILURE_ARTIFACTS_DIR = "test-failures" -/** - * Copies the diagnosable parts of a failed scenario workspace into a stable - * directory inside the checkout, then removes the temporary scenario root. - * CI uploads that directory as a run artifact, so the failure that used to be - * deleted in the cleanup path stays inspectable: phase results, VS Code logs, - * and the extension's task files. Global state databases are excluded. - * - * The directory is keyed by the unique scenario root name and cleared before - * copying, so retried runs cannot mix artifacts from different failures. - */ +type FileDiagnostic = { + pathHash: string + name?: string + kind: "file" | "directory" | "symlink" | "error" + directoryHash: string + class: "backup" | "new-temp" | "lock" | "other" + target?: string + size?: number + sha256?: string + code?: string +} + +function hash(value: string | Buffer): string { + return createHash("sha256").update(value).digest("hex") +} + +function diagnosticCode(error: unknown): string { + const code = typeof error === "object" && error !== null && "code" in error ? error.code : undefined + return typeof code === "string" && ["ENOENT", "ENOTDIR", "EACCES", "EPERM", "EBUSY", "EIO"].includes(code) + ? code + : "IO_ERROR" +} + +type TraceDiagnostic = { stage: string; pid: number; ts: string } + +const knownFiles = ["ui_messages.json", "api_conversation_history.json", "history_item.json"] + +function classifyFile(name: string): Pick { + const leftover = /^\.([^/\\]+)\.(bak|new)_[^/\\]+\.tmp$/.exec(name) + if (leftover) + return { + class: leftover[2] === "bak" ? "backup" : "new-temp", + target: knownFiles.includes(leftover[1] ?? "") ? leftover[1] : undefined, + } + const lock = /^([^/\\]+)\.lock$/.exec(name) + if (lock) return { class: "lock", target: knownFiles.includes(lock[1] ?? "") ? lock[1] : undefined } + return { class: "other" } +} + +function traceDiagnostics(data: Buffer): TraceDiagnostic[] { + const traces: TraceDiagnostic[] = [] + // Unknown stages stay private until their publication is reviewed. + const stages = new Set([ + "json-recovery-failed", + "ui-messages-recovery", + "ui-messages-write-start", + "ui-messages-backup-rename", + "ui-messages-replacement-rename", + "ui-messages-write-complete", + "ui-messages-marker-check", + "shutdown", + ]) + const marker = "[persistence-trace] " + for (const line of data.toString("utf8").split(/\r?\n/)) { + const start = line.indexOf(marker) + if (start < 0) continue + try { + const value: unknown = JSON.parse(line.slice(start + marker.length)) + if (!value || typeof value !== "object" || !("stage" in value) || !("pid" in value) || !("ts" in value)) + continue + const { stage, pid, ts } = value + if ( + typeof stage !== "string" || + !stages.has(stage) || + typeof pid !== "number" || + !Number.isSafeInteger(pid) || + pid <= 0 + ) + continue + if ( + typeof ts !== "string" || + !/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$/.test(ts) || + !Number.isFinite(Date.parse(ts)) + ) + continue + traces.push({ stage, pid, ts }) + } catch { + // A malformed or truncated log line must not expose its raw contents. + } + } + return traces +} + +async function fileDiagnostics( + directory: string, + relative = "", + traces?: TraceDiagnostic[], +): Promise { + const files: FileDiagnostic[] = [] + for (const entry of await fs.readdir(path.join(directory, relative), { withFileTypes: true })) { + const child = path.join(relative, entry.name) + const identity = { pathHash: hash(child), directoryHash: hash(relative), ...classifyFile(entry.name) } + try { + if (entry.isSymbolicLink()) files.push({ ...identity, kind: "symlink" }) + else if (entry.isDirectory()) { + if (identity.class === "lock") files.push({ ...identity, kind: "directory" }) + files.push(...(await fileDiagnostics(directory, child, traces))) + } else if (entry.isFile()) { + const data = await fs.readFile(path.join(directory, child)) + if (traces) traces.push(...traceDiagnostics(data)) + // Arbitrary filenames can also contain private data. Publish only known names. + const name = knownFiles.includes(entry.name) ? entry.name : undefined + files.push({ ...identity, name, kind: "file", size: data.length, sha256: hash(data) }) + } + } catch (error) { + files.push({ ...identity, kind: "error", code: diagnosticCode(error) }) + } + } + return files +} + +/** Publish metadata only. Never copy task contents, phase errors, or raw logs. */ export async function preserveScenarioWorkspace(scenarioWorkspace: ScenarioWorkspace): Promise { const destinationRoot = path.resolve( __dirname, @@ -76,42 +181,67 @@ export async function preserveScenarioWorkspace(scenarioWorkspace: ScenarioWorks FAILURE_ARTIFACTS_DIR, path.basename(scenarioWorkspace.root), ) - await fs.rm(destinationRoot, { recursive: true, force: true }) - await fs.mkdir(destinationRoot, { recursive: true }) - - const selections: Array<{ label: string; source: string; destination: string }> = [ - { - label: "phase results", - source: scenarioWorkspace.results, - destination: path.join(destinationRoot, "phase-results"), - }, - { - label: "VS Code logs", - source: path.join(scenarioWorkspace.userData, "logs"), - destination: path.join(destinationRoot, "vscode-logs"), - }, - { - label: "task files", - source: path.join( - scenarioWorkspace.userData, - "User", - "globalStorage", - "zoocodeorganization.zoo-code", - "tasks", - ), - destination: path.join(destinationRoot, "tasks"), - }, - ] - - for (const selection of selections) { - try { - await fs.cp(selection.source, selection.destination, { recursive: true, force: true }) - } catch (error) { - // A missing subdirectory must not hide the other artifacts. - console.error(`Failed to preserve ${selection.label} from ${selection.source}:`, error) + try { + await fs.rm(destinationRoot, { recursive: true, force: true }) + await fs.mkdir(destinationRoot, { recursive: true }) + const selections = [ + { label: "phase-results", source: scenarioWorkspace.results }, + { label: "vscode-logs", source: path.join(scenarioWorkspace.userData, "logs") }, + { + label: "tasks", + source: path.join( + scenarioWorkspace.userData, + "User", + "globalStorage", + "zoocodeorganization.zoo-code", + "tasks", + ), + }, + ] + const sources = [] + const traces: TraceDiagnostic[] = [] + for (const selection of selections) { + try { + sources.push({ + label: selection.label, + status: "collected", + files: await fileDiagnostics( + selection.source, + "", + selection.label === "vscode-logs" ? traces : undefined, + ), + }) + } catch (error) { + const code = diagnosticCode(error) + sources.push({ label: selection.label, status: code === "ENOENT" ? "missing" : "error", code }) + } } + const phases = [] + for (const phase of ["create", "verify"] as const) { + try { + const result = await readPhaseResult(scenarioWorkspace.results, phase) + phases.push({ phase, status: result.status }) + } catch (error) { + phases.push({ phase, code: diagnosticCode(error) }) + } + } + await fs.writeFile( + path.join(destinationRoot, "diagnostics.json"), + JSON.stringify( + { + sources, + phases, + traces: [...new Map(traces.map((event) => [JSON.stringify(event), event])).values()].sort((a, b) => + a.ts.localeCompare(b.ts), + ), + }, + null, + 2, + ), + ) + return destinationRoot + } finally { + // Collection or output errors must not leave the temporary workspace behind. + await removeScenarioWorkspace(scenarioWorkspace) } - - await removeScenarioWorkspace(scenarioWorkspace) - return destinationRoot } diff --git a/apps/vscode-e2e/src/runTest.ts b/apps/vscode-e2e/src/runTest.ts index f24f37d388..978a8d2d08 100644 --- a/apps/vscode-e2e/src/runTest.ts +++ b/apps/vscode-e2e/src/runTest.ts @@ -231,13 +231,12 @@ async function main() { await fs.rm(testWorkspace, { recursive: true, force: true }) } if (scenarioWorkspace) { - // A failed restart scenario must stay inspectable: the phase - // results, VS Code logs, and task files are copied to a stable - // directory for CI artifact upload before the temp root goes away. + // Keep metadata from a failed restart scenario for CI inspection. + // Raw histories, phase errors, and logs must never enter the artifact. if (runFailed) { try { const preservedAt = await preserveScenarioWorkspace(scenarioWorkspace) - console.error(`Restart scenario workspace preserved for failure inspection: ${preservedAt}`) + console.error(`Restart scenario diagnostics saved for failure inspection: ${preservedAt}`) } catch (preserveError) { console.error("Failed to preserve the restart scenario workspace:", preserveError) } diff --git a/src/__tests__/delegation-concurrent.spec.ts b/src/__tests__/delegation-concurrent.spec.ts index 40d9b49ee5..96ff662e86 100644 --- a/src/__tests__/delegation-concurrent.spec.ts +++ b/src/__tests__/delegation-concurrent.spec.ts @@ -19,7 +19,8 @@ vi.mock("fs", () => ({ existsSync: vi.fn().mockReturnValue(false), })) -vi.mock("../utils/safeWriteJson", () => ({ +vi.mock("../utils/safeWriteJson", async (importOriginal) => ({ + ...(await importOriginal()), safeWriteJson: vi.fn().mockResolvedValue(undefined), })) diff --git a/src/core/context-tracking/__tests__/FileContextTracker.spec.ts b/src/core/context-tracking/__tests__/FileContextTracker.spec.ts index 531221e098..2ccfad0720 100644 --- a/src/core/context-tracking/__tests__/FileContextTracker.spec.ts +++ b/src/core/context-tracking/__tests__/FileContextTracker.spec.ts @@ -23,7 +23,8 @@ vi.mock("../../../utils/fs", () => ({ fileExistsAtPath: vi.fn().mockResolvedValue(false), })) -vi.mock("../../../utils/safeWriteJson", () => ({ +vi.mock("../../../utils/safeWriteJson", async (importOriginal) => ({ + ...(await importOriginal()), safeWriteJson: vi.fn().mockResolvedValue(undefined), })) diff --git a/src/core/task-persistence/TaskHistoryStore.ts b/src/core/task-persistence/TaskHistoryStore.ts index 9b575c8448..a04b813b86 100644 --- a/src/core/task-persistence/TaskHistoryStore.ts +++ b/src/core/task-persistence/TaskHistoryStore.ts @@ -440,7 +440,7 @@ export class TaskHistoryStore { } catch (error) { // An unavailable snapshot is not evidence of deletion. In // particular, startup must not repair delegation from it. - if (getErrorCode(error) !== "ENOENT") throw error + if (!["ENOENT", "ENOTDIR"].includes(getErrorCode(error) ?? "")) throw error // File may be temporarily absent during a peer's atomic // rename window in safeWriteJson. The advisory lock is // held for the entire write, so its presence means a diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts index 488eadc5cd..5e6bb78c7d 100644 --- a/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts @@ -124,4 +124,12 @@ describe("TaskHistoryStore interrupted history recovery", () => { expect(store.get(child.id)).toEqual(child) expect(store.get(parent.id)).toEqual(parent) }) + it("treats a task path that is no longer a directory as an absent record", async () => { + await store.initialize() + await fs.rm(path.dirname(canonical), { recursive: true }) + await fs.writeFile(path.dirname(canonical), "not a task directory") + await expect(store.reconcile()).resolves.toBeUndefined() + expect(store.get(child.id)).toBeUndefined() + expect(store.get(parent.id)).toEqual(parent) + }) }) diff --git a/src/core/task-persistence/__tests__/taskMessages.spec.ts b/src/core/task-persistence/__tests__/taskMessages.spec.ts index 2486c7a52f..e022c47712 100644 --- a/src/core/task-persistence/__tests__/taskMessages.spec.ts +++ b/src/core/task-persistence/__tests__/taskMessages.spec.ts @@ -14,7 +14,8 @@ vi.mock("fs/promises", async (importOriginal) => ({ ...(await importOriginal()), readFile: hoisted.readFileMock, })) -vi.mock("../../../utils/safeWriteJson", () => ({ +vi.mock("../../../utils/safeWriteJson", async (importOriginal) => ({ + ...(await importOriginal()), safeWriteJson: hoisted.safeWriteJsonMock, recoverJsonFile: vi.fn().mockResolvedValue(undefined), })) diff --git a/src/core/task-persistence/readFileWithMissingRetry.ts b/src/core/task-persistence/readFileWithMissingRetry.ts index 16b370d445..7f06923b6f 100644 --- a/src/core/task-persistence/readFileWithMissingRetry.ts +++ b/src/core/task-persistence/readFileWithMissingRetry.ts @@ -1,6 +1,6 @@ import * as fs from "fs/promises" -import { recoverJsonFile } from "../../utils/safeWriteJson" +import { getErrorCode, recoverJsonFile } from "../../utils/safeWriteJson" // safeWriteJson commits a replacement with a single atomic rename. Only the // Windows EPERM fallback replaces a file in two renames (target to backup, @@ -12,11 +12,7 @@ const READ_RETRY_MIN_MS = 1 const READ_RETRY_MAX_MS = 10 const READ_RETRY_RANGE_MS = READ_RETRY_MAX_MS - READ_RETRY_MIN_MS + 1 -export function getErrorCode(error: unknown): string | undefined { - return typeof error === "object" && error !== null && "code" in error && typeof error.code === "string" - ? error.code - : undefined -} +export { getErrorCode } from "../../utils/safeWriteJson" /** * Formats the actionable detail of an underlying error for inclusion in diff --git a/src/core/webview/ClineProvider.ts b/src/core/webview/ClineProvider.ts index 94eb31c2ab..a736995865 100644 --- a/src/core/webview/ClineProvider.ts +++ b/src/core/webview/ClineProvider.ts @@ -515,6 +515,7 @@ export class ClineProvider } this.taskHistoryStoreInitialized = true + if (this.isViewLaunched) await this.postStateToWebview() } catch (error) { this.log(`[initializeTaskHistoryStore] Error: ${error instanceof Error ? error.message : String(error)}`) } @@ -2902,8 +2903,12 @@ export class ClineProvider clineMessages: currentTask?.clineMessages || [], currentTaskTodos: currentTask?.todoList || [], messageQueue: currentTask?.messageQueueService?.messages, + // Legacy history can include deleted tasks. Prefer it to hiding all history while the store is unhealthy. taskHistory: includeTaskHistory - ? this.taskHistoryStore.getAll().filter((item: HistoryItem) => item.ts && item.task) + ? (this.taskHistoryStore.isHealthy + ? this.taskHistoryStore.getAll() + : (this.contextProxy.getValue("taskHistory") ?? []) + ).filter((item: HistoryItem) => item.ts && item.task) : [], soundEnabled: soundEnabled ?? false, ttsEnabled: ttsEnabled ?? false, diff --git a/src/core/webview/__tests__/ClineProvider.spec.ts b/src/core/webview/__tests__/ClineProvider.spec.ts index 73662526f0..6d98b41a9c 100644 --- a/src/core/webview/__tests__/ClineProvider.spec.ts +++ b/src/core/webview/__tests__/ClineProvider.spec.ts @@ -1486,7 +1486,67 @@ describe("ClineProvider", () => { expect(postMessageSpy.mock.calls[0]?.[0].state).not.toHaveProperty("taskHistory") }) + test.each([ + { launched: true, fails: false }, + { launched: false, fails: false }, + { launched: true, fails: true }, + ])("refreshes history after initialization: launched=$launched, fails=$fails", async ({ launched, fails }) => { + await provider["initializeTaskHistoryStore"]() + let release!: () => void + const waiting = new Promise((resolve, reject) => { + release = () => (fails ? reject(new Error("initialization failed")) : resolve()) + }) + const initialize = vi.spyOn(provider.taskHistoryStore, "initialize").mockReturnValue(waiting) + const post = vi.spyOn(provider, "postStateToWebview").mockResolvedValue(undefined) + provider.isViewLaunched = launched + provider["taskHistoryStoreInitialized"] = false + try { + const pending = provider["initializeTaskHistoryStore"]() + expect(post).not.toHaveBeenCalled() + release() + await pending + expect(post).toHaveBeenCalledTimes(launched && !fails ? 1 : 0) + expect(provider["taskHistoryStoreInitialized"]).toBe(!fails) + } finally { + provider.isViewLaunched = false + initialize.mockRestore() + post.mockRestore() + } + }) + + test.each([ + { healthy: true, includeTaskHistory: true }, + { healthy: false, includeTaskHistory: true }, + { healthy: false, includeTaskHistory: false }, + ])( + "publishes history with store health $healthy and inclusion $includeTaskHistory", + async ({ healthy, includeTaskHistory }) => { + const item = { + id: "legacy", + number: 1, + ts: 1, + task: "legacy task", + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + } + const cached = { ...item, id: "cached", task: "cached task" } + const health = vi.spyOn(provider.taskHistoryStore, "isHealthy", "get").mockReturnValue(healthy) + const getAll = vi.spyOn(provider.taskHistoryStore, "getAll").mockReturnValue([cached]) + await provider["contextProxy"].setValue("taskHistory", [item, { ...item, id: "invalid", ts: 0 }]) + try { + const state = await provider.getStateToPostToWebview({ includeTaskHistory }) + expect(state.taskHistory).toEqual(includeTaskHistory ? [healthy ? cached : item] : []) + expect(getAll).toHaveBeenCalledTimes(healthy && includeTaskHistory ? 1 : 0) + } finally { + health.mockRestore() + getAll.mockRestore() + } + }, + ) + test("getStateToPostToWebview computes task history once after its base state resolves", async () => { + const health = vi.spyOn(provider.taskHistoryStore, "isHealthy", "get").mockReturnValue(true) const historyItem = { id: "history-task", number: 1, @@ -1516,6 +1576,7 @@ describe("ClineProvider", () => { expect(getAllSpy).toHaveBeenCalledOnce() expect(historyReadPhases).toEqual([true]) expect(state.taskHistory).toEqual([historyItem]) + health.mockRestore() }) describe("postStateToWebviewThrottled", () => { diff --git a/src/core/webview/__tests__/ClineProvider.taskHistory.spec.ts b/src/core/webview/__tests__/ClineProvider.taskHistory.spec.ts index bec8a31040..245d87142c 100644 --- a/src/core/webview/__tests__/ClineProvider.taskHistory.spec.ts +++ b/src/core/webview/__tests__/ClineProvider.taskHistory.spec.ts @@ -57,7 +57,8 @@ vi.mock("../../../utils/storage", () => ({ }), })) -vi.mock("../../../utils/safeWriteJson", () => ({ +vi.mock("../../../utils/safeWriteJson", async (importOriginal) => ({ + ...(await importOriginal()), safeWriteJson: vi.fn().mockResolvedValue(undefined), })) diff --git a/src/eslint-suppressions.json b/src/eslint-suppressions.json index 5ff2c94f7e..cfde98cf90 100644 --- a/src/eslint-suppressions.json +++ b/src/eslint-suppressions.json @@ -1686,7 +1686,7 @@ }, "utils/safeWriteJson.ts": { "@typescript-eslint/no-explicit-any": { - "count": 4 + "count": 3 } }, "vitest.setup.ts": { diff --git a/src/utils/__mocks__/safeWriteJson.ts b/src/utils/__mocks__/safeWriteJson.ts new file mode 100644 index 0000000000..e43c9f5320 --- /dev/null +++ b/src/utils/__mocks__/safeWriteJson.ts @@ -0,0 +1,9 @@ +import { vi } from "vitest" + +const actual = await vi.importActual("../safeWriteJson") + +// Mock filesystem operations, but keep error classification shared with the real reader. +export const getErrorCode = actual.getErrorCode +export const safeWriteJson = vi.fn() +export const recoverJsonFile = vi.fn() +export const removeJsonBackups = vi.fn() diff --git a/src/utils/__tests__/safeWriteJson.test.ts b/src/utils/__tests__/safeWriteJson.test.ts index 3bb22da3f1..647ee2d12d 100644 --- a/src/utils/__tests__/safeWriteJson.test.ts +++ b/src/utils/__tests__/safeWriteJson.test.ts @@ -660,4 +660,19 @@ describe("safeWriteJson", () => { const content = await readFileContent(currentTestFilePath) expect(content).toEqual(newData) }) + test.each(["recover", "write-start", "replacement-rename", "backup-rename", "write-complete"] as const)( + "keeps the EPERM replacement when the %s trace throws", + async (stage) => { + await fs.writeFile(path.join(tempDir, ".test-file.json.new_orphan.tmp"), "partial") + const incoming = { message: "committed despite trace failure" } + vi.spyOn(fs, "rename").mockRejectedValueOnce(Object.assign(new Error("open file"), { code: "EPERM" })) + const trace = vi.fn((event: { stage: string }) => { + if (event.stage === stage) throw new Error("diagnostic sink failed") + }) + await expect(safeWriteJson(currentTestFilePath, incoming, { trace })).resolves.toBeUndefined() + expect(trace).toHaveBeenCalledWith(expect.objectContaining({ stage })) + expect(await readFileContent(currentTestFilePath)).toEqual(incoming) + expect(await fs.readdir(tempDir)).toEqual(["test-file.json"]) + }, + ) }) diff --git a/src/utils/safeWriteJson.ts b/src/utils/safeWriteJson.ts index ae798530bf..58494dc147 100644 --- a/src/utils/safeWriteJson.ts +++ b/src/utils/safeWriteJson.ts @@ -47,6 +47,18 @@ export interface SafeWriteJsonOptions { trace?: SafeWriteJsonTrace } +function notifyTrace(trace: SafeWriteJsonTrace | undefined, event: Parameters[0]): void { + try { + trace?.(event) + } catch { + try { + console.error("JSON write trace callback failed") + } catch { + // Diagnostics must not affect persistence, even if logging fails. + } + } +} + function createTempFilePath(absoluteFilePath: string, kind: "new" | "bak"): string { return path.join( path.dirname(absoluteFilePath), @@ -158,7 +170,7 @@ async function withRecoveryTrace(absoluteFilePath: string, operation: () => P } } -function getErrorCode(error: unknown): string | undefined { +export function getErrorCode(error: unknown): string | undefined { return typeof error === "object" && error !== null && "code" in error && typeof error.code === "string" ? error.code : undefined @@ -246,6 +258,7 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso // Variables to hold the actual paths of temp files if they are created. let actualTempNewFilePath: string | null = null let actualTempBackupFilePath: string | null = null + let committed = false try { // Heal any state an interrupted previous write left behind: an absent @@ -254,11 +267,11 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso const recovery = await withRecoveryTrace(absoluteFilePath, () => recoverInterruptedReplacementUnchecked(absoluteFilePath), ).catch((error: unknown) => { - options?.trace?.({ stage: "recover", detail: `failed: ${getErrorCode(error) ?? String(error)}` }) + notifyTrace(options?.trace, { stage: "recover", detail: `failed: ${getErrorCode(error) ?? String(error)}` }) throw error }) if (recovery.foundLeftovers) { - options?.trace?.({ stage: "recover", detail: recovery.restoredFrom ?? "cleaned-leftovers" }) + notifyTrace(options?.trace, { stage: "recover", detail: recovery.restoredFrom ?? "cleaned-leftovers" }) } // If a merge callback was provided, read the current file under the lock @@ -279,7 +292,7 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso } // Step 1: Stream the replacement to a temporary file before commit. - options?.trace?.({ stage: "write-start" }) + notifyTrace(options?.trace, { stage: "write-start" }) actualTempNewFilePath = createTempFilePath(absoluteFilePath, "new") await _streamDataToFile(actualTempNewFilePath, data, options?.prettyPrint) @@ -289,10 +302,10 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso // process exit before or during the commit can no longer leave the // canonical path absent. try { - options?.trace?.({ stage: "replacement-rename" }) + notifyTrace(options?.trace, { stage: "replacement-rename" }) await fs.rename(actualTempNewFilePath, absoluteFilePath) - } catch (renameError: any) { - if (renameError?.code !== "EPERM") { + } catch (renameError: unknown) { + if (getErrorCode(renameError) !== "EPERM") { throw renameError } @@ -302,19 +315,20 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso // The rollback in the catch below restores the backup when the // second rename fails, and the recovery pass at the start of the // next write repairs a crash between the two renames. - options?.trace?.({ stage: "backup-rename", detail: "eperm-fallback" }) + notifyTrace(options?.trace, { stage: "backup-rename", detail: "eperm-fallback" }) const backupPath = createTempFilePath(absoluteFilePath, "bak") await fs.rename(absoluteFilePath, backupPath) actualTempBackupFilePath = backupPath - options?.trace?.({ stage: "replacement-rename", detail: "eperm-fallback" }) + notifyTrace(options?.trace, { stage: "replacement-rename", detail: "eperm-fallback" }) await fs.rename(actualTempNewFilePath, absoluteFilePath) } + committed = true + // If we reach here, the new file is successfully in place. // The original actualTempNewFilePath is now the main file, so we shouldn't try to clean it up as "temp". // Mark as "used" or "committed" actualTempNewFilePath = null - options?.trace?.({ stage: "write-complete" }) // Step 3: If a backup was created, attempt to delete it. if (actualTempBackupFilePath) { @@ -338,7 +352,7 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso const backupFileToRollbackOrCleanupWithinCatch = actualTempBackupFilePath // Attempt rollback if a backup was made - if (backupFileToRollbackOrCleanupWithinCatch) { + if (!committed && backupFileToRollbackOrCleanupWithinCatch) { try { await fs.rename(backupFileToRollbackOrCleanupWithinCatch, absoluteFilePath) // Mark as handled, prevent later unlink of this path @@ -368,6 +382,7 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso // Preserve it so a subsequent read or write can recover it. throw originalError // This MUST be the error that rejects the promise. } finally { + if (committed) notifyTrace(options?.trace, { stage: "write-complete" }) // Release the lock in the main finally block. try { // releaseLock will be the actual unlock function if lock was acquired, From fb2a0fedc8df522383f306a47a1ea28aa8ebd0f3 Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sat, 24 Oct 2026 21:06:27 +0000 Subject: [PATCH 08/14] fix(tests): handle filesystem races in JSON crash checker --- docs/architecture/task-lifecycle-model.md | 6 ++ scripts/check-json-replacement.test.ts | 13 ++++ scripts/check-json-replacement.ts | 88 ++++++++++++++++++++--- 3 files changed, 97 insertions(+), 10 deletions(-) diff --git a/docs/architecture/task-lifecycle-model.md b/docs/architecture/task-lifecycle-model.md index f674bcdaa2..dca5a654db 100644 --- a/docs/architecture/task-lifecycle-model.md +++ b/docs/architecture/task-lifecycle-model.md @@ -346,6 +346,12 @@ Successful cold initialization must report a healthy store. A successful rename can publish a new value before the write promise resolves. The checker treats that value as committed. +A native rename can also finish after the last JavaScript snapshot but before SIGKILL. +The checker reads committed files after child exit to set exact follow-up expectations. +That final state must preserve the newest value already observed. +An observer also retries a complete snapshot if a rename races its directory listing and file reads. +Three failed attempts exhaust the snapshot budget and fail the check. +Deterministic regressions cover both orderings without waiting for scheduling races. Deletion follow-ups run without injected faults. The best-effort delete API can resolve after an I/O failure; this check does not strengthen that contract. diff --git a/scripts/check-json-replacement.test.ts b/scripts/check-json-replacement.test.ts index 8c928555d6..19c740cdce 100644 --- a/scripts/check-json-replacement.test.ts +++ b/scripts/check-json-replacement.test.ts @@ -31,3 +31,16 @@ for (const workers of ["0", "9", "1.5", "invalid"]) { assert.match(result.stderr, /JSON_REPLACEMENT_WORKERS must be an integer from 1 to 8/) }) } + +for (const regression of ["rename-in-flight", "snapshot-race"]) { + test(`accepts the deterministic ${regression} schedule`, () => { + const result = spawnSync( + process.execPath, + ["--import", "tsx", "scripts/check-json-replacement.ts", `--regression=${regression}`], + { encoding: "utf8", timeout: 30_000 }, + ) + assert.ifError(result.error) + assert.equal(result.status, 0, result.stderr) + assert.match(result.stdout, new RegExp(`${regression} regression passed`)) + }) +} diff --git a/scripts/check-json-replacement.ts b/scripts/check-json-replacement.ts index 8dc2f403b4..4882116e5f 100644 --- a/scripts/check-json-replacement.ts +++ b/scripts/check-json-replacement.ts @@ -19,17 +19,30 @@ type Result = { op: string; ok: boolean; code?: string; value?: string; repairRu const CHILD = String.raw` const fs = require("fs"), fsp = require("fs/promises"), path = require("path") const native = { ...fsp }, emit = (data) => fs.writeSync(1, JSON.stringify(data) + "\n") -let root = process.env.CHECK_ROOT, fault = JSON.parse(process.env.CHECK_FAULT || "null"), count = 0, forced = false, rolledBack = false, observing = true, pending = 0 +let root = process.env.CHECK_ROOT, fault = JSON.parse(process.env.CHECK_FAULT || "null"), count = 0, forced = false, rolledBack = false, observing = true, pending = 0, pendingClose, pendingCommit, pendingSnapshotMove const canonical = () => path.join(root, "tasks", "child", "history_item.json") const normalize = (p) => typeof p === "string" ? path.relative(root, p).replace(/\\/g, "/").replace(/\.(new|bak)_[^.]+\.tmp/g, ".$1.tmp") : "" function copies() { const dir = path.dirname(canonical()) - return fs.readdirSync(dir).filter((name) => name === "history_item.json" || (name.startsWith(".history_item.json.bak_") && name.endsWith(".tmp"))).map((name) => fs.readFileSync(path.join(dir, name), "utf8")) + // Native namespace changes can race this synchronous list/read observer. + // Retry the whole snapshot; never drop a missing entry from a stale list. + for (let attempt = 0; attempt < 3; attempt++) { + try { + const names = fs.readdirSync(dir).filter((name) => name === "history_item.json" || (name.startsWith(".history_item.json.bak_") && name.endsWith(".tmp"))) + if (pendingSnapshotMove) { const move = pendingSnapshotMove; pendingSnapshotMove = undefined; move() } + return names.map((name) => fs.readFileSync(path.join(dir, name), "utf8")) + } catch (error) { if (error.code !== "ENOENT") throw error } + } + throw new Error("Committed-copy snapshot retry budget exhausted") } console.error = console.warn = console.log = () => {} Math.random = () => 0.5 function cut(n, phase) { if (fault && fault.step === n && fault.kind === phase) { + if (process.env.CHECK_SCHEDULE === "late-rename") { + if (!pendingCommit) throw new Error("Regression schedule did not reach the in-flight rename") + pendingCommit() + } emit({ crash: true }); process.kill(process.pid, "SIGKILL") } } @@ -54,7 +67,22 @@ function after(n, call, error) { for (const name of ["mkdir", "access", "readdir", "stat", "readFile", "rename", "unlink"]) { fsp[name] = async (...args) => { const { n, error } = before(name, args) - try { if (error) throw error; const value = await native[name](...args); after(n, name); return value } + try { + if (error) throw error + if (name === "rename" && process.env.CHECK_SCHEDULE === "move-during-snapshot" && args[0] === canonical()) { + pendingSnapshotMove = () => fs.renameSync(...args) + if (pendingClose) pendingClose() + return await new Promise(() => {}) + } + if (name === "rename" && process.env.CHECK_SCHEDULE === "late-rename") { + // Hold the real rename until the close snapshot has been emitted. Its + // filesystem effect then lands before SIGKILL, without a JS completion event. + pendingCommit = () => fs.renameSync(...args) + if (pendingClose) pendingClose() + return await new Promise(() => {}) + } + const value = await native[name](...args); after(n, name); return value + } catch (error) { after(n, name, error); throw error } } } @@ -64,7 +92,13 @@ function callbacks(names, prefix) { const callback = args.pop(), { n, error } = before(prefix + name, args) if (error) { after(n, prefix + name, error); return callback(error) } pending++ - return fs[name](...args, (error, ...values) => { pending--; after(n, prefix + name, error); callback(error, ...values) }) + return fs[name](...args, (error, ...values) => { + const finish = () => { pending--; after(n, prefix + name, error); callback(error, ...values) } + if (prefix === "stream." && name === "close" && process.env.CHECK_SCHEDULE) { + pendingClose = finish + if (pendingCommit || pendingSnapshotMove) finish() + } else finish() + }) } return result } @@ -173,7 +207,13 @@ function committed(root: string): string[] { ) .map((name) => fs.readFileSync(path.join(dir, name), "utf8")) } -async function runtime(bundle: string, root: string, mode: string, fault?: Fault) { +async function runtime( + bundle: string, + root: string, + mode: string, + fault?: Fault, + schedule?: "late-rename" | "move-during-snapshot", +) { const child = await new Promise<{ status: number | null; stdout: string; stderr: string }>((resolve, reject) => { execFile( process.execPath, @@ -190,6 +230,7 @@ async function runtime(bundle: string, root: string, mode: string, fault?: Fault CHECK_MODE: mode, CHECK_INCOMING: encoded[2], CHECK_FAULT: JSON.stringify(fault ?? null), + CHECK_SCHEDULE: schedule, }, encoding: "utf8", timeout: 20_000, @@ -296,13 +337,19 @@ function violation(invariant: number, context: string, events: Event[]): never { .join("\n"), ) } -async function runCase(bundle: string, dir: string, mode: Mode, fault?: Fault) { +async function runCase( + bundle: string, + dir: string, + mode: Mode, + fault?: Fault, + schedule?: "late-rename" | "move-during-snapshot", +) { const root = path.join(dir, "storage") seed(root, mode) const beforeCanonical = fs.existsSync(path.join(root, relativeCanonical)) ? fs.readFileSync(path.join(root, relativeCanonical), "utf8") : undefined - const run = await runtime(bundle, root, mode, fault) + const run = await runtime(bundle, root, mode, fault, schedule) const context = `${mode} ${JSON.stringify(fault ?? "no fault")}` let latest = mode === "newer" ? 1 : 0 for (const [index, event] of run.events.entries()) { @@ -316,8 +363,12 @@ async function runCase(bundle: string, dir: string, mode: Mode, fault?: Fault) { run.events.some((event) => event.n === fault.step), "Fault cutpoint was not reached", ) - if (!committed(root).some((data) => encoded.some((entry) => entry === data))) - violation(2, context + " lost the only committed copy", run.events) + // Native renames can finish after the last JS snapshot but before SIGKILL. + // Once the child exits, its actual disk state owns follow-up expectations. + const diskVersion = Math.max(-1, ...committed(root).map((data) => encoded.findIndex((entry) => entry === data))) + if (diskVersion < latest) + violation(2, context + " lost the latest committed copy after the last snapshot", run.events) + latest = diskVersion const result = run.results[0] if ( result?.ok && @@ -342,7 +393,12 @@ async function runCase(bundle: string, dir: string, mode: Mode, fault?: Fault) { if (followup.op === "delete" && followup.value !== undefined) violation(4, context + " deleted file returned after recovery", run.events) if (followup.op !== "delete" && followup.value !== encoded[followup.op === "write" ? 2 : latest]) - violation(3, context + " invalid follow-up value", run.events) + violation( + 3, + context + + ` follow-up ${followup.op} returned an invalid value (expected version ${followup.op === "write" ? 2 : latest})`, + run.events, + ) if (followup.op === "cold" && !followup.healthy) violation(5, context + " cold-start snapshot unavailable", run.events) } @@ -354,6 +410,18 @@ async function main() { const mutation = process.argv.find((arg) => arg.startsWith("--mutation="))?.split("=")[1] const bundle = path.join(work, "production.cjs") await bundleAt(bundle, mutation) + const regression = process.argv.find((arg) => arg.startsWith("--regression="))?.split("=")[1] + if (regression === "rename-in-flight" || regression === "snapshot-race") { + const mode = regression === "rename-in-flight" ? "write" : "fallback" + const schedule = regression === "rename-in-flight" ? "late-rename" : "move-during-snapshot" + const trace = await runCase(bundle, path.join(work, "baseline"), mode) + const close = trace.find((event) => event.phase === "before" && event.call === "stream.close") + assert(close, "Regression requires the real stream-close boundary") + await runCase(bundle, path.join(work, schedule), mode, { step: close.n, kind: "after" }, schedule) + console.log(`${regression} regression passed`) + return + } + assert(!regression, "Unknown regression") if (mutation === "restore-backup-loss") { const baseline = path.join(work, "baseline") const events = await runCase(bundle, baseline, "restore") From 45599ea6939674dd2c402950bf96b62747f53b9f Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sat, 24 Oct 2026 22:05:00 +0000 Subject: [PATCH 09/14] fix(persistence): keep reconciliation progressing past unreadable tasks --- .github/workflows/code-qa.yml | 2 + docs/architecture/json-persistence-audit.md | 3 +- docs/architecture/task-lifecycle-model.md | 8 ++- scripts/code-qa-workflow.test.mjs | 13 +++++ src/core/task-persistence/TaskHistoryStore.ts | 17 ++++-- .../TaskHistoryStore.recovery.spec.ts | 52 +++++++++++++++++-- 6 files changed, 86 insertions(+), 9 deletions(-) diff --git a/.github/workflows/code-qa.yml b/.github/workflows/code-qa.yml index f03ee6b408..b574fb687c 100644 --- a/.github/workflows/code-qa.yml +++ b/.github/workflows/code-qa.yml @@ -96,6 +96,8 @@ jobs: run: pnpm lint - name: Check types run: pnpm check-types + - name: Test restart artifact sanitization + run: pnpm --filter @roo-code/vscode-e2e test:restart-artifacts - name: Validate Code QA workflow run: pnpm test:code-qa-ci - name: Validate Solheim provider smoke workflow diff --git a/docs/architecture/json-persistence-audit.md b/docs/architecture/json-persistence-audit.md index bcfc3b37d8..ee3bff381e 100644 --- a/docs/architecture/json-persistence-audit.md +++ b/docs/architecture/json-persistence-audit.md @@ -114,7 +114,8 @@ Its read path can have different behavior. - Writes task history, repair intents, merged changes, and conditional action settlement. - Recovers missing history files during reconciliation and individual reads. -- Blocks delegation repair when the history scan fails. +- Forced scans report read errors before delegation repair or replay. +- Background scans retain unreadable cached records and update readable tasks. - Keeps cached records when a refresh fails. - Removes backups under the file lock before it deletes canonical history. - Logs deletion errors other than `ENOENT`. diff --git a/docs/architecture/task-lifecycle-model.md b/docs/architecture/task-lifecycle-model.md index dca5a654db..4aa12c2144 100644 --- a/docs/architecture/task-lifecycle-model.md +++ b/docs/architecture/task-lifecycle-model.md @@ -92,7 +92,9 @@ The known-unsafe witnesses currently compare exact shortest action sequences. Th ## History-file availability boundary `TaskHistoryStore.reconcile()` recovers a missing canonical history file from its backup under the file lock. -A failed scan blocks delegation repair. +Forced scans, including startup and replay refreshes, report read failures after scanning all tasks. +A failed forced scan blocks delegation repair or replay. +Background scans keep unreadable cached records, log the first error, and continue updating other tasks. A failed refresh keeps the last cached record. ### Initialization and availability @@ -365,7 +367,9 @@ Three source mutations must fail with their named invariants: - Omitting backup removal from deletion must violate no resurrection, invariant 4. - Ignoring an existing canonical file during reader recovery must violate reader preservation, invariant 6. -Coverage excludes concurrent actors, stale takeover of a paused owner, and crashes inside fault-induced rollback paths. +The rollback baseline includes its EPERM and EIO failures, plus crashes at the recorded rollback boundaries. +Coverage excludes concurrent actors and stale takeover of a paused owner. +It also excludes crash combinations with additional replay-injected faults beyond the fixed scenario failures. It also excludes native Windows open-handle semantics and power-loss durability. The existing subprocess SIGKILL tests and extension-host restart tests remain separate checks. See the [JSON persistence contract](./json-persistence-audit.md) for caller coverage and remaining gaps. diff --git a/scripts/code-qa-workflow.test.mjs b/scripts/code-qa-workflow.test.mjs index 3f83d1129e..a470b2cf45 100644 --- a/scripts/code-qa-workflow.test.mjs +++ b/scripts/code-qa-workflow.test.mjs @@ -136,3 +136,16 @@ describe("Knip quality gate", () => { assert.doesNotMatch(job, /continue-on-error|if:/) }) }) + +describe("restart artifact privacy gate", () => { + it("runs the package-local artifact tests in the compile job on pull requests", () => { + const compile = workflow.match(/\n compile:\n(?[\s\S]*?)\n [a-z-]+:/)?.groups?.body + assert.ok(compile, "missing compile job") + assert.match(compile, /name: Test restart artifact sanitization/) + assert.match( + workflowStep("Test restart artifact sanitization"), + /run: pnpm --filter @roo-code\/vscode-e2e test:restart-artifacts\s*$/, + ) + assert.doesNotMatch(workflowStep("Test restart artifact sanitization"), /continue-on-error|if:/) + }) +}) diff --git a/src/core/task-persistence/TaskHistoryStore.ts b/src/core/task-persistence/TaskHistoryStore.ts index a04b813b86..f03e9e3c9e 100644 --- a/src/core/task-persistence/TaskHistoryStore.ts +++ b/src/core/task-persistence/TaskHistoryStore.ts @@ -411,6 +411,7 @@ export class TaskHistoryStore { const onDiskIds = new Set(taskDirNames) const cacheIds = new Set(this.cache.keys()) const liveIds = new Set() + let scanFailure: { error: unknown } | undefined for (const taskId of onDiskIds) { try { @@ -438,9 +439,13 @@ export class TaskHistoryStore { } } } catch (error) { - // An unavailable snapshot is not evidence of deletion. In - // particular, startup must not repair delegation from it. - if (!["ENOENT", "ENOTDIR"].includes(getErrorCode(error) ?? "")) throw error + // An unreadable record is not evidence of deletion. Keep its + // cached value and scan the other tasks before reporting failure. + if (!["ENOENT", "ENOTDIR"].includes(getErrorCode(error) ?? "")) { + liveIds.add(taskId) + scanFailure ??= { error } + continue + } // File may be temporarily absent during a peer's atomic // rename window in safeWriteJson. The advisory lock is // held for the entire write, so its presence means a @@ -464,6 +469,12 @@ export class TaskHistoryStore { this.taskFileMtimes.delete(taskId) } } + + if (scanFailure) { + // Startup and replay require a complete snapshot before repair. + if (options.forceRefresh) throw scanFailure.error + console.warn("[TaskHistoryStore] Reconciliation retained unreadable task records:", scanFailure.error) + } }) } diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts index 5e6bb78c7d..b92efa356c 100644 --- a/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts @@ -9,10 +9,10 @@ import { acquireFileLock, LOCK_STALE_MS } from "../../../utils/fileLock" vi.mock("fs/promises", async () => { const actual = await vi.importActual("fs/promises") - return { ...actual, rename: vi.fn(actual.rename) } + return { ...actual, rename: vi.fn(actual.rename), readFile: vi.fn(actual.readFile) } }) const actual = await vi.importActual("fs/promises") -const entryPoints = ["initialize", "reconcile", "invalidate"] as const +const entryPoints = ["initialize", "forced reconcile", "invalidate"] as const describe("TaskHistoryStore interrupted history recovery", () => { let root: string @@ -25,6 +25,7 @@ describe("TaskHistoryStore interrupted history recovery", () => { beforeEach(async () => { vi.mocked(fs.rename).mockReset().mockImplementation(actual.rename) + vi.mocked(fs.readFile).mockReset().mockImplementation(actual.readFile) root = await fs.mkdtemp(path.join(os.tmpdir(), "history-recovery-")) parent = { id: "parent", @@ -75,7 +76,8 @@ describe("TaskHistoryStore interrupted history recovery", () => { async function run(entry: (typeof entryPoints)[number]) { if (entry === "invalidate") await store.invalidate(child.id) - else await store[entry]() + else if (entry === "forced reconcile") await store.reconcile({ forceRefresh: true }) + else await store.initialize() } it.each(entryPoints)("restores an orphaned child before %s can treat it as missing", async (entry) => { @@ -132,4 +134,48 @@ describe("TaskHistoryStore interrupted history recovery", () => { expect(store.get(child.id)).toBeUndefined() expect(store.get(parent.id)).toEqual(parent) }) + it.each( + (["background", "forced", "initialize"] as const).flatMap((entry) => + (["EACCES", "EIO", "EISDIR", "null"] as const).map((code) => ({ entry, code })), + ), + )("keeps unreadable records and completes the $entry scan with $code", async ({ entry, code }) => { + const gonePath = path.join(root, "tasks", "gone", "history_item.json") + await fs.mkdir(path.dirname(gonePath), { recursive: true }) + await fs.writeFile(gonePath, JSON.stringify({ ...child, id: "gone" })) + await store.reconcile() + await fs.rm(path.dirname(gonePath), { recursive: true }) + const updated = { ...parent, totalCost: parent.totalCost + 1 } + await fs.writeFile(parentPath, JSON.stringify(updated)) + await fs.utimes(parentPath, new Date(1), new Date(1)) + await fs.utimes(canonical, new Date(2), new Date(2)) + const error = Object.assign(new Error("unreadable task"), { code }) + vi.mocked(fs.readFile).mockImplementation(async (...args) => { + if (String(args[0]) === canonical) { + if (code === "null") return "null" + throw error + } + return actual.readFile(...args) + }) + const repair = vi.fn(store["reconcileDelegationState"].bind(store)) + store["reconcileDelegationState"] = repair + const result = + entry === "initialize" ? store.initialize() : store.reconcile({ forceRefresh: entry === "forced" }) + if (entry === "background") await expect(result).resolves.toBeUndefined() + else if (code === "null") await expect(result).rejects.toBeInstanceOf(TypeError) + else await expect(result).rejects.toBe(error) + expect(store.get(child.id)).toEqual(child) + expect(store.get(parent.id)).toEqual(updated) + expect(store.get("gone")).toBeUndefined() + expect(JSON.parse(await actual.readFile(parentPath, "utf8"))).toEqual(updated) + expect(repair).not.toHaveBeenCalled() + if (entry === "initialize") expect(store.isHealthy).toBe(false) + }) + + it("preserves a failed restore during background reconciliation", async () => { + await prepare("forced reconcile") + vi.mocked(fs.rename).mockRejectedValueOnce(Object.assign(new Error("restore failed"), { code: "EIO" })) + await expect(store.reconcile()).resolves.toBeUndefined() + expect(store.get(child.id)).toEqual(child) + expect(JSON.parse(await fs.readFile(backup, "utf8"))).toEqual(child) + }) }) From 32ce403e549d0cfb77fae81c2e0a7540e1e0f3de Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sat, 24 Oct 2026 22:34:20 +0000 Subject: [PATCH 10/14] fix(ci): isolate restart artifact test compilation --- apps/vscode-e2e/package.json | 2 +- .../tsconfig.restart-artifacts.json | 8 ++++++ scripts/code-qa-workflow.test.mjs | 25 +++++++++++++++++++ 3 files changed, 34 insertions(+), 1 deletion(-) create mode 100644 apps/vscode-e2e/tsconfig.restart-artifacts.json diff --git a/apps/vscode-e2e/package.json b/apps/vscode-e2e/package.json index 06ad0bec7b..2171de92cb 100644 --- a/apps/vscode-e2e/package.json +++ b/apps/vscode-e2e/package.json @@ -7,7 +7,7 @@ "format": "prettier --write src", "test:ci": "pnpm -w bundle && pnpm --filter @roo-code/vscode-webview build && pnpm test:run", "test:ci:mock": "pnpm -w bundle && pnpm --filter @roo-code/vscode-webview build && USE_MOCK=true pnpm test:run", - "test:restart-artifacts": "tsc -p tsconfig.json && node ./out/restart/scenarioWorkspace.test.js", + "test:restart-artifacts": "tsc -p tsconfig.restart-artifacts.json && node ./out/restart/scenarioWorkspace.test.js", "test:record": "AIMOCK_RECORD=true pnpm test:ci", "test:run": "rimraf out && tsc -p tsconfig.json && dotenv -e .env.local -- node ./out/runTest.js", "themes:build": "pnpm -w bundle && pnpm --filter @roo-code/vscode-webview build && rimraf out && tsc -p tsconfig.json", diff --git a/apps/vscode-e2e/tsconfig.restart-artifacts.json b/apps/vscode-e2e/tsconfig.restart-artifacts.json new file mode 100644 index 0000000000..d59f9ccf95 --- /dev/null +++ b/apps/vscode-e2e/tsconfig.restart-artifacts.json @@ -0,0 +1,8 @@ +{ + "extends": "./tsconfig.json", + "compilerOptions": { + "rootDir": "src", + "types": ["node"] + }, + "include": ["src/restart/scenarioWorkspace.test.ts"] +} diff --git a/scripts/code-qa-workflow.test.mjs b/scripts/code-qa-workflow.test.mjs index a470b2cf45..70bfae95aa 100644 --- a/scripts/code-qa-workflow.test.mjs +++ b/scripts/code-qa-workflow.test.mjs @@ -3,6 +3,7 @@ import fs from "node:fs" import path from "node:path" import { describe, it } from "node:test" import { fileURLToPath } from "node:url" +import ts from "typescript" const repositoryRoot = path.resolve(path.dirname(fileURLToPath(import.meta.url)), "..") const workflow = fs.readFileSync(path.join(repositoryRoot, ".github/workflows/code-qa.yml"), "utf8") @@ -138,6 +139,30 @@ describe("Knip quality gate", () => { }) describe("restart artifact privacy gate", () => { + it("compiles the artifact tests without extension-host suites or workspace build dependencies", () => { + const appRoot = path.join(repositoryRoot, "apps/vscode-e2e") + const manifest = JSON.parse(fs.readFileSync(path.join(appRoot, "package.json"), "utf8")) + assert.match(manifest.scripts["test:restart-artifacts"], /tsc -p tsconfig\.restart-artifacts\.json/) + const config = ts.readConfigFile(path.join(appRoot, "tsconfig.restart-artifacts.json"), ts.sys.readFile) + assert.equal(config.error, undefined) + const parsed = ts.parseJsonConfigFileContent(config.config, ts.sys, appRoot) + assert.deepEqual(parsed.errors, []) + assert.deepEqual( + parsed.fileNames.map((file) => path.resolve(file)), + [path.join(appRoot, "src/restart/scenarioWorkspace.test.ts")], + ) + const program = ts.createProgram(parsed.fileNames, parsed.options) + const restartRoot = path.join(appRoot, "src/restart") + path.sep + const workspaceRoot = path.join(repositoryRoot, "packages") + path.sep + for (const source of program.getSourceFiles()) { + const sourcePath = path.resolve(source.fileName) + assert.ok(!sourcePath.startsWith(workspaceRoot), `Unexpected workspace dependency: ${sourcePath}`) + if (!source.isDeclarationFile) { + assert.ok(sourcePath.startsWith(restartRoot), `Unexpected application source: ${sourcePath}`) + } + } + }) + it("runs the package-local artifact tests in the compile job on pull requests", () => { const compile = workflow.match(/\n compile:\n(?[\s\S]*?)\n [a-z-]+:/)?.groups?.body assert.ok(compile, "missing compile job") From 260aea485e7f2fd85f5b8c33e0c830caa0d0881b Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sun, 25 Oct 2026 15:51:24 +0000 Subject: [PATCH 11/14] fix(persistence): keep startup responsive without trusting stale history --- docs/architecture/json-persistence-audit.md | 5 ++ docs/architecture/task-lifecycle-model.md | 15 ++++- scripts/check-json-replacement.test.ts | 1 + scripts/check-json-replacement.ts | 30 +++++++++ src/core/task-persistence/TaskHistoryStore.ts | 10 +-- .../TaskHistoryStore.initialization.spec.ts | 64 ++++++++++++++++++- .../TaskHistoryStore.reconciliation.spec.ts | 9 ++- src/core/webview/ClineProvider.ts | 11 ++-- .../webview/__tests__/ClineProvider.spec.ts | 53 +++++++++++++++ .../__tests__/webviewMessageHandler.spec.ts | 13 ++++ src/core/webview/webviewMessageHandler.ts | 4 +- 11 files changed, 197 insertions(+), 18 deletions(-) diff --git a/docs/architecture/json-persistence-audit.md b/docs/architecture/json-persistence-audit.md index ee3bff381e..7ceea79576 100644 --- a/docs/architecture/json-persistence-audit.md +++ b/docs/architecture/json-persistence-audit.md @@ -132,6 +132,11 @@ Its read path can have different behavior. ## Other readers and write paths +Legacy history can be displayed while initialization is pending or has failed. +After migration, per-task reads and metadata updates use the file-backed store. +The persisted migration marker keeps this rule active during later startup retries. +A stale legacy row cannot supply a missing task record. + `ClineProvider.getTaskWithId` reads API history through the recovery reader. It returns an empty history for `SyntaxError` or `ENOENT`. It throws other read errors. diff --git a/docs/architecture/task-lifecycle-model.md b/docs/architecture/task-lifecycle-model.md index 4aa12c2144..99974eee33 100644 --- a/docs/architecture/task-lifecycle-model.md +++ b/docs/architecture/task-lifecycle-model.md @@ -102,6 +102,8 @@ A failed refresh keeps the last cached record. Initialization retries only `ELOCKED` and `EBUSY`. It uses one timeout chain with delays of 1, 2, 4, 8, 8, and 8 seconds. Each retry repeats the full scan before delegation repair. +Replay and repair failures propagate through the same retry policy. +An intent read error is not treated as malformed JSON. Lock acquisition has separate retries, which add time to this sequence. Concurrent `initialize()` calls share one promise. @@ -112,6 +114,9 @@ Disposal cancels a pending retry. The provider therefore skips legacy migration after initialization failure. `initialized` resolves after success or terminal failure. `isHealthy` is true only after a successful attempt. +Webview state publication does not wait for this attempt. +It uses legacy history while the store is unhealthy, or omits history when requested. +The provider posts fresh state after successful initialization. Activation can continue after terminal failure. The cache can remain incomplete, and observers do not start. @@ -308,7 +313,7 @@ Add E2E coverage only when a lifecycle change crosses one of those runtime bound ## JSON replacement crash points Run `pnpm json-replacement:model-check` for the production-backed filesystem check. -The umbrella command also runs this check and its three negative controls. +The umbrella command also runs this check and its four negative controls. This check enumerates call boundaries, rather than actor interleavings. The harness bundles production code and runs it in child processes against real temporary directories. @@ -361,11 +366,17 @@ The bounds are seven baseline scenarios, 128 filesystem calls per execution, and Budget exhaustion fails the command. A violation prints the observed trace through the first failing boundary. This prefix is replayable, but it is not a shortest interleaving counterexample. -Three source mutations must fail with their named invariants: +Four source mutations must fail with their named invariants: - Swallowing a failed backup restore must violate backup preservation, invariant 2. - Omitting backup removal from deletion must violate no resurrection, invariant 4. - Ignoring an existing canonical file during reader recovery must violate reader preservation, invariant 6. +- Swallowing a replay I/O failure must violate initialization integrity, invariant 5. + +The cold-start oracle requires injected non-retryable intent read errors to reject initialization. +Checking only rejected attempts would miss a swallowed error followed by false health. +Focused production tests cover busy replay reads, failed repair writes, and pending webview initialization. +These are boundary tests, not an exhaustive liveness proof. The rollback baseline includes its EPERM and EIO failures, plus crashes at the recorded rollback boundaries. Coverage excludes concurrent actors and stale takeover of a paused owner. diff --git a/scripts/check-json-replacement.test.ts b/scripts/check-json-replacement.test.ts index 19c740cdce..cb1c63f3a8 100644 --- a/scripts/check-json-replacement.test.ts +++ b/scripts/check-json-replacement.test.ts @@ -6,6 +6,7 @@ for (const [mutation, invariant] of [ ["restore-backup-loss", 2], ["delete-keeps-backup", 4], ["reader-overwrites-newer", 6], + ["swallowed-replay-error", 5], ] as const) { test(`checker rejects ${mutation} with invariant ${invariant}`, () => { const result = spawnSync( diff --git a/scripts/check-json-replacement.ts b/scripts/check-json-replacement.ts index 4882116e5f..9a8952a056 100644 --- a/scripts/check-json-replacement.ts +++ b/scripts/check-json-replacement.ts @@ -317,6 +317,12 @@ async function bundleAt(destination: string, mutation?: string) { "/* mutation: omit backup removal */", ) } + if (mutation === "swallowed-replay-error" && args.path.endsWith("TaskHistoryStore.ts")) { + const original = "await this.replayDelegationRepairIntent()" + assert(source.includes(original), "Replay mutation anchor changed") + source = source.replace(original, "try { " + original + " } catch {}") + applied = true + } return { contents: source, loader: "ts" } }) }, @@ -385,6 +391,18 @@ async function runCase( if (result?.ok && ["read", "newer"].includes(mode) && !encoded.some((entry) => entry === result.value)) violation(3, context, run.events) if (mode === "cold" && result && !result.ok && result.repairRuns !== 0) violation(5, context, run.events) + // A read fault must not be reclassified as a missing or malformed intent. + // Check the injected outcome, not only the implication "failure => no repair". + if (mode === "cold" && fault && ["EPERM", "EACCES", "EIO"].includes(fault.kind)) { + const injected = run.events.find((event) => event.n === fault.step && event.phase === "before") + if ( + injected?.call === "readFile" && + injected.paths.some((entry) => entry.endsWith("_delegation_repair_intent.json")) + ) { + if (!result || result.ok || result.code !== fault.kind || result.repairRuns !== 0) + violation(5, context + " replay read failure published health or entered repair", run.events) + } + } const followups = (await runtime(bundle, root, "followups")).results assert.equal(followups.length, 4) for (const followup of followups) { @@ -448,6 +466,18 @@ async function main() { violation(6, "reader replaced a newer canonical value", run.events) throw new Error("Reader mutant survived") } + if (mutation === "swallowed-replay-error") { + const events = await runCase(bundle, path.join(work, "replay-baseline"), "cold") + const read = events.find( + (event) => + event.phase === "before" && + event.call === "readFile" && + event.paths.some((entry) => entry.endsWith("_delegation_repair_intent.json")), + ) + assert(read, "Replay read was not reached") + await runCase(bundle, path.join(work, "replay-mutant"), "cold", { step: read.n, kind: "EIO" }) + throw new Error("Replay mutant survived") + } assert(!mutation, "Unknown mutation") const workers = Number(process.env.JSON_REPLACEMENT_WORKERS ?? 4) assert( diff --git a/src/core/task-persistence/TaskHistoryStore.ts b/src/core/task-persistence/TaskHistoryStore.ts index f03e9e3c9e..4f80525a14 100644 --- a/src/core/task-persistence/TaskHistoryStore.ts +++ b/src/core/task-persistence/TaskHistoryStore.ts @@ -176,11 +176,9 @@ export class TaskHistoryStore { const persistedActiveIds = this.getPersistedActiveIds() // 2. Complete any two-record repair interrupted after its intent was durable. - try { - await this.replayDelegationRepairIntent() - } catch (error) { - console.error("[TaskHistoryStore] Failed to replay delegation repair intent:", error) - } + // Replay must succeed before repair or health publication. Lock failures + // use the same bounded retry policy as the initial scan. + await this.replayDelegationRepairIntent() // 3. Repair delegation inconsistencies left by a previous crash await this.reconcileDelegationState(persistedActiveIds) @@ -590,6 +588,7 @@ export class TaskHistoryStore { } } catch (error) { console.error(`[TaskHistoryStore] Failed to reconcile delegation for task ${item.id}:`, error) + throw error } // child.status === "interrupted" or "delegated" → leave as-is this pass } @@ -747,6 +746,7 @@ export class TaskHistoryStore { if (this.isFileNotFoundError(error)) { return null } + if (!(error instanceof SyntaxError)) throw error await this.quarantineDelegationRepairIntent(null, "malformed JSON") return null } diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts index d76dfeccce..491ca52e8b 100644 --- a/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts @@ -6,7 +6,7 @@ import { TaskHistoryStore } from "../TaskHistoryStore" vi.mock("fs/promises", async () => { const actual = await vi.importActual("fs/promises") - return { ...actual, readdir: vi.fn(actual.readdir) } + return { ...actual, readdir: vi.fn(actual.readdir), readFile: vi.fn(actual.readFile) } }) const actual = await vi.importActual("fs/promises") @@ -16,6 +16,7 @@ describe("TaskHistoryStore initialization retries", () => { beforeEach(async () => { vi.mocked(fs.readdir).mockReset().mockImplementation(actual.readdir) + vi.mocked(fs.readFile).mockReset().mockImplementation(actual.readFile) root = await fs.mkdtemp(path.join(os.tmpdir(), "history-initialization-")) store = new TaskHistoryStore(root) vi.useFakeTimers({ toFake: ["setTimeout", "clearTimeout"] }) @@ -91,13 +92,72 @@ describe("TaskHistoryStore initialization retries", () => { expect(fs.readdir).toHaveBeenCalledTimes(2) }) + it.each(["ELOCKED", "EBUSY", "EIO", "EACCES"])("preserves %s from the real repair-intent reader", async (code) => { + const error = Object.assign(new Error("intent unavailable"), { code }) + vi.mocked(fs.readFile).mockImplementation(async (...args) => { + if (String(args[0]).endsWith("_delegation_repair_intent.json")) throw error + return actual.readFile(...args) + }) + const repair = vi.fn(store["reconcileDelegationState"].bind(store)) + store["reconcileDelegationState"] = repair + const pending = store.initialize().catch((caught: unknown) => caught) + if (code === "ELOCKED" || code === "EBUSY") { + await waitForRetry() + expect(store.isHealthy).toBe(false) + vi.mocked(fs.readFile).mockImplementation(actual.readFile) + await vi.advanceTimersByTimeAsync(1_000) + expect(await pending).toBeUndefined() + expect(store.isHealthy).toBe(true) + } else { + expect(await pending).toBe(error) + expect(store.isHealthy).toBe(false) + expect(repair).not.toHaveBeenCalled() + } + }) + + it.each(["ELOCKED", "EBUSY", "EIO", "EACCES"])("preserves %s from a delegation repair write", async (code) => { + const directory = path.join(root, "tasks", "parent") + await fs.mkdir(directory, { recursive: true }) + await fs.writeFile( + path.join(directory, "history_item.json"), + JSON.stringify({ + id: "parent", + number: 1, + ts: 1, + task: "parent", + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + status: "delegated", + }), + ) + const error = Object.assign(new Error("repair unavailable"), { code }) + const write = vi.fn(store["writeTaskFile"].bind(store)).mockRejectedValueOnce(error) + store["writeTaskFile"] = write + const pending = store.initialize().catch((caught: unknown) => caught) + if (code === "ELOCKED" || code === "EBUSY") { + await waitForRetry() + expect(store.isHealthy).toBe(false) + await vi.advanceTimersByTimeAsync(1_000) + expect(await pending).toBeUndefined() + expect(write).toHaveBeenCalledTimes(2) + expect(store.isHealthy).toBe(true) + } else { + expect(await pending).toBe(error) + expect(store.isHealthy).toBe(false) + expect(store.get("parent")?.status).toBe("delegated") + } + }) + it("caps backoff at eight seconds and gives up after six retries", async () => { const error = Object.assign(new Error("busy"), { code: "EBUSY" }) const reconcile = vi.spyOn(store, "reconcile").mockRejectedValue(error) const result = store.initialize().catch((caught: unknown) => caught) await waitForRetry() for (const [index, delay] of [1_000, 2_000, 4_000, 8_000, 8_000, 8_000].entries()) { - await vi.advanceTimersByTimeAsync(delay) + await vi.advanceTimersByTimeAsync(delay - 1) + expect(reconcile).toHaveBeenCalledTimes(index + 1) + await vi.advanceTimersByTimeAsync(1) await vi.waitFor(() => expect(reconcile).toHaveBeenCalledTimes(index + 2)) if (index < 5) await waitForRetry() } diff --git a/src/core/task-persistence/__tests__/TaskHistoryStore.reconciliation.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.reconciliation.spec.ts index 866e27b698..bc2b0e03da 100644 --- a/src/core/task-persistence/__tests__/TaskHistoryStore.reconciliation.spec.ts +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.reconciliation.spec.ts @@ -356,7 +356,8 @@ describe("TaskHistoryStore reconcileDelegationState", () => { throw new Error("fault before child write") await writeJson(filePath, data) }) - await expect(store.initialize()).resolves.toBeUndefined() + await expect(store.initialize()).rejects.toThrow("fault before child write") + expect(store.isHealthy).toBe(false) store.dispose() safeWriteJsonMock.mockImplementation(writeJson) const replayedStore = registerStore(new TaskHistoryStore(tmpDir)) @@ -393,7 +394,8 @@ describe("TaskHistoryStore reconcileDelegationState", () => { throw new Error("fault before parent write") await writeJson(filePath, data) }) - await expect(store.initialize()).resolves.toBeUndefined() + await expect(store.initialize()).rejects.toThrow("fault before parent write") + expect(store.isHealthy).toBe(false) store.dispose() safeWriteJsonMock.mockImplementation(writeJson) const replayedStore = registerStore(new TaskHistoryStore(tmpDir)) @@ -425,7 +427,8 @@ describe("TaskHistoryStore reconcileDelegationState", () => { store = registerStore( new TaskHistoryStore(tmpDir, { onWrite: vi.fn().mockRejectedValue(new Error("fault before cleanup")) }), ) - await expect(store.initialize()).resolves.toBeUndefined() + await expect(store.initialize()).rejects.toThrow("fault before cleanup") + expect(store.isHealthy).toBe(false) const intentPath = path.join(tmpDir, "tasks", GlobalFileNames.delegationRepairIntent) expect(await fs.readFile(intentPath, "utf8")).toContain(child.id) store.dispose() diff --git a/src/core/webview/ClineProvider.ts b/src/core/webview/ClineProvider.ts index a736995865..213852177f 100644 --- a/src/core/webview/ClineProvider.ts +++ b/src/core/webview/ClineProvider.ts @@ -2359,9 +2359,10 @@ export class ClineProvider private getTaskHistoryItem(id: string): HistoryItem | undefined { const historyItem = this.taskHistoryStore.get(id) - // Once initialization and migration succeed, the file-backed store is authoritative. - // Legacy global state is only a fallback while startup is incomplete or has failed. - if (historyItem || this.taskHistoryStoreInitialized) { + // A completed migration keeps files authoritative across later startup failures. + // Legacy history can still be displayed, but must not recreate a deleted task. + const alreadyMigrated = this.context.globalState.get("taskHistoryMigratedToFiles") + if (historyItem || this.taskHistoryStoreInitialized || alreadyMigrated) { return historyItem } @@ -2711,8 +2712,8 @@ export class ClineProvider } async getStateToPostToWebview({ includeTaskHistory = true }: GetStateOptions = {}): Promise { - // Ensure the store is initialized before reading task history - await this.taskHistoryStore.initialized + // Publish the legacy fallback while initialization retries. The successful + // initialization path posts fresh state after the store becomes healthy. const { apiConfiguration, diff --git a/src/core/webview/__tests__/ClineProvider.spec.ts b/src/core/webview/__tests__/ClineProvider.spec.ts index 6d98b41a9c..f870f95999 100644 --- a/src/core/webview/__tests__/ClineProvider.spec.ts +++ b/src/core/webview/__tests__/ClineProvider.spec.ts @@ -1518,6 +1518,7 @@ describe("ClineProvider", () => { { healthy: true, includeTaskHistory: true }, { healthy: false, includeTaskHistory: true }, { healthy: false, includeTaskHistory: false }, + { healthy: true, includeTaskHistory: false }, ])( "publishes history with store health $healthy and inclusion $includeTaskHistory", async ({ healthy, includeTaskHistory }) => { @@ -1533,12 +1534,15 @@ describe("ClineProvider", () => { const cached = { ...item, id: "cached", task: "cached task" } const health = vi.spyOn(provider.taskHistoryStore, "isHealthy", "get").mockReturnValue(healthy) const getAll = vi.spyOn(provider.taskHistoryStore, "getAll").mockReturnValue([cached]) + const initialized = Object.getOwnPropertyDescriptor(provider.taskHistoryStore, "initialized")! + Object.defineProperty(provider.taskHistoryStore, "initialized", { value: new Promise(() => {}) }) await provider["contextProxy"].setValue("taskHistory", [item, { ...item, id: "invalid", ts: 0 }]) try { const state = await provider.getStateToPostToWebview({ includeTaskHistory }) expect(state.taskHistory).toEqual(includeTaskHistory ? [healthy ? cached : item] : []) expect(getAll).toHaveBeenCalledTimes(healthy && includeTaskHistory ? 1 : 0) } finally { + Object.defineProperty(provider.taskHistoryStore, "initialized", initialized) health.mockRestore() getAll.mockRestore() } @@ -3081,6 +3085,55 @@ describe("ClineProvider", () => { }) }) + describe("early launch history authority", () => { + it.each( + (["resume", "mode", "profile"] as const).flatMap((action) => + [false, true].map((cached) => ({ action, cached })), + ), + )( + "uses file-backed authority for launch-time $action with cached record $cached", + async ({ action, cached }) => { + await provider["initializeTaskHistoryStore"]() + const item = { + id: "stale-launch-task", + number: 1, + ts: 1, + task: "stale task", + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + } + await provider["contextProxy"].setValue("taskHistory", [item]) + await mockContext.globalState.update("taskHistoryMigratedToFiles", true) + const authoritative = { ...item, task: "current task", tokensIn: 42 } + if (cached) provider.taskHistoryStore["cache"].set(item.id, authoritative) + provider["taskHistoryStoreInitialized"] = false + const health = vi.spyOn(provider.taskHistoryStore, "isHealthy", "get").mockReturnValue(false) + const update = vi.spyOn(provider, "updateTaskHistory").mockResolvedValue([]) + const task = new Task({ ...defaultTaskOptions, historyItem: item }) + task.setTaskApiConfigName = vi.fn() + const current = vi.spyOn(provider, "getCurrentTask").mockReturnValue(task) + try { + expect((await provider.getStateToPostToWebview()).taskHistory).toEqual([item]) + if (action === "resume") { + if (cached) expect((await provider.getTaskWithId(item.id)).historyItem).toEqual(authoritative) + else await expect(provider.getTaskWithId(item.id)).rejects.toThrow("Task not found") + } + if (action === "mode") await provider.handleModeSwitch("architect", task) + if (action === "profile") await provider["persistStickyProviderProfileToCurrentTask"]("new-profile") + if (cached && action !== "resume") + expect(update).toHaveBeenCalledWith(expect.objectContaining(authoritative)) + else expect(update).not.toHaveBeenCalled() + expect(provider.taskHistoryStore.get(item.id)).toEqual(cached ? authoritative : undefined) + } finally { + current.mockRestore() + update.mockRestore() + health.mockRestore() + } + }, + ) + }) + describe("handleModeSwitch", () => { beforeEach(async () => { // Set up webview for each test diff --git a/src/core/webview/__tests__/webviewMessageHandler.spec.ts b/src/core/webview/__tests__/webviewMessageHandler.spec.ts index d5c72de742..774de9e220 100644 --- a/src/core/webview/__tests__/webviewMessageHandler.spec.ts +++ b/src/core/webview/__tests__/webviewMessageHandler.spec.ts @@ -2802,6 +2802,19 @@ describe("webviewMessageHandler - telemetrySetting", () => { expect(calls.at(-1)).toEqual([true]) }) + it("registers launch before posting state so initialization can refresh history", async () => { + Object.assign(mockClineProvider, { + isViewLaunched: false, + getMcpHub: vi.fn().mockReturnValue(undefined), + providerSettingsManager: { listConfig: vi.fn().mockResolvedValue(undefined) }, + }) + vi.mocked(mockClineProvider.customModesManager.getCustomModes).mockResolvedValue([]) + vi.mocked(mockClineProvider.postStateToWebview).mockImplementationOnce(async () => { + expect(Reflect.get(mockClineProvider, "isViewLaunched")).toBe(true) + }) + await webviewMessageHandler(mockClineProvider, { type: "webviewDidLaunch" }) + }) + // CodeRabbit follow-up on the finding #12 fix: webviewDidLaunch's telemetry init read state // via an async provider.getStateToPostToWebview().then(...) continuation, outside // telemetrySettingQueue -- so it could resolve after a concurrent "telemetrySetting" message diff --git a/src/core/webview/webviewMessageHandler.ts b/src/core/webview/webviewMessageHandler.ts index 5596b90e67..75a3f0a0a9 100644 --- a/src/core/webview/webviewMessageHandler.ts +++ b/src/core/webview/webviewMessageHandler.ts @@ -596,6 +596,9 @@ export const webviewMessageHandler = async ( const customModes = await provider.customModesManager.getCustomModes() await updateGlobalState("customModes", customModes) + // Register launch before the first state post so initialization cannot + // finish during launch without publishing its healthy snapshot. + provider.isViewLaunched = true await provider.postStateToWebview() void provider.workspaceTracker ?.initializeFilePaths() @@ -698,7 +701,6 @@ export const webviewMessageHandler = async ( ), ) - provider.isViewLaunched = true break case "newTask": // Initializing new instance of Cline will make sure that any From fd44800fe1d2b51f823834961e2436b6d9cf80f8 Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sun, 25 Oct 2026 16:33:49 +0000 Subject: [PATCH 12/14] fix(persistence): validate recovery backups and publish diagnostics atomically --- .../src/restart/scenarioWorkspace.test.ts | 44 +++++++-- .../src/restart/scenarioWorkspace.ts | 15 ++-- docs/architecture/json-persistence-audit.md | 6 ++ docs/architecture/task-lifecycle-model.md | 3 + scripts/check-json-replacement.ts | 19 +++- .../__tests__/safeWriteJson.recovery.test.ts | 89 +++++++++++++++++-- src/utils/safeWriteJson.ts | 59 ++++++++++-- 7 files changed, 210 insertions(+), 25 deletions(-) diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts index db34b3a123..b51b4da05d 100644 --- a/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts @@ -127,11 +127,45 @@ void test("records collection failures without copying raw files and still clean await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) }) -void test("cleans the workspace even when writing the diagnostic artifact fails", async (t) => { - const { workspace } = await scenario(t) - t.mock.method(fs, "writeFile", async () => { - throw Object.assign(new Error("disk failed"), { code: "EIO" }) +for (const failure of ["partial write", "rename"] as const) { + for (const existing of [false, true]) { + void test(`keeps the source after a failed ${failure}, previous artifact: ${existing}`, async (t) => { + const { workspace, destination } = await scenario(t) + await fs.mkdir(destination, { recursive: true }) + const artifact = path.join(destination, "diagnostics.json") + const previous = JSON.stringify({ previous: true }) + if (existing) await fs.writeFile(artifact, previous) + const write = fs.writeFile + if (failure === "partial write") { + t.mock.method(fs, "writeFile", async (file: Parameters[0]) => { + await write(file, '{"partial":') + throw Object.assign(new Error("disk failed"), { code: "EIO" }) + }) + } else { + t.mock.method(fs, "rename", async () => { + throw Object.assign(new Error("rename failed"), { code: "EIO" }) + }) + } + await assert.rejects(preserveScenarioWorkspace(workspace), { code: "EIO" }) + await fs.access(workspace.root) + if (existing) assert.equal(await fs.readFile(artifact, "utf8"), previous) + else await assert.rejects(fs.access(artifact), { code: "ENOENT" }) + assert.deepEqual(await fs.readdir(destination), existing ? ["diagnostics.json"] : []) + }) + } +} + +void test("publishes complete diagnostics before removing the source workspace", async (t) => { + const { workspace, destination } = await scenario(t) + const rename = fs.rename + t.mock.method(fs, "rename", async (source: string, target: string) => { + assert.equal(target, path.join(destination, "diagnostics.json")) + await fs.access(workspace.root) + await assert.rejects(fs.access(target), { code: "ENOENT" }) + assert(JSON.parse(await fs.readFile(source, "utf8")).sources) + await rename(source, target) }) - await assert.rejects(preserveScenarioWorkspace(workspace), { code: "EIO" }) + await preserveScenarioWorkspace(workspace) + assert.deepEqual(await fs.readdir(destination), ["diagnostics.json"]) await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) }) diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts index 8da6694f42..e4a12ec4e5 100644 --- a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts @@ -1,7 +1,7 @@ import * as os from "os" import * as path from "path" import * as fs from "fs/promises" -import { createHash } from "crypto" +import { createHash, randomUUID } from "crypto" import { readPhaseResult } from "./phaseProtocol" @@ -181,8 +181,8 @@ export async function preserveScenarioWorkspace(scenarioWorkspace: ScenarioWorks FAILURE_ARTIFACTS_DIR, path.basename(scenarioWorkspace.root), ) + const temporaryPath = path.join(destinationRoot, `.diagnostics-${randomUUID()}.tmp`) try { - await fs.rm(destinationRoot, { recursive: true, force: true }) await fs.mkdir(destinationRoot, { recursive: true }) const selections = [ { label: "phase-results", source: scenarioWorkspace.results }, @@ -226,7 +226,7 @@ export async function preserveScenarioWorkspace(scenarioWorkspace: ScenarioWorks } } await fs.writeFile( - path.join(destinationRoot, "diagnostics.json"), + temporaryPath, JSON.stringify( { sources, @@ -238,10 +238,13 @@ export async function preserveScenarioWorkspace(scenarioWorkspace: ScenarioWorks null, 2, ), + { flag: "wx", mode: 0o600 }, ) - return destinationRoot + await fs.rename(temporaryPath, path.join(destinationRoot, "diagnostics.json")) } finally { - // Collection or output errors must not leave the temporary workspace behind. - await removeScenarioWorkspace(scenarioWorkspace) + await fs.rm(temporaryPath, { force: true }) } + // Keep the source available for retry if collection or publication fails. + await removeScenarioWorkspace(scenarioWorkspace) + return destinationRoot } diff --git a/docs/architecture/json-persistence-audit.md b/docs/architecture/json-persistence-audit.md index 7ceea79576..ad8c1a491c 100644 --- a/docs/architecture/json-persistence-audit.md +++ b/docs/architecture/json-persistence-audit.md @@ -28,6 +28,12 @@ The results also include the function declaration and text examples. - The writer does not call `fsync`. - Read recovery searches for a matching backup before it takes the file lock. - Read recovery checks the canonical file and backups again under that lock. +- Recovery rejects backup symlinks and non-regular files. +- It validates the open backup descriptor before copying bytes into an exclusive temporary file. +- It publishes that regular file by rename and retains the backup until commit. + +Recovery uses `O_NOFOLLOW` where Node provides it. +Descriptor and pathname identity checks also apply on platforms without that flag. A fresh lock can belong to a paused writer. The protocol does not remove that lock before the stale interval expires. diff --git a/docs/architecture/task-lifecycle-model.md b/docs/architecture/task-lifecycle-model.md index 99974eee33..16a8d3ec0c 100644 --- a/docs/architecture/task-lifecycle-model.md +++ b/docs/architecture/task-lifecycle-model.md @@ -331,6 +331,9 @@ It does not add a production injection interface or copy the replacement protoco Each scenario starts with a committed child record and its parent. Some scenarios also contain an orphaned backup and an incomplete replacement. The baseline records stream, filesystem, and advisory-lock calls. +Recovery also records descriptor opens, stat, reads, writes, and closes. +Recovery copies a validated regular backup into a new temporary file before commit. +The original backup remains available across failed copies and interrupted commits. Each recorded call gets a SIGKILL before and after it. Each call also gets one injected EPERM, EBUSY, EACCES, or EIO error. Each resulting state gets four isolated follow-ups: read, write, delete, and cold initialization. diff --git a/scripts/check-json-replacement.ts b/scripts/check-json-replacement.ts index 9a8952a056..983b57fa9f 100644 --- a/scripts/check-json-replacement.ts +++ b/scripts/check-json-replacement.ts @@ -64,7 +64,7 @@ function after(n, call, error) { emit({ n, phase: "after", call, copies: copies(), paths: [], code: error && error.code }) cut(n, "after") } -for (const name of ["mkdir", "access", "readdir", "stat", "readFile", "rename", "unlink"]) { +for (const name of ["mkdir", "access", "readdir", "stat", "lstat", "open", "readFile", "rename", "unlink"]) { fsp[name] = async (...args) => { const { n, error } = before(name, args) try { @@ -81,7 +81,18 @@ for (const name of ["mkdir", "access", "readdir", "stat", "readFile", "rename", if (pendingClose) pendingClose() return await new Promise(() => {}) } - const value = await native[name](...args); after(n, name); return value + const value = await native[name](...args) + if (name === "open") { + for (const method of ["stat", "read", "writeFile", "close"]) { + const original = value[method].bind(value) + value[method] = async (...parameters) => { + const step = before("handle." + method, args) + try { if (step.error) throw step.error; const result = await original(...parameters); after(step.n, "handle." + method); return result } + catch (error) { after(step.n, "handle." + method, error); throw error } + } + } + } + after(n, name); return value } catch (error) { after(n, name, error); throw error } } @@ -292,7 +303,7 @@ async function bundleAt(destination: string, mutation?: string) { let source = fs.readFileSync(args.path, "utf8") if (mutation === "restore-backup-loss" && args.path.endsWith("safeWriteJson.ts")) { const original = - "await fs.rename(newestBackupPath, absoluteFilePath)\n\t\t\trestoredFrom = newestBackupPath" + "await restoreBackup(newestBackupPath, absoluteFilePath)\n\t\t\trestoredFrom = newestBackupPath" assert(source.includes(original), "Restore mutation anchor changed") source = source.replace(original, "try { " + original + " } catch {}") applied = true @@ -444,7 +455,7 @@ async function main() { const baseline = path.join(work, "baseline") const events = await runCase(bundle, baseline, "restore") const restore = events.find( - (event) => event.phase === "before" && event.call === "rename" && event.paths[0]?.includes(".bak"), + (event) => event.phase === "before" && event.call === "rename" && event.paths[0]?.includes(".new"), ) assert(restore) await runCase(bundle, path.join(work, "mutant"), "restore", { step: restore.n, kind: "EIO" }) diff --git a/src/utils/__tests__/safeWriteJson.recovery.test.ts b/src/utils/__tests__/safeWriteJson.recovery.test.ts index 3ac97f06d4..7614bd598e 100644 --- a/src/utils/__tests__/safeWriteJson.recovery.test.ts +++ b/src/utils/__tests__/safeWriteJson.recovery.test.ts @@ -15,7 +15,8 @@ vi.mock("fs/promises", async () => { ...actual, access: vi.fn(actual.access), rename: vi.fn(actual.rename), - stat: vi.fn(actual.stat), + lstat: vi.fn(actual.lstat), + open: vi.fn(actual.open), readdir: vi.fn(actual.readdir), } }) @@ -31,7 +32,8 @@ describe("interrupted JSON recovery", () => { beforeEach(async () => { vi.mocked(fs.access).mockReset().mockImplementation(actual.access) vi.mocked(fs.rename).mockReset().mockImplementation(actual.rename) - vi.mocked(fs.stat).mockReset().mockImplementation(actual.stat) + vi.mocked(fs.lstat).mockReset().mockImplementation(actual.lstat) + vi.mocked(fs.open).mockReset().mockImplementation(actual.open) vi.mocked(fs.readdir).mockReset().mockImplementation(actual.readdir) dir = await fs.mkdtemp(path.join(os.tmpdir(), "json-recovery-")) canonical = path.join(dir, "history.json") @@ -45,6 +47,83 @@ describe("interrupted JSON recovery", () => { await fs.rm(dir, { recursive: true, force: true }) }) + // Creating file symlinks requires privileges not guaranteed on Windows CI. + it.skipIf(process.platform === "win32").each(["recover", "read", "write"] as const)( + "rejects a symlinked backup through %s without reading its target", + async (entry) => { + const secret = path.join(dir, "secrets.json") + await fs.writeFile(secret, JSON.stringify({ secret: "must not be restored" })) + await fs.unlink(backup) + await fs.symlink(secret, backup) + const merge = vi.fn() + const pending = + entry === "recover" + ? recoverJsonFile(canonical) + : entry === "read" + ? readFileWithMissingRetry(canonical) + : safeWriteJson(canonical, {}, { merge }) + await expect(pending).rejects.toMatchObject({ code: "EINVAL" }) + expect(merge).not.toHaveBeenCalled() + await expect(fs.lstat(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + expect((await fs.lstat(backup)).isSymbolicLink()).toBe(true) + expect(JSON.parse(await fs.readFile(secret, "utf8"))).toEqual({ secret: "must not be restored" }) + }, + ) + + it("rejects a directory backup without publishing it", async () => { + await fs.unlink(backup) + await fs.mkdir(backup) + await expect(recoverJsonFile(canonical)).rejects.toMatchObject({ code: "EINVAL" }) + await expect(fs.lstat(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + }) + + it.skipIf(process.platform === "win32")("rejects a swapped backup even without O_NOFOLLOW", async () => { + const secret = path.join(dir, "secrets.json") + await fs.writeFile(secret, JSON.stringify({ secret: true })) + vi.mocked(fs.open).mockImplementation(async (file, flags, mode) => { + if (file === backup) { + await fs.rename(backup, backup + ".saved") + await fs.symlink(secret, backup) + // Exercise identity validation on platforms without O_NOFOLLOW. + return actual.open(file, "r", mode) + } + return actual.open(file, flags, mode) + }) + await expect(recoverJsonFile(canonical)).rejects.toMatchObject({ code: "EINVAL" }) + await expect(fs.lstat(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + expect(JSON.parse(await fs.readFile(secret, "utf8"))).toEqual({ secret: true }) + }) + + it.skipIf(process.platform === "win32")( + "copies descriptor bytes when the backup path changes after validation", + async () => { + const secret = path.join(dir, "secrets.json") + await fs.writeFile(secret, JSON.stringify({ secret: true })) + let inspections = 0 + vi.mocked(fs.lstat).mockImplementation(async (...args) => { + const stats = await actual.lstat(...args) + if (args[0] === backup && ++inspections === 3) { + await fs.rename(backup, backup + ".saved") + await fs.symlink(secret, backup) + } + return stats + }) + await recoverJsonFile(canonical) + expect((await fs.lstat(canonical)).isFile()).toBe(true) + expect(JSON.parse(await fs.readFile(canonical, "utf8"))).toEqual({ committed: true }) + expect(JSON.parse(await fs.readFile(secret, "utf8"))).toEqual({ secret: true }) + }, + ) + + it("copies a regular backup across multiple buffers before publishing it", async () => { + const committed = JSON.stringify({ text: "x".repeat(150 * 1024) }) + await fs.writeFile(backup, committed) + await recoverJsonFile(canonical) + expect((await fs.lstat(canonical)).isFile()).toBe(true) + expect(await fs.readFile(canonical, "utf8")).toBe(committed) + expect(await fs.readdir(dir)).toEqual(["history.json"]) + }) + it("preserves committed backups and aborts before merge when restoration fails", async () => { vi.mocked(fs.rename).mockRejectedValueOnce(ioError("EIO")) const merge = vi.fn() @@ -70,7 +149,7 @@ describe("interrupted JSON recovery", () => { expect(fs.rename).not.toHaveBeenCalled() }) - it.each(["readdir", "stat"] as const)("preserves backups and stops a write after %s fails", async (operation) => { + it.each(["readdir", "lstat"] as const)("preserves backups and stops a write after %s fails", async (operation) => { vi.mocked(fs[operation]).mockRejectedValueOnce(ioError("EIO")) await expect(safeWriteJson(canonical, {})).rejects.toMatchObject({ code: "EIO" }) await expect(fs.access(backup)).resolves.toBeUndefined() @@ -85,11 +164,11 @@ describe("interrupted JSON recovery", () => { await fs.utimes(backup, new Date(1_000), new Date(1_000)) await fs.utimes(newer, new Date(2_000), new Date(2_000)) // Make the vanished stat deterministic, regardless of directory order. - vi.mocked(fs.stat) + vi.mocked(fs.lstat) .mockReset() .mockImplementation((...args) => { if (args[0] === vanished) return Promise.reject(ioError("ENOENT")) - return actual.stat(...args) + return actual.lstat(...args) }) const merge = vi.fn((existing: unknown) => existing) const trace = vi.fn() diff --git a/src/utils/safeWriteJson.ts b/src/utils/safeWriteJson.ts index 58494dc147..e9c923dc6a 100644 --- a/src/utils/safeWriteJson.ts +++ b/src/utils/safeWriteJson.ts @@ -70,6 +70,55 @@ function getTempFilePrefix(absoluteFilePath: string, kind: "new" | "bak"): strin return `.${path.basename(absoluteFilePath)}.${kind}_` } +/** Copy validated backup bytes; never publish the backup pathname itself. */ +async function restoreBackup(backupPath: string, absoluteFilePath: string): Promise { + const temporaryPath = createTempFilePath(absoluteFilePath, "new") + try { + const before = await fs.lstat(backupPath, { bigint: true }) + if (!before.isFile()) + throw Object.assign(new Error("Recovery backup must be a regular file"), { code: "EINVAL" }) + const flags = + fsSync.constants.O_RDONLY | (fsSync.constants.O_NOFOLLOW ?? 0) | (fsSync.constants.O_NONBLOCK ?? 0) + const source = await fs.open(backupPath, flags) + try { + const opened = await source.stat({ bigint: true }) + const after = await fs.lstat(backupPath, { bigint: true }) + // Identity checks also protect platforms without O_NOFOLLOW. No bytes + // are read until the descriptor matches the regular entry inspected. + if ( + !opened.isFile() || + !after.isFile() || + before.dev !== opened.dev || + before.ino !== opened.ino || + after.dev !== opened.dev || + after.ino !== opened.ino + ) { + throw Object.assign(new Error("Recovery backup changed during validation"), { code: "EINVAL" }) + } + const destination = await fs.open(temporaryPath, "wx", 0o600) + try { + const buffer = Buffer.alloc(64 * 1024) + for (;;) { + const { bytesRead } = await source.read(buffer, 0, buffer.length, null) + if (bytesRead === 0) break + await destination.writeFile(buffer.subarray(0, bytesRead)) + } + } finally { + await destination.close() + } + } finally { + await source.close() + } + await fs.rename(temporaryPath, absoluteFilePath) + } finally { + try { + await fs.unlink(temporaryPath) + } catch (error) { + if (getErrorCode(error) !== "ENOENT") console.error("Failed to clean recovery temporary file:", error) + } + } +} + /** * Heals the canonical path after an interrupted previous write. Must run * under the advisory lock and before any data is read or written: temp and @@ -125,7 +174,10 @@ async function recoverInterruptedReplacementUnchecked( .filter((orphanPath) => path.basename(orphanPath).startsWith(backupPrefix)) .map(async (backupPath) => { try { - return { backupPath, mtimeMs: (await fs.stat(backupPath)).mtimeMs } + const stats = await fs.lstat(backupPath) + if (!stats.isFile()) + throw Object.assign(new Error("Recovery backup must be a regular file"), { code: "EINVAL" }) + return { backupPath, mtimeMs: stats.mtimeMs } } catch (statError) { if (getErrorCode(statError) !== "ENOENT") throw statError return null @@ -139,15 +191,12 @@ async function recoverInterruptedReplacementUnchecked( const newestBackupPath = newest.backupPath // A failed restore leaves every backup intact and aborts the write. // In particular, a merge must never observe null in this state. - await fs.rename(newestBackupPath, absoluteFilePath) + await restoreBackup(newestBackupPath, absoluteFilePath) restoredFrom = newestBackupPath } } for (const orphanPath of orphanedPaths) { - if (orphanPath === restoredFrom) { - continue - } try { await fs.unlink(orphanPath) } catch (cleanupError) { From b5396be34c0a2ecb64251b975d07451b02d7d938 Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Sun, 25 Oct 2026 22:24:02 +0000 Subject: [PATCH 13/14] fix(ci): avoid stdout backpressure in JSON crash checker --- docs/architecture/task-lifecycle-model.md | 4 +++ scripts/check-json-replacement.test.ts | 2 +- scripts/check-json-replacement.ts | 33 ++++++++++++++++++----- 3 files changed, 32 insertions(+), 7 deletions(-) diff --git a/docs/architecture/task-lifecycle-model.md b/docs/architecture/task-lifecycle-model.md index 16a8d3ec0c..198b2b8556 100644 --- a/docs/architecture/task-lifecycle-model.md +++ b/docs/architecture/task-lifecycle-model.md @@ -362,6 +362,10 @@ That final state must preserve the newest value already observed. An observer also retries a complete snapshot if a rename races its directory listing and file reads. Three failed attempts exhaust the snapshot budget and fail the check. Deterministic regressions cover both orderings without waiting for scheduling races. +Each child writes trace events synchronously to its own regular file. +The parent reads the file after child exit and removes it afterwards. +This avoids stdout pipe backpressure without buffering events across SIGKILL. +A deterministic regression makes stdout writes fail with `EAGAIN`. Deletion follow-ups run without injected faults. The best-effort delete API can resolve after an I/O failure; this check does not strengthen that contract. diff --git a/scripts/check-json-replacement.test.ts b/scripts/check-json-replacement.test.ts index cb1c63f3a8..65cf92a24a 100644 --- a/scripts/check-json-replacement.test.ts +++ b/scripts/check-json-replacement.test.ts @@ -33,7 +33,7 @@ for (const workers of ["0", "9", "1.5", "invalid"]) { }) } -for (const regression of ["rename-in-flight", "snapshot-race"]) { +for (const regression of ["rename-in-flight", "snapshot-race", "stdout-backpressure"]) { test(`accepts the deterministic ${regression} schedule`, () => { const result = spawnSync( process.execPath, diff --git a/scripts/check-json-replacement.ts b/scripts/check-json-replacement.ts index 983b57fa9f..fb3ea43d72 100644 --- a/scripts/check-json-replacement.ts +++ b/scripts/check-json-replacement.ts @@ -4,6 +4,7 @@ import * as os from "node:os" import * as path from "node:path" import { execFile } from "node:child_process" import { build } from "esbuild" +import { randomUUID } from "node:crypto" // Real filesystem fallback: no production injection seam. Each cut kills a fresh // process, so exception cleanup cannot masquerade as process-crash recovery. @@ -18,7 +19,17 @@ type Result = { op: string; ok: boolean; code?: string; value?: string; repairRu const CHILD = String.raw` const fs = require("fs"), fsp = require("fs/promises"), path = require("path") -const native = { ...fsp }, emit = (data) => fs.writeSync(1, JSON.stringify(data) + "\n") +if (process.env.CHECK_SCHEDULE === "stdout-backpressure") { + const nativeWriteSync = fs.writeSync + fs.writeSync = (fd, ...args) => { + if (fd === 1) throw Object.assign(new Error("injected stdout backpressure"), { code: "EAGAIN" }) + return nativeWriteSync(fd, ...args) + } +} +// A regular file avoids nonblocking stdout EAGAIN and keeps every event +// complete before a synchronous SIGKILL cutpoint. +const events = fs.openSync(process.env.CHECK_EVENTS, "wx") +const native = { ...fsp }, emit = (data) => fs.writeFileSync(events, JSON.stringify(data) + "\n") let root = process.env.CHECK_ROOT, fault = JSON.parse(process.env.CHECK_FAULT || "null"), count = 0, forced = false, rolledBack = false, observing = true, pending = 0, pendingClose, pendingCommit, pendingSnapshotMove const canonical = () => path.join(root, "tasks", "child", "history_item.json") const normalize = (p) => typeof p === "string" ? path.relative(root, p).replace(/\\/g, "/").replace(/\.(new|bak)_[^.]+\.tmp/g, ".$1.tmp") : "" @@ -105,7 +116,7 @@ function callbacks(names, prefix) { pending++ return fs[name](...args, (error, ...values) => { const finish = () => { pending--; after(n, prefix + name, error); callback(error, ...values) } - if (prefix === "stream." && name === "close" && process.env.CHECK_SCHEDULE) { + if (prefix === "stream." && name === "close" && ["late-rename", "move-during-snapshot"].includes(process.env.CHECK_SCHEDULE)) { pendingClose = finish if (pendingCommit || pendingSnapshotMove) finish() } else finish() @@ -223,8 +234,9 @@ async function runtime( root: string, mode: string, fault?: Fault, - schedule?: "late-rename" | "move-during-snapshot", + schedule?: "late-rename" | "move-during-snapshot" | "stdout-backpressure", ) { + const eventPath = path.join(path.dirname(root), `events-${randomUUID()}.jsonl`) const child = await new Promise<{ status: number | null; stdout: string; stderr: string }>((resolve, reject) => { execFile( process.execPath, @@ -236,6 +248,7 @@ async function runtime( path.delimiter, ), CHECK_BUNDLE: bundle, + CHECK_EVENTS: eventPath, CHECK_MAX_STEPS: String(MAX_STEPS), CHECK_ROOT: root, CHECK_MODE: mode, @@ -258,12 +271,15 @@ async function runtime( }, ) }) - const output = child.stdout + assert(fs.existsSync(eventPath), child.stderr || "Checker child did not create its trace file") + const trace = fs.readFileSync(eventPath, "utf8") + fs.unlinkSync(eventPath) + const output = trace .trim() .split("\n") .filter(Boolean) .map((line) => JSON.parse(line) as { n?: number; result?: Result; harnessError?: string; crash?: boolean }) - assert(!output.some((event) => event.harnessError), child.stdout + child.stderr) + assert(!output.some((event) => event.harnessError), trace + child.stderr) assert(child.status === 0 || output.some((event) => event.crash), child.stderr) if (fault && ["before", "after"].includes(fault.kind)) assert( @@ -359,7 +375,7 @@ async function runCase( dir: string, mode: Mode, fault?: Fault, - schedule?: "late-rename" | "move-during-snapshot", + schedule?: "late-rename" | "move-during-snapshot" | "stdout-backpressure", ) { const root = path.join(dir, "storage") seed(root, mode) @@ -450,6 +466,11 @@ async function main() { console.log(`${regression} regression passed`) return } + if (regression === "stdout-backpressure") { + await runCase(bundle, path.join(work, "stdout-backpressure"), "cold", undefined, "stdout-backpressure") + console.log("stdout-backpressure regression passed") + return + } assert(!regression, "Unknown regression") if (mutation === "restore-backup-loss") { const baseline = path.join(work, "baseline") From 554d91e40e75134f4dc1cf4370fcc2ff73fe3bd9 Mon Sep 17 00:00:00 2001 From: Elliott de Launay Date: Mon, 26 Oct 2026 00:38:18 +0000 Subject: [PATCH 14/14] fix(e2e): clean up scenario workspace after artifact publication fails --- .../src/restart/scenarioWorkspace.test.ts | 93 +++++++++++-------- .../src/restart/scenarioWorkspace.ts | 10 ++ apps/vscode-e2e/src/runTest.ts | 4 +- 3 files changed, 66 insertions(+), 41 deletions(-) diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts index b51b4da05d..2843b837f8 100644 --- a/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts @@ -3,7 +3,12 @@ import fs from "node:fs/promises" import path from "node:path" import test, { type TestContext } from "node:test" -import { createScenarioWorkspace, preserveScenarioWorkspace, removeScenarioWorkspace } from "./scenarioWorkspace" +import { + createScenarioWorkspace, + preserveScenarioWorkspace, + preserveScenarioWorkspaceForRunner, + removeScenarioWorkspace, +} from "./scenarioWorkspace" async function scenario(t: TestContext) { const workspace = await createScenarioWorkspace() @@ -127,45 +132,55 @@ void test("records collection failures without copying raw files and still clean await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) }) -for (const failure of ["partial write", "rename"] as const) { - for (const existing of [false, true]) { - void test(`keeps the source after a failed ${failure}, previous artifact: ${existing}`, async (t) => { - const { workspace, destination } = await scenario(t) - await fs.mkdir(destination, { recursive: true }) - const artifact = path.join(destination, "diagnostics.json") - const previous = JSON.stringify({ previous: true }) - if (existing) await fs.writeFile(artifact, previous) - const write = fs.writeFile - if (failure === "partial write") { - t.mock.method(fs, "writeFile", async (file: Parameters[0]) => { - await write(file, '{"partial":') - throw Object.assign(new Error("disk failed"), { code: "EIO" }) - }) - } else { - t.mock.method(fs, "rename", async () => { - throw Object.assign(new Error("rename failed"), { code: "EIO" }) - }) - } - await assert.rejects(preserveScenarioWorkspace(workspace), { code: "EIO" }) - await fs.access(workspace.root) - if (existing) assert.equal(await fs.readFile(artifact, "utf8"), previous) - else await assert.rejects(fs.access(artifact), { code: "ENOENT" }) - assert.deepEqual(await fs.readdir(destination), existing ? ["diagnostics.json"] : []) - }) +const preservationEntries = [ + { name: "retryable preservation", preserve: preserveScenarioWorkspace, keepsSource: true }, + { name: "runner cleanup", preserve: preserveScenarioWorkspaceForRunner, keepsSource: false }, +] + +for (const entry of preservationEntries) { + for (const failure of ["partial write", "rename"] as const) { + for (const existing of [false, true]) { + void test(`${entry.name}: failed ${failure}, previous artifact: ${existing}`, async (t) => { + const { workspace, destination } = await scenario(t) + await fs.mkdir(destination, { recursive: true }) + const artifact = path.join(destination, "diagnostics.json") + const previous = JSON.stringify({ previous: true }) + if (existing) await fs.writeFile(artifact, previous) + const write = fs.writeFile + if (failure === "partial write") { + t.mock.method(fs, "writeFile", async (file: Parameters[0]) => { + await write(file, '{"partial":') + throw Object.assign(new Error("disk failed"), { code: "EIO" }) + }) + } else { + t.mock.method(fs, "rename", async () => { + throw Object.assign(new Error("rename failed"), { code: "EIO" }) + }) + } + await assert.rejects(entry.preserve(workspace), { code: "EIO" }) + if (entry.keepsSource) await fs.access(workspace.root) + else await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) + if (existing) assert.equal(await fs.readFile(artifact, "utf8"), previous) + else await assert.rejects(fs.access(artifact), { code: "ENOENT" }) + assert.deepEqual(await fs.readdir(destination), existing ? ["diagnostics.json"] : []) + }) + } } } -void test("publishes complete diagnostics before removing the source workspace", async (t) => { - const { workspace, destination } = await scenario(t) - const rename = fs.rename - t.mock.method(fs, "rename", async (source: string, target: string) => { - assert.equal(target, path.join(destination, "diagnostics.json")) - await fs.access(workspace.root) - await assert.rejects(fs.access(target), { code: "ENOENT" }) - assert(JSON.parse(await fs.readFile(source, "utf8")).sources) - await rename(source, target) +for (const entry of preservationEntries) { + void test(`${entry.name}: publishes complete diagnostics before removing the source workspace`, async (t) => { + const { workspace, destination } = await scenario(t) + const rename = fs.rename + t.mock.method(fs, "rename", async (source: string, target: string) => { + assert.equal(target, path.join(destination, "diagnostics.json")) + await fs.access(workspace.root) + await assert.rejects(fs.access(target), { code: "ENOENT" }) + assert(JSON.parse(await fs.readFile(source, "utf8")).sources) + await rename(source, target) + }) + await entry.preserve(workspace) + assert.deepEqual(await fs.readdir(destination), ["diagnostics.json"]) + await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) }) - await preserveScenarioWorkspace(workspace) - assert.deepEqual(await fs.readdir(destination), ["diagnostics.json"]) - await assert.rejects(fs.access(workspace.root), { code: "ENOENT" }) -}) +} diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts index e4a12ec4e5..198cc3888b 100644 --- a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts @@ -248,3 +248,13 @@ export async function preserveScenarioWorkspace(scenarioWorkspace: ScenarioWorks await removeScenarioWorkspace(scenarioWorkspace) return destinationRoot } + +/** The runner has no retry step, so it must also clean up failed publications. */ +export async function preserveScenarioWorkspaceForRunner(scenarioWorkspace: ScenarioWorkspace): Promise { + try { + return await preserveScenarioWorkspace(scenarioWorkspace) + } catch (error) { + await removeScenarioWorkspace(scenarioWorkspace) + throw error + } +} diff --git a/apps/vscode-e2e/src/runTest.ts b/apps/vscode-e2e/src/runTest.ts index 978a8d2d08..d2a3682a89 100644 --- a/apps/vscode-e2e/src/runTest.ts +++ b/apps/vscode-e2e/src/runTest.ts @@ -23,7 +23,7 @@ import { addUseMcpToolResultFixtures } from "./fixtures/use-mcp-tool" import { addWriteToFileResultFixtures } from "./fixtures/write-to-file" import { createScenarioWorkspace, - preserveScenarioWorkspace, + preserveScenarioWorkspaceForRunner, removeScenarioWorkspace, } from "./restart/scenarioWorkspace" import { runRestartScenario } from "./restart/vscodeCoordinator" @@ -235,7 +235,7 @@ async function main() { // Raw histories, phase errors, and logs must never enter the artifact. if (runFailed) { try { - const preservedAt = await preserveScenarioWorkspace(scenarioWorkspace) + const preservedAt = await preserveScenarioWorkspaceForRunner(scenarioWorkspace) console.error(`Restart scenario diagnostics saved for failure inspection: ${preservedAt}`) } catch (preserveError) { console.error("Failed to preserve the restart scenario workspace:", preserveError)