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/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index 4b33fc678b..4ab8ff735c 100644 --- a/.github/workflows/e2e.yml +++ b/.github/workflows/e2e.yml @@ -156,6 +156,16 @@ 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 + # 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/**/diagnostics.json + 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/package.json b/apps/vscode-e2e/package.json index d19b5b765b..2171de92cb 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.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/src/restart/scenarioWorkspace.test.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts new file mode 100644 index 0000000000..2843b837f8 --- /dev/null +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.test.ts @@ -0,0 +1,186 @@ +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, + preserveScenarioWorkspaceForRunner, + 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" }) +}) + +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"] : []) + }) + } + } +} + +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" }) + }) +} diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts index 9ce49deaf0..198cc3888b 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, randomUUID } from "crypto" + +import { readPhaseResult } from "./phaseProtocol" const SCENARIO_ROOT_PREFIX = "roo-vscode-e2e-restart-" @@ -56,3 +59,202 @@ export async function removeScenarioWorkspace(scenarioWorkspace: ScenarioWorkspa await fs.rm(root, { recursive: true, force: true }) } + +const FAILURE_ARTIFACTS_DIR = "test-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, + "../../", + FAILURE_ARTIFACTS_DIR, + path.basename(scenarioWorkspace.root), + ) + const temporaryPath = path.join(destinationRoot, `.diagnostics-${randomUUID()}.tmp`) + try { + 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( + temporaryPath, + 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, + ), + { flag: "wx", mode: 0o600 }, + ) + await fs.rename(temporaryPath, path.join(destinationRoot, "diagnostics.json")) + } finally { + await fs.rm(temporaryPath, { force: true }) + } + // Keep the source available for retry if collection or publication fails. + 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/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/runTest.ts b/apps/vscode-e2e/src/runTest.ts index 88c687bc76..d2a3682a89 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, + preserveScenarioWorkspaceForRunner, + 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,18 @@ async function main() { await fs.rm(testWorkspace, { recursive: true, force: true }) } if (scenarioWorkspace) { - await removeScenarioWorkspace(scenarioWorkspace) + // 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 preserveScenarioWorkspaceForRunner(scenarioWorkspace) + console.error(`Restart scenario diagnostics saved 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/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/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/docs/architecture/json-persistence-audit.md b/docs/architecture/json-persistence-audit.md new file mode 100644 index 0000000000..ad8c1a491c --- /dev/null +++ b/docs/architecture/json-persistence-audit.md @@ -0,0 +1,174 @@ +# JSON persistence contract and caller inventory + +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 + +- 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. +- 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. +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` + +- 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. + +### `core/task-persistence/apiMessages.ts` + +- 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. + +### `core/task-persistence/TaskHistoryStore.ts` + +- Writes task history, repair intents, merged changes, and conditional action settlement. +- Recovers missing history files during reconciliation and individual reads. +- 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`. +- 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). + +### `core/context-tracking/FileContextTracker.ts` + +- 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). + +## 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. +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. + +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. + +Repair-intent quarantine and removal use rename or unlink operations. +These operations do not replace JSON content. + +`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). + +Workspace edits, credential files, and CLI state use other write paths. +This contract does not cover those paths. + +## Validation limits + +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. + +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 eaeb61d987..198b2b8556 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. @@ -88,6 +89,52 @@ 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 + +`TaskHistoryStore.reconcile()` recovers a missing canonical history file from its backup under the file lock. +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 + +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. +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. +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. +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 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). @@ -262,3 +309,85 @@ 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 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. +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. +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. +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. +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. +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. + +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. +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. +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/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..65cf92a24a --- /dev/null +++ b/scripts/check-json-replacement.test.ts @@ -0,0 +1,47 @@ +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], + ["swallowed-replay-error", 5], +] 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/) + }) +} + +for (const regression of ["rename-in-flight", "snapshot-race", "stdout-backpressure"]) { + 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 new file mode 100644 index 0000000000..fb3ea43d72 --- /dev/null +++ b/scripts/check-json-replacement.ts @@ -0,0 +1,573 @@ +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" +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. +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") +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") : "" +function copies() { + const dir = path.dirname(canonical()) + // 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") + } +} +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", "lstat", "open", "readFile", "rename", "unlink"]) { + fsp[name] = async (...args) => { + const { n, error } = before(name, args) + 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) + 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 } + } +} +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) => { + const finish = () => { pending--; after(n, prefix + name, error); callback(error, ...values) } + if (prefix === "stream." && name === "close" && ["late-rename", "move-during-snapshot"].includes(process.env.CHECK_SCHEDULE)) { + pendingClose = finish + if (pendingCommit || pendingSnapshotMove) finish() + } else finish() + }) + } + 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, + 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, + ["-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_EVENTS: eventPath, + CHECK_MAX_STEPS: String(MAX_STEPS), + CHECK_ROOT: root, + CHECK_MODE: mode, + CHECK_INCOMING: encoded[2], + CHECK_FAULT: JSON.stringify(fault ?? null), + CHECK_SCHEDULE: schedule, + }, + 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, + }) + }, + ) + }) + 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), trace + 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 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 + } + 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 */", + ) + } + 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" } + }) + }, + }, + ], + }) + 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, + schedule?: "late-rename" | "move-during-snapshot" | "stdout-backpressure", +) { + 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, schedule) + 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", + ) + // 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 && + ["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) + // 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) { + 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 + + ` 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) + } + 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) + 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 + } + 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") + const events = await runCase(bundle, baseline, "restore") + const restore = events.find( + (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" }) + 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") + } + 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( + 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/scripts/code-qa-workflow.test.mjs b/scripts/code-qa-workflow.test.mjs index 3f83d1129e..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") @@ -136,3 +137,40 @@ describe("Knip quality gate", () => { assert.doesNotMatch(job, /continue-on-error|if:/) }) }) + +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") + 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/__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 346d697d9a..4f80525a14 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 } 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,70 @@ export class TaskHistoryStore { /** * Scan task files, reconcile delegation state, start watchers. */ - async initialize(): Promise { + initialize(): Promise { + if (this.initializationHealthy) return Promise.resolve() + if (!this.initializationPromise) { + this.initializationPromise = this.initializeWithRetry().finally(() => { + this.initializationPromise = undefined + }) + } + return this.initializationPromise + } + + private async initializeWithRetry(): Promise { try { - const tasksDir = await this.getTasksDir() - await fs.mkdir(tasksDir, { recursive: true }) + 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() + } + } - // 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() + private async initializeAttempt(): Promise { + const tasksDir = await this.getTasksDir() + await fs.mkdir(tasksDir, { recursive: true }) - // 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) - } + // 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() - // 3. Repair delegation inconsistencies left by a previous crash - await this.reconcileDelegationState(persistedActiveIds) + // 2. Complete any two-record repair interrupted after its intent was durable. + // Replay must succeed before repair or health publication. Lock failures + // use the same bounded retry policy as the initial scan. + await this.replayDelegationRepairIntent() - // 4. Start fs.watch for cross-instance reactivity - this.startWatcher() + // 3. Repair delegation inconsistencies left by a previous crash + await this.reconcileDelegationState(persistedActiveIds) - // 5. Start periodic reconciliation as a defensive fallback - this.startPeriodicReconciliation() - } finally { - // Mark initialization as complete so callers awaiting `initialized` can proceed - this.resolveInitialized() - } + // 4. Start fs.watch for cross-instance reactivity + this.startWatcher() + + // 5. Start periodic reconciliation as a defensive fallback + this.startPeriodicReconciliation() } /** @@ -149,6 +195,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) @@ -280,9 +333,13 @@ export class TaskHistoryStore { // Remove per-task file (best-effort) try { const filePath = await this.getTaskFilePath(taskId) - await withFileLock(filePath, (absoluteFilePath) => fs.unlink(absoluteFilePath)) - } catch { - // File may already be deleted + await withFileLock(filePath, async (absoluteFilePath) => { + await removeJsonBackups(absoluteFilePath) + await fs.unlink(absoluteFilePath) + }) + } 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 @@ -308,9 +365,13 @@ export class TaskHistoryStore { // Remove per-task file (best-effort) try { const filePath = await this.getTaskFilePath(taskId) - await withFileLock(filePath, (absoluteFilePath) => fs.unlink(absoluteFilePath)) - } catch { - // File may already be deleted + await withFileLock(filePath, async (absoluteFilePath) => { + await removeJsonBackups(absoluteFilePath) + await fs.unlink(absoluteFilePath) + }) + } catch (error) { + if (getErrorCode(error) !== "ENOENT") + console.warn(`[TaskHistoryStore] Failed to delete task ${taskId}:`, error) } } @@ -337,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 } @@ -347,11 +409,16 @@ 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 { 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 && @@ -369,7 +436,14 @@ export class TaskHistoryStore { this.cache.set(taskId, item) } } - } catch { + } catch (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 @@ -393,6 +467,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) + } }) } @@ -508,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 } @@ -665,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 } @@ -769,17 +851,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) }) } @@ -888,10 +967,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.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.initialization.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts new file mode 100644 index 0000000000..491ca52e8b --- /dev/null +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts @@ -0,0 +1,184 @@ +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), readFile: vi.fn(actual.readFile) } +}) +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) + 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"] }) + }) + + 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.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 - 1) + expect(reconcile).toHaveBeenCalledTimes(index + 1) + await vi.advanceTimersByTimeAsync(1) + 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.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.reconciliation.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.reconciliation.spec.ts index e37fd1a25e..bc2b0e03da 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) @@ -353,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)) @@ -390,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)) @@ -422,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/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts new file mode 100644 index 0000000000..b92efa356c --- /dev/null +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts @@ -0,0 +1,181 @@ +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), readFile: vi.fn(actual.readFile) } +}) +const actual = await vi.importActual("fs/promises") +const entryPoints = ["initialize", "forced 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) + vi.mocked(fs.readFile).mockReset().mockImplementation(actual.readFile) + 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 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) => { + 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) + }) + 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) + }) + 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) + }) +}) 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__/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..e022c47712 100644 --- a/src/core/task-persistence/__tests__/taskMessages.spec.ts +++ b/src/core/task-persistence/__tests__/taskMessages.spec.ts @@ -14,13 +14,16 @@ 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), })) // Import after mocks import { saveTaskMessages, readTaskMessages } from "../taskMessages" import { formatErrorDetail } from "../readFileWithMissingRetry" +import { setPersistenceTraceSink } from "../persistenceTrace" let tmpBaseDir: string @@ -35,6 +38,7 @@ beforeEach(async () => { afterEach(() => { vi.useRealTimers() vi.restoreAllMocks() + setPersistenceTraceSink(undefined) }) describe("taskMessages.saveTaskMessages", () => { @@ -63,7 +67,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 +109,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 @@ -182,7 +223,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 new file mode 100644 index 0000000000..4067b8fb44 --- /dev/null +++ b/src/core/task-persistence/persistenceTrace.ts @@ -0,0 +1,7 @@ +// 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 1036049470..7f06923b6f 100644 --- a/src/core/task-persistence/readFileWithMissingRetry.ts +++ b/src/core/task-persistence/readFileWithMissingRetry.ts @@ -1,17 +1,18 @@ 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. +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, +// 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. 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 -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 @@ -41,6 +42,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/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/core/webview/ClineProvider.ts b/src/core/webview/ClineProvider.ts index 3d88df632b..213852177f 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" @@ -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)}`) } @@ -2358,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 } @@ -2385,21 +2387,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)}`, ) } @@ -2716,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, @@ -2908,8 +2904,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 93543435e2..f870f95999 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" @@ -1486,7 +1486,71 @@ 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 }, + { healthy: true, 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]) + 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() + } + }, + ) + 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 +1580,7 @@ describe("ClineProvider", () => { expect(getAllSpy).toHaveBeenCalledOnce() expect(historyReadPhases).toEqual([true]) expect(state.taskHistory).toEqual([historyItem]) + health.mockRestore() }) describe("postStateToWebviewThrottled", () => { @@ -3020,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 @@ -5808,6 +5922,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", @@ -5849,13 +5975,46 @@ 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" }] + 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) + }) + + 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).mockImplementation(async (filePath) => { + if (filePath === apiHistoryPath) throw Object.assign(new Error(code), { code }) + return "" + }) + 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 +6024,19 @@ 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) + vi.mocked(fsp.readFile).mockImplementation(async (filePath) => + filePath === apiHistoryPath ? "{not valid json!!!" : "", + ) 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/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/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 diff --git a/src/eslint-suppressions.json b/src/eslint-suppressions.json index 0dd477ab2d..cfde98cf90 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": { @@ -1686,7 +1686,7 @@ }, "utils/safeWriteJson.ts": { "@typescript-eslint/no-explicit-any": { - "count": 4 + "count": 3 } }, "vitest.setup.ts": { diff --git a/src/extension.ts b/src/extension.ts index 6ce42aacd5..34865230c4 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,10 @@ 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(createDualLogger(createOutputChannelLogger(outputChannel))) outputChannel.appendLine(`${Package.name} extension activated - ${JSON.stringify(Package)}`) // Initialize network proxy configuration early, before any network requests. @@ -402,6 +407,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..76532848f2 100644 --- a/src/extension/api.ts +++ b/src/extension/api.ts @@ -33,6 +33,8 @@ 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" import { getCommands } from "../services/command/commands" @@ -360,10 +362,17 @@ export class API extends EventEmitter implements RooCodeAPI { taskId, globalStoragePath: this.sidebarProvider.contextProxy.globalStorageUri.fsPath, }) - } catch { + } catch (error) { + tracePersistenceEvent("ui-messages-marker-check", { + taskId, + result: "read-error", + detail: formatErrorDetail(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/__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.interruption.test.ts b/src/utils/__tests__/safeWriteJson.interruption.test.ts new file mode 100644 index 0000000000..a7851ad1cb --- /dev/null +++ b/src/utils/__tests__/safeWriteJson.interruption.test.ts @@ -0,0 +1,198 @@ +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 { LOCK_STALE_MS } from "../fileLock" +import { setPersistenceTraceSink } from "../persistenceTrace" +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: SIGKILL before the replacement lands. Any rename +// whose destination is the canonical path is the commit step, whatever +// 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.kill(process.pid, "SIGKILL") + } + 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.kill(process.pid, "SIGKILL") + }) + .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; signal: NodeJS.Signals | 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, signal) => { + clearTimeout(timeout) + resolve({ + code, + signal, + 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 () => { + setPersistenceTraceSink(undefined) + await fs.rm(tempDir, { recursive: true, force: true }) + }) + + 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") + + // 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_EPERM: eperm ? "1" : "0", + INTERRUPTION_PAYLOAD: JSON.stringify({ + ui_messages: [{ ts: 2, type: "say", text: "INTERRUPTED_WRITE" }], + }), + 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") + // 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. + 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) + + 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.recovery.test.ts b/src/utils/__tests__/safeWriteJson.recovery.test.ts new file mode 100644 index 0000000000..7614bd598e --- /dev/null +++ b/src/utils/__tests__/safeWriteJson.recovery.test.ts @@ -0,0 +1,293 @@ +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), + lstat: vi.fn(actual.lstat), + open: vi.fn(actual.open), + 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.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") + 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 }) + }) + + // 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() + 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", "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() + 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.lstat) + .mockReset() + .mockImplementation((...args) => { + if (args[0] === vanished) return Promise.reject(ioError("ENOENT")) + return actual.lstat(...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([ + { 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() + }) + + 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/__tests__/safeWriteJson.test.ts b/src/utils/__tests__/safeWriteJson.test.ts index 0ebdea281d..647ee2d12d 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,117 @@ 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) + }) + 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/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 7da68b2a7a..e9c923dc6a 100644 --- a/src/utils/safeWriteJson.ts +++ b/src/utils/safeWriteJson.ts @@ -3,7 +3,19 @@ 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 + * 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 +38,235 @@ 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 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), + `.${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}_` +} + +/** 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 + * 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 recoverInterruptedReplacementUnchecked( + 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 (error) { + if (getErrorCode(error) !== "ENOENT") throw error + 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 (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) => { + try { + 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 + } + }), + ) + const backups = backupStats.filter((backup) => backup !== null) + backups.sort((a, b) => b.mtimeMs - a.mtimeMs || b.backupPath.localeCompare(a.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 restoreBackup(newestBackupPath, absoluteFilePath) + restoredFrom = newestBackupPath + } + } + + for (const orphanPath of orphanedPaths) { + try { + await fs.unlink(orphanPath) + } catch (cleanupError) { + console.error(`Failed to clean up interrupted-write leftover ${orphanPath}:`, cleanupError) + } + } + + 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 + } +} + +export 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 * - 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. * @@ -74,8 +307,22 @@ 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 + // canonical path with an orphaned backup, or leftover replacement + // files. Runs first so a merge callback reads the restored content. + const recovery = await withRecoveryTrace(absoluteFilePath, () => + recoverInterruptedReplacementUnchecked(absoluteFilePath), + ).catch((error: unknown) => { + notifyTrace(options?.trace, { stage: "recover", detail: `failed: ${getErrorCode(error) ?? String(error)}` }) + throw error + }) + if (recovery.foundLeftovers) { + notifyTrace(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 +340,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: Stream the replacement to a temporary file before commit. + notifyTrace(options?.trace, { stage: "write-start" }) + actualTempNewFilePath = createTempFilePath(absoluteFilePath, "new") await _streamDataToFile(actualTempNewFilePath, data, options?.prettyPrint) - // 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 + notifyTrace(options?.trace, { stage: "replacement-rename" }) + await fs.rename(actualTempNewFilePath, absoluteFilePath) + } catch (renameError: unknown) { + if (getErrorCode(renameError) !== "EPERM") { + throw renameError } - // Target file does not exist, so no backup is made. actualTempBackupFilePath remains null. + + // 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. + notifyTrace(options?.trace, { stage: "backup-rename", detail: "eperm-fallback" }) + const backupPath = createTempFilePath(absoluteFilePath, "bak") + await fs.rename(absoluteFilePath, backupPath) + actualTempBackupFilePath = backupPath + notifyTrace(options?.trace, { stage: "replacement-rename", detail: "eperm-fallback" }) + await fs.rename(actualTempNewFilePath, absoluteFilePath) } - // Step 3: Rename the new temporary file to the target file path. - // This is the main "commit" step. - 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 - // 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) @@ -151,7 +401,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 @@ -177,19 +427,11 @@ 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 { + 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,