diff --git a/.github/workflows/code-qa.yml b/.github/workflows/code-qa.yml index f03ee6b408..6aad106c4d 100644 --- a/.github/workflows/code-qa.yml +++ b/.github/workflows/code-qa.yml @@ -109,6 +109,7 @@ jobs: - name: Check agent evals types run: pnpm agent-evals:check-types - name: Model-check task lifecycle protocols + timeout-minutes: 10 run: pnpm lifecycle:model-check - name: Validate MCP OAuth integration run: pnpm mcp:integration-check diff --git a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts index 9ce49deaf0..5a1c091f77 100644 --- a/apps/vscode-e2e/src/restart/scenarioWorkspace.ts +++ b/apps/vscode-e2e/src/restart/scenarioWorkspace.ts @@ -33,20 +33,16 @@ export async function createScenarioWorkspace(): Promise { await Promise.all( [ - scenarioPath(scenarioWorkspace, "workspace"), - scenarioPath(scenarioWorkspace, "userData"), - scenarioPath(scenarioWorkspace, "extensions"), - scenarioPath(scenarioWorkspace, "results"), + scenarioWorkspace.workspace, + scenarioWorkspace.userData, + scenarioWorkspace.extensions, + scenarioWorkspace.results, ].map((directory) => fs.mkdir(directory, { recursive: true })), ) return scenarioWorkspace } -function scenarioPath(scenarioWorkspace: ScenarioWorkspace, key: "workspace" | "userData" | "extensions" | "results") { - return scenarioWorkspace[key] -} - export async function removeScenarioWorkspace(scenarioWorkspace: ScenarioWorkspace): Promise { const root = path.resolve(scenarioWorkspace.root) const tempRoot = path.resolve(os.tmpdir()) diff --git a/apps/vscode-e2e/src/restart/vscodeCoordinator.ts b/apps/vscode-e2e/src/restart/vscodeCoordinator.ts index 9400aaaaf4..cddab1f029 100644 --- a/apps/vscode-e2e/src/restart/vscodeCoordinator.ts +++ b/apps/vscode-e2e/src/restart/vscodeCoordinator.ts @@ -27,6 +27,12 @@ function phaseEnvironment(options: RestartCoordinatorOptions, phase: RestartPhas E2E_PHASE: phase, E2E_SCENARIO: options.scenario, E2E_RESULTS_DIR: options.workspace.results, + E2E_GLOBAL_STORAGE_PATH: path.join( + options.workspace.userData, + "User", + "globalStorage", + "zoocodeorganization.zoo-code", + ), } } diff --git a/apps/vscode-e2e/src/suite/restart-persistence.test.ts b/apps/vscode-e2e/src/suite/restart-persistence.test.ts index 0d508273e3..6068defd05 100644 --- a/apps/vscode-e2e/src/suite/restart-persistence.test.ts +++ b/apps/vscode-e2e/src/suite/restart-persistence.test.ts @@ -1,4 +1,6 @@ import * as assert from "assert" +import * as fs from "fs/promises" +import * as path from "path" import * as vscode from "vscode" import { RooCodeEventName, type RooCodeAPI } from "@roo-code/types" @@ -60,6 +62,28 @@ async function runCreate(api: RooCodeAPI): Promise { // never reads a task directory whose final write has not landed yet. const createdTaskId: string = taskId await waitFor(() => api.hasTaskUiMessageText(createdTaskId, MARKER)) + const globalStoragePath = process.env.E2E_GLOBAL_STORAGE_PATH + if (!globalStoragePath) throw new Error("E2E_GLOBAL_STORAGE_PATH is required") + // The public history API reads the cache; check the committed file + // before quitting so the fresh host has both history and messages. + await waitFor(async () => { + try { + const persisted: unknown = JSON.parse( + await fs.readFile( + path.join(globalStoragePath, "tasks", createdTaskId, "history_item.json"), + "utf8", + ), + ) + return ( + typeof persisted === "object" && + persisted !== null && + "id" in persisted && + persisted.id === createdTaskId + ) + } catch { + return false + } + }) const result: PhaseResult = { version: PHASE_RESULT_VERSION, @@ -103,7 +127,31 @@ async function runVerify(api: RooCodeAPI): Promise { const historyItem = await api.getTaskHistoryItem(taskId) assert.ok(historyItem, "Task history item should be available after restart") assert.ok(historyItem.task.includes("RESTART_PERSISTENCE_SMOKE"), "History title should persist after restart") + + // No task is running in this fresh host yet. Recreate the on-disk + // state left by an interrupted two-step replacement, then require + // public reads to recover it before resume can write anything. + const globalStoragePath = process.env.E2E_GLOBAL_STORAGE_PATH + if (!globalStoragePath) throw new Error("E2E_GLOBAL_STORAGE_PATH is required") + const taskDir = path.join(globalStoragePath, "tasks", taskId) + const interruptedFiles = [] + for (const file of ["ui_messages.json", "api_conversation_history.json"]) { + const canonical = path.join(taskDir, file) + const backup = path.join(taskDir, `.${file}.bak_restart_e2e.tmp`) + const committed = await fs.readFile(canonical, "utf8") + await fs.rename(canonical, backup) + interruptedFiles.push({ canonical, backup, committed }) + } + assert.strictEqual(await api.hasTaskUiMessageText(taskId, MARKER), true, "Read should recover the UI marker") await waitForMarkedCompletion(api, taskId) + for (const { canonical, backup, committed } of interruptedFiles) { + assert.strictEqual( + await fs.readFile(canonical, "utf8"), + committed, + "Read recovery must retain committed bytes", + ) + await assert.rejects(fs.access(backup), { code: "ENOENT" }, "Recovery should consume the backup") + } await api.resumeTask(taskId) await waitFor(() => taskMessages.some(({ type, ask }) => type === "ask" && ask === "resume_completed_task")) @@ -137,7 +185,7 @@ async function runVerify(api: RooCodeAPI): Promise { } suite("Restart persistence", () => { - test("persists completed task across a fresh extension host", async () => { + test("persists and recovers completed task history across a fresh extension host", async () => { const api = globalThis.api if (process.env.E2E_PHASE === "create") { await runCreate(api) diff --git a/docs/architecture/json-persistence-audit.md b/docs/architecture/json-persistence-audit.md new file mode 100644 index 0000000000..f40c94c3c2 --- /dev/null +++ b/docs/architecture/json-persistence-audit.md @@ -0,0 +1,212 @@ +# 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, then removes the restored backup during leftover cleanup. + +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. + +Successful backup restoration emits `json-recovered`. +Leftover-file cleanup errors emit `json-cleanup-failed` with the canonical path and error code, and also go to the console. +These errors do not reject a write that otherwise succeeded. + +Trace events are local diagnostics and can include absolute paths, task IDs, and filesystem error details. Treat extension logs as private when sharing them. + +## 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. +- Migration replacement failure keeps the legacy source; unlink failure reports an error while keeping the newly committed current file and the legacy source. + +### `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`. +- If backup removal fails, canonical deletion is skipped to avoid restoring stale data later. The best-effort API still evicts the cache. Since the canonical record remains on disk, a later scan or restart can show the task again; this API does not confirm durable deletion. +- The legacy global-state migration writer backfills missing per-task files and then repairs delegations. Its active-task snapshot survives an explicit retry after a partial repair. +- 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 or legacy migration is pending or has failed. +All history-list readers use the same readiness rule, including base state, webview state, broadcasts, and recent tasks. Explicit open, export, delete, and cost queries wait for the shared provider initialization attempt and retry after a terminal failure. Runtime metadata reads for cached tasks bypass that wait so startup cannot block cancellation, completion, or delegation. A failed attempt produces an availability error, rather than declaring a task absent. +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. +Metadata-only callers explicitly skip API-history loading, including cancellation, completion/delegation guards, checkpoint restoration, and extension metadata queries. Export and conversation readers retain the full read. +Task loading and parent reopening also use the message readers. +Error diagnostics and debug API/UI history actions read through `readFileWithMissingRetry`, so a canonical-only existence check cannot bypass backup recovery. +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). + +## Write-path correspondence + +Every production `safeWriteJson` call is covered by the consumer inventory above. This table distinguishes writers that share a module, including the legacy migration and repair-intent paths. + +| Writer / operation | Persistence authority and read path | Failure / recovery boundary | +| ---------------------------------------------------- | ---------------------------------------------------------------------------- | ---------------------------------------------------------------------------------------------- | +| Endpoint cache; model cache | Fetched models replace disposable cache files; direct or synchronous readers | Missing cache is refetched; refresh errors are reported | +| MCP global creation | Settings file under shared writer lock, with merge-preserving creation | Restored settings survive creation | +| MCP disabled flags, server edits, and config updates | Settings read before the writer lock | Cross-process read-modify-write gap remains #2173 | +| Project MCP settings creation | Canonical absence checked before default write | Restored-settings overwrite gap remains #2175 | +| Code-index save and clear | Derived file hashes; VS Code filesystem reader | Rebuildable cache; save errors logged | +| Settings export | User-selected snapshot file | Write failure reported; direct import reader | +| File-context metadata save | Task-local metadata, canonical-only reader | Backup recovery gap remains #2177 | +| UI-message save | Snapshot merge or replacement; recovery-aware reader | Trace and typed read/save error paths | +| API-message save | Snapshot merge or replacement; recovery-aware reader | I/O errors propagate | +| Legacy API-message migration | Legacy history copied to current file, then legacy source unlinked | Failed replacement preserves source; failed unlink preserves committed current history | +| Task-history migration | Legacy global state backfills missing files | Provider remains in legacy mode until migration and repair succeed; retry snapshot preserved | +| Task-history administrative and delta writes | Per-task files; disk merge under file lock where configured | Forced scans and failed refreshes retain evidence | +| Rejected-action compare-and-clear | Locked disk record owns conditional settlement | Validation and matching action ID are checked inside merge | +| Delegation repair intent | Task records are authoritative; intent journals a guarded two-record repair | Intent reader remains a raw canonical read (#2176); replay must succeed before ordinary repair | + +The initialization verifier explores failures before and after nested repair writes and preserves ancestor links across same-process retries, including explicit migration retries. Provider tests cover failed migration publication and a delayed post that captured legacy history before initialization, then resumes after the healthy post. The sending path refreshes that delayed history list before publication. + +## Concurrency and deletion limits + +Advisory lock expiry does not fence a paused former owner. A process that resumes after stale-lock takeover can overwrite or resurrect state; preventing this requires ownership fencing across writes, restores, and deletes. + +A failed backup unlink can leave older committed bytes alongside a valid canonical file. Supported deletion removes backups under the shared lock before deleting the canonical file; an external unlink that bypasses this protocol can expose a leftover backup to recovery. diff --git a/docs/architecture/task-lifecycle-model.md b/docs/architecture/task-lifecycle-model.md index eaeb61d987..cac8e64108 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 ten independent bounded checks in sequence: 1. the persisted task delegation lifecycle; 2. shared-store concurrency across task-history hosts; @@ -14,8 +14,10 @@ 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; +9. production JSON replacement crash points; and +10. production task-history initialization retries. 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 +90,58 @@ 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. +The active-task snapshot from the first complete scan is preserved across retries, including an explicit retry after terminal failure, so this process’s repairs are not reclassified as crash evidence. Successful initialization clears the snapshot. +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. +`isHealthy` is true only after a successful attempt. +Webview state publication does not wait for this attempt. +It uses legacy history until both store initialization and legacy migration succeed, 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 code, stack, degraded legacy mode, and the retry behavior. +Explicit open, export, delete, and cost queries wait for pending provider initialization, or start another attempt after a terminal failure. Runtime metadata reads return an already-cached task immediately, so cancellation, completion, and delegation do not wait for unrelated startup recovery. +A failed attempt reports unavailable history rather than a missing task. +Metadata-only cost, open, and delete operations do not load API conversation history. +Migration retains its original active-task snapshot across explicit retries and clears it after successful repair and persistence of the migration-complete marker. A marker write failure retains the snapshot for the next retry. State-publication errors do not change history readiness, and disposal does not log a degraded-history warning. +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. +The initialization suite also commits a nested-child repair, injects a later retryable write failure, and verifies that the retry preserves the repaired parent as active on disk. +The task-history initialization checker below explores nested delegation repair and same-process retries through production code. The persisted reducer and JSON replacement crash models retain their separate scopes. + +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 +316,104 @@ 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. +After the restore rename succeeds, leftover cleanup removes the backup before an incoming write 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. +Backup-recovery seeds include an incomplete `.new_` file, multiple backups, and committed JSON larger than 64 KiB. The newer-canonical scenario combines these leftovers with an existing canonical record. +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. +Five 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. +- Selecting the oldest backup must violate backup preservation, invariant 2; backup seeds carry distinct committed payloads. + +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. + +## Task-history initialization retry check + +The CI lifecycle-check step has a ten-minute timeout. + +`pnpm history-initialization:model-check` runs a bounded production-backed exploration and its mutation test. It is included in `pnpm lifecycle:model-check`. + +The harness bundles `TaskHistoryStore`, substitutes the VS Code storage-path adapter, and sets the six retry delays to zero without changing retry count or control flow. Each execution uses a fresh store and real temporary files. It enumerates all 24 scan orders for a grandparent awaiting a delegated parent, that parent awaiting an active child, and an independent invalid delegation. Three initial states enter ordinary repair, replay of a durable repair intent, or legacy migration into initially empty task directories. Migration exercises explicit caller retries through its public entry point; the provider tests cover the caller orchestration. + +Each order runs without faults and with `ELOCKED` or `EBUSY` injected before or after each of the three task-file writes. Before-write failures repeat once or twice; after-write failures occur once, after the real write has committed but before its caller receives the result. The complete bound is 1,368 executions, at most eight task-file write attempts per execution, and at most two injected retries. Every scheduled fault and resulting retry must be reached. Losing a scenario or exceeding a bound fails the check. + +The invariant requires healthy initialization, exact expected disk records, matching cache records, and removal of the completed repair intent. In particular, the recovered parent stays active and its grandparent keeps the delegation to it. A failure prints the scenario, scan order, fault schedule, scans, attempted writes, and committed writes. This trace is deterministic and replayable, but is not a shortest-state counterexample. + +The `resnapshot-active` source mutation restores the original startup bug by recomputing the active-task snapshot on every attempt. The mutation test must fail with the initialization invariant after a committed parent repair and a second scan. The `resnapshot-migration` mutation removes the corresponding migration snapshot guard and must fail after a committed parent repair and a second migration attempt. These checks demonstrate that the checker detects both regressions rather than merely accepting the current implementation. + +This check exhausts only the declared orders and fault schedules. It does not prove concurrent-host behavior, process crashes, arbitrary task graphs, wall-clock backoff, or arbitrary-length failures. The JSON crash campaign and persisted reducer models cover separate boundaries. diff --git a/package.json b/package.json index 6ec1d9067f..3d94fb899f 100644 --- a/package.json +++ b/package.json @@ -20,7 +20,9 @@ "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 && pnpm history-initialization:model-check", + "history-initialization:model-check": "tsx scripts/check-task-history-initialization.ts && node --import tsx --test scripts/check-task-history-initialization.test.ts", + "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..8e67c745e3 --- /dev/null +++ b/scripts/check-json-replacement.test.ts @@ -0,0 +1,48 @@ +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], + ["oldest-backup-first", 2], +] 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..9ae04c51cf --- /dev/null +++ b/scripts/check-json-replacement.ts @@ -0,0 +1,591 @@ +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: cost === 0 ? "child-" + "x".repeat(70 * 1024) : "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]) + const older = path.join(root, "tasks", "child", ".history_item.json.bak_older.tmp") + fs.writeFileSync(older, JSON.stringify({ ...value(0), ts: 0, task: "older committed history" })) + fs.utimesSync(older, new Date(1_000), new Date(1_000)) + 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 === "oldest-backup-first" && args.path.endsWith("safeWriteJson.ts")) { + const original = "b.mtimeMs - a.mtimeMs || b.backupPath.localeCompare(a.backupPath)" + assert(source.includes(original), "Backup selection mutation anchor changed") + source = source.replace( + original, + "a.mtimeMs - b.mtimeMs || a.backupPath.localeCompare(b.backupPath)", + ) + applied = true + } + + 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") + } + if (mutation === "oldest-backup-first") { + await runCase(bundle, path.join(work, "oldest-backup-mutant"), "restore") + throw new Error("Oldest-backup 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/check-task-history-initialization.test.ts b/scripts/check-task-history-initialization.test.ts new file mode 100644 index 0000000000..4131a71528 --- /dev/null +++ b/scripts/check-task-history-initialization.test.ts @@ -0,0 +1,22 @@ +import assert from "node:assert/strict" +import { spawnSync } from "node:child_process" +import { test } from "node:test" + +for (const [mutation, retry] of [ + ["resnapshot-active", "scan"], + ["resnapshot-migration", "migration"], +] as const) { + test(`initialization checker rejects ${mutation}`, () => { + const result = spawnSync( + process.execPath, + ["--import", "tsx", "scripts/check-task-history-initialization.ts", `--mutation=${mutation}`], + { encoding: "utf8", timeout: 30_000 }, + ) + assert.ifError(result.error) + assert.equal(result.status, 1, result.stderr) + assert.match(result.stderr, /Initialization invariant: recovery must preserve repaired parents/) + assert.match(result.stderr, /committed write \d+ parent=active/) + assert.match(result.stderr, new RegExp(`${retry} 2:`)) + assert.match(result.stderr, /disk state changed across retries/) + }) +} diff --git a/scripts/check-task-history-initialization.ts b/scripts/check-task-history-initialization.ts new file mode 100644 index 0000000000..c5cdebbdc3 --- /dev/null +++ b/scripts/check-task-history-initialization.ts @@ -0,0 +1,254 @@ +import assert from "node:assert/strict" +import * as fs from "node:fs/promises" +import * as os from "node:os" +import * as path from "node:path" +import { createRequire } from "node:module" +import { build } from "esbuild" + +import type { HistoryItem } from "../packages/types/src/history" +import type { TaskHistoryStore as Store } from "../src/core/task-persistence/TaskHistoryStore" + +// Bounded exploration of the production startup protocol, rather than a second +// implementation of its repair transitions. No concurrent hosts or crash cuts. +const MAX_CASES = 1_368 +const MAX_WRITES = 8 +const ids = ["grandparent", "parent", "child", "other"] as const +type TaskId = (typeof ids)[number] +type Fault = { write: number; edge: "before" | "after"; code: "ELOCKED" | "EBUSY"; repeats: number } +type Scenario = "repair" | "replay" | "migration" + +function permutations(values: readonly T[]): T[][] { + if (!values.length) return [[]] + return values.flatMap((value, index) => + permutations(values.filter((_, other) => index !== other)).map((rest) => [value, ...rest]), + ) +} + +async function bundleAt(destination: string, mutation: string | undefined) { + let applied = false + await build({ + stdin: { + contents: 'export { TaskHistoryStore } from "./src/core/task-persistence/TaskHistoryStore"', + resolveDir: process.cwd(), + }, + bundle: true, + platform: "node", + format: "cjs", + target: "node22", + outfile: destination, + logLevel: "silent", + plugins: [ + { + name: "storage-adapter-and-retry-clock", + setup(build) { + build.onLoad({ filter: /[\\/]src[\\/]utils[\\/]storage\.ts$/ }, () => ({ + contents: "export async function getStorageBasePath(root: string) { return root }", + loader: "ts", + })) + build.onLoad({ filter: /[\\/]TaskHistoryStore\.ts$/ }, async (args) => { + let source = await fs.readFile(args.path, "utf8") + const delays = "[1_000, 2_000, 4_000, 8_000, 8_000, 8_000]" + assert(source.includes(delays), "Retry clock anchor changed") + // Preserve retry count and control flow while advancing the clock immediately. + source = source.replace(delays, "[0, 0, 0, 0, 0, 0]") + if (mutation) { + const snapshot = + mutation === "resnapshot-active" + ? "(this.initializationActiveIds ??= this.getPersistedActiveIds())" + : "(this.migrationActiveIds ??= this.getPersistedActiveIds())" + assert(source.includes(snapshot), "Active snapshot mutation anchor changed") + source = source.replace(snapshot, "this.getPersistedActiveIds()") + applied = true + } + return { contents: source, loader: "ts" } + }) + }, + }, + ], + }) + assert(!mutation || applied, "Snapshot mutation was not applied") +} + +function records(): Record { + const item = (id: TaskId, fields: Partial): HistoryItem => ({ + id, + number: 1, + ts: 1, + task: id, + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + ...fields, + }) + return { + grandparent: item("grandparent", { status: "delegated", awaitingChildId: "parent", delegatedToId: "parent" }), + parent: item("parent", { + status: "delegated", + awaitingChildId: "child", + delegatedToId: "child", + parentTaskId: "grandparent", + }), + child: item("child", { status: "active", parentTaskId: "parent" }), + other: item("other", { status: "delegated" }), + } +} + +async function runCase(StoreClass: typeof Store, root: string, scenario: Scenario, order: TaskId[], fault?: Fault) { + const initial = records() + for (const id of ids) { + const directory = path.join(root, "tasks", id) + await fs.mkdir(directory, { recursive: true }) + if (scenario !== "migration") + await fs.writeFile(path.join(directory, "history_item.json"), JSON.stringify(initial[id])) + } + if (scenario === "replay") { + await fs.writeFile( + path.join(root, "tasks", "_delegation_repair_intent.json"), + JSON.stringify({ + version: 1, + operationId: "checker", + parentTaskId: "parent", + childTaskId: "child", + expected: { + parent: { status: "delegated", awaitingChildId: "child", delegatedToId: "child" }, + child: { status: "active", parentTaskId: "parent" }, + }, + target: { childStatus: "interrupted", parentStatus: "active" }, + }), + ) + } + const store = new StoreClass(root) + if (scenario === "migration") await store.initialize() + const trace: string[] = [] + let writes = 0, + injected = 0, + attempts = 0 + const reconcile = store.reconcile.bind(store) + store.reconcile = async (options) => { + await reconcile(options) + // Enumerate filesystem directory orders without depending on host readdir ordering. + store["cache"] = new Map(order.map((id) => [id, store.get(id)!])) + attempts++ + trace.push(`scan ${attempts}: ${order.map((id) => `${id}=${store.get(id)?.status}`).join(", ")}`) + } + const write = store["writeTaskFile"].bind(store) + store["writeTaskFile"] = async (item, delta) => { + assert(++writes <= MAX_WRITES, "Initialization write budget exhausted") + const inject = (edge: Fault["edge"]) => { + if (fault && edge === fault.edge && writes >= fault.write && injected < fault.repeats) { + injected++ + trace.push(`${edge} write ${writes} ${item.id}=${item.status}: ${fault.code}`) + throw Object.assign(new Error("injected repair failure"), { code: fault.code }) + } + } + trace.push(`before write ${writes} ${item.id}=${item.status}`) + inject("before") + const result = await write(item, delta) + trace.push(`committed write ${writes} ${item.id}=${item.status}`) + inject("after") + return result + } + try { + if (scenario === "migration") { + // Migration has an explicit caller retry, rather than the store's timer loop. + // Exercise that public entry point again after each injected failure. + for (;;) { + attempts++ + trace.push( + `migration ${attempts}: ${order.map((id) => `${id}=${store.get(id)?.status ?? "legacy"}`).join(", ")}`, + ) + try { + await store.migrateFromGlobalState(order.map((id) => initial[id])) + break + } catch (error) { + if ( + attempts > 2 || + !(error instanceof Error) || + !("code" in error) || + !["ELOCKED", "EBUSY"].includes(String(error.code)) + ) + throw error + } + } + } else await store.initialize() + assert.equal(injected, fault?.repeats ?? 0, "Fault schedule was not reached") + assert.equal(attempts, injected + 1, "Retry landmark was not reached") + assert(store.isHealthy, "Initialization did not publish a healthy snapshot") + const expected = { + grandparent: { ...initial.grandparent }, + parent: { ...initial.parent, status: "active", awaitingChildId: undefined, delegatedToId: undefined }, + child: { ...initial.child, status: "interrupted" }, + other: { ...initial.other, status: "active", awaitingChildId: undefined, delegatedToId: undefined }, + } + for (const id of ids) { + const disk: unknown = JSON.parse( + await fs.readFile(path.join(root, "tasks", id, "history_item.json"), "utf8"), + ) + // JSON normalization removes optional undefined fields from both sides. + assert.deepEqual(disk, JSON.parse(JSON.stringify(expected[id])), `${id} disk state changed across retries`) + assert.deepEqual(JSON.parse(JSON.stringify(store.get(id))), disk, `${id} cache differs from disk`) + } + await assert.rejects(fs.access(path.join(root, "tasks", "_delegation_repair_intent.json")), { code: "ENOENT" }) + } catch (error) { + throw new Error( + `Initialization invariant: recovery must preserve repaired parents and their ancestor links\nScenario: ${scenario}; order: ${order.join(" -> ")}; fault: ${JSON.stringify(fault ?? null)}\n${trace.join("\n")}`, + { cause: error }, + ) + } finally { + store.dispose() + } +} + +async function main() { + const mutation = process.argv.find((arg) => arg.startsWith("--mutation="))?.split("=")[1] + assert( + process.argv + .slice(2) + .every((arg) => ["--mutation=resnapshot-active", "--mutation=resnapshot-migration"].includes(arg)), + "Unknown checker argument", + ) + const work = await fs.mkdtemp(path.join(os.tmpdir(), "history-initialization-check-")) + const warn = console.warn, + error = console.error + try { + const bundle = path.join(work, "production.cjs") + await bundleAt(bundle, mutation) + // The generated module exports the production class with only the adapter/clock substitutions above. + const { TaskHistoryStore } = createRequire(path.join(process.cwd(), "package.json"))(bundle) as { + TaskHistoryStore: typeof Store + } + console.warn = console.error = () => {} + const faults: Array = [undefined] + for (const write of [1, 2, 3]) + for (const code of ["ELOCKED", "EBUSY"] as const) { + faults.push( + { write, code, edge: "before", repeats: 1 }, + { write, code, edge: "before", repeats: 2 }, + { write, code, edge: "after", repeats: 1 }, + ) + } + let cases = 0 + for (const scenario of ["repair", "replay", "migration"] as const) + for (const order of permutations(ids)) + for (const fault of faults) { + assert(++cases <= MAX_CASES, "Initialization case budget exhausted") + const root = path.join(work, `case-${cases}`) + await runCase(TaskHistoryStore, root, scenario, order, fault) + await fs.rm(root, { recursive: true, force: true }) + } + assert.equal(cases, MAX_CASES, "Initialization exploration lost a scenario") + assert(!mutation, "Active snapshot mutant survived") + console.log( + `History initialization check passed: ${cases} cases, 24 scan orders, repair, replay and migration, before/after commits, ELOCKED/EBUSY, up to two retries. No concurrency or process-crash proof.`, + ) + } finally { + console.warn = warn + console.error = error + await fs.rm(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..9e4766ddf4 100644 --- a/scripts/code-qa-workflow.test.mjs +++ b/scripts/code-qa-workflow.test.mjs @@ -136,3 +136,11 @@ describe("Knip quality gate", () => { assert.doesNotMatch(job, /continue-on-error|if:/) }) }) + +describe("lifecycle verification timeout", () => { + it("gives the bounded check suite an explicit ten-minute budget", () => { + const step = workflowStep("Model-check task lifecycle protocols") + assert.match(step, /timeout-minutes: 10/) + assert.match(step, /run: pnpm lifecycle:model-check/) + }) +}) diff --git a/src/__tests__/ClineProvider.delegation.spec.ts b/src/__tests__/ClineProvider.delegation.spec.ts index 68f39c6517..13db8c50cf 100644 --- a/src/__tests__/ClineProvider.delegation.spec.ts +++ b/src/__tests__/ClineProvider.delegation.spec.ts @@ -1202,6 +1202,10 @@ describe("ClineProvider.delegateParentAndOpenChild()", () => { removeClineFromStack: vi.fn().mockResolvedValue(undefined), createTask, getTaskWithId, + // The real deletion path now asks for metadata without reading API history. + requireTaskHistoryItem: vi.fn(async (taskId: string) => + taskId === "parent-1" ? settledParent : childItem, + ), handleModeSwitch: vi.fn().mockResolvedValue(undefined), // The real deletion path: the store swallows a per-file history // lock failure, so deleteMany resolves and cleanup continues. @@ -1239,6 +1243,7 @@ describe("ClineProvider.delegateParentAndOpenChild()", () => { // history lock failed and was swallowed, and the settled parent // was restored before the original rejection surfaced. await expect(fs.access(childDir)).rejects.toMatchObject({ code: "ENOENT" }) + expect(getTaskWithId).not.toHaveBeenCalledWith("child-1") expect(clearPendingActionIfMatching).toHaveBeenCalledWith("parent-1", "create-action") expect(createTaskWithHistoryItem).toHaveBeenCalledWith( expect.objectContaining({ status: "interrupted", pendingAction: undefined }), 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..f9843a4656 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,13 +88,21 @@ 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 + private initializationActiveIds: ReadonlySet | undefined + private migrationActiveIds: ReadonlySet | undefined + private migrationComplete = false + + /** Whether startup completed successfully with a full snapshot. */ + get isHealthy(): boolean { + return this.initializationHealthy + } - /** - * Promise that resolves when initialization is complete. - * Callers can await this to ensure the store is ready before reading. - */ - public readonly initialized: Promise - private resolveInitialized!: () => void + // 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 @@ -101,9 +110,6 @@ export class TaskHistoryStore { constructor(globalStoragePath: string, options?: TaskHistoryStoreOptions) { this.globalStoragePath = globalStoragePath this.onWrite = options?.onWrite - this.initialized = new Promise((resolve) => { - this.resolveInitialized = resolve - }) } // ────────────────────────────── Lifecycle ────────────────────────────── @@ -111,37 +117,65 @@ export class TaskHistoryStore { /** * Scan task files, reconcile delegation state, start watchers. */ - async initialize(): Promise { - try { - const tasksDir = await this.getTasksDir() - await fs.mkdir(tasksDir, { recursive: true }) - - // 1. Scan task directories to populate the cache - await this.reconcile({ forceRefresh: true }) - // Capture which active tasks were present in persisted state before replay can - // change any statuses. Reconciliation must not treat a replay-repaired parent - // as an orphaned active child in the same startup pass. - const persistedActiveIds = this.getPersistedActiveIds() + initialize(): Promise { + if (this.initializationHealthy) return Promise.resolve() + if (!this.initializationPromise) { + this.initializationPromise = this.initializeWithRetry().finally(() => { + this.initializationPromise = undefined + }) + } + return this.initializationPromise + } - // 2. Complete any two-record repair interrupted after its intent was durable. + private async initializeWithRetry(): Promise { + for (let attempt = 0; ; attempt++) { try { - await this.replayDelegationRepairIntent() + 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 + this.initializationActiveIds = undefined + return } catch (error) { - console.error("[TaskHistoryStore] Failed to replay delegation repair intent:", 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 } + } + } + + private async initializeAttempt(): Promise { + const tasksDir = await this.getTasksDir() + await fs.mkdir(tasksDir, { recursive: true }) - // 3. Repair delegation inconsistencies left by a previous crash - await this.reconcileDelegationState(persistedActiveIds) + // 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 this process, including subsequent retries. + const persistedActiveIds = (this.initializationActiveIds ??= this.getPersistedActiveIds()) - // 4. Start fs.watch for cross-instance reactivity - this.startWatcher() + // 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() - // 5. Start periodic reconciliation as a defensive fallback - this.startPeriodicReconciliation() - } finally { - // Mark initialization as complete so callers awaiting `initialized` can proceed - this.resolveInitialized() - } + // 3. Repair delegation inconsistencies left by a previous crash + await this.reconcileDelegationState(persistedActiveIds) + + // 4. Start fs.watch for cross-instance reactivity + this.startWatcher() + + // 5. Start periodic reconciliation as a defensive fallback + this.startPeriodicReconciliation() } /** @@ -149,6 +183,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) @@ -277,13 +318,7 @@ export class TaskHistoryStore { this.cache.delete(taskId) this.taskFileMtimes.delete(taskId) - // 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 this.deleteTaskFile(taskId) // Call onWrite callback inside the lock for serialized write-through if (this.onWrite) { @@ -305,13 +340,7 @@ export class TaskHistoryStore { this.cache.delete(taskId) this.taskFileMtimes.delete(taskId) - // 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 this.deleteTaskFile(taskId) } // Call onWrite callback inside the lock for serialized write-through @@ -321,6 +350,21 @@ export class TaskHistoryStore { }) } + private async deleteTaskFile(taskId: string): Promise { + try { + const filePath = await this.getTaskFilePath(taskId) + await withFileLock(filePath, async (absoluteFilePath) => { + // If backup cleanup fails, retain the canonical copy too. Deleting it + // would allow a subsequent reader to restore older task state. + await removeJsonBackups(absoluteFilePath) + await fs.unlink(absoluteFilePath) + }) + } catch (error) { + if (getErrorCode(error) !== "ENOENT") + console.warn(`[TaskHistoryStore] Failed to delete task ${taskId}:`, error) + } + } + // ────────────────────────────── Reconciliation ────────────────────────────── /** @@ -337,7 +381,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 +392,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 +419,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 +450,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 +571,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 +729,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 +834,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) }) } @@ -799,13 +861,19 @@ export class TaskHistoryStore { * * For each entry in the globalState array, writes a `history_item.json` * file if one doesn't already exist. This is idempotent and safe to re-run. + * commitMigration persists the caller's completion marker under the store + * lock after repairs; it must not re-enter this store. */ - async migrateFromGlobalState(taskHistoryEntries: HistoryItem[]): Promise { + async migrateFromGlobalState( + taskHistoryEntries: HistoryItem[], + commitMigration?: () => Promise, + ): Promise { if (!taskHistoryEntries || taskHistoryEntries.length === 0) { return } await this.withLock(async () => { + if (this.migrationComplete) return const tasksDir = await this.getTasksDir() for (const item of taskHistoryEntries) { @@ -837,7 +905,12 @@ export class TaskHistoryStore { // Repair any delegation inconsistencies introduced by the migrated entries. // Run the lock-free core because migration already holds the store lock. - await this.reconcileDelegationStateCore(this.getPersistedActiveIds()) + await this.reconcileDelegationStateCore((this.migrationActiveIds ??= this.getPersistedActiveIds())) + // Marker persistence is part of the migration epoch. A failed marker write + // must retain this snapshot for the provider's next explicit retry. + await commitMigration?.() + this.migrationActiveIds = undefined + this.migrationComplete = true }) } @@ -888,10 +961,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.deleteSemantics.spec.ts b/src/core/task-persistence/__tests__/TaskHistoryStore.deleteSemantics.spec.ts index 5071c9de73..3da2696de6 100644 --- a/src/core/task-persistence/__tests__/TaskHistoryStore.deleteSemantics.spec.ts +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.deleteSemantics.spec.ts @@ -90,6 +90,32 @@ describe("TaskHistoryStore best-effort deletion semantics", () => { return store } + it.each(["delete", "deleteMany"] as const)("%s retains canonical data when backup cleanup fails", async (entry) => { + const store = createStore() + await store.initialize() + const item = makeHistoryItem({ id: "backup-cleanup-failure" }) + await store.upsert(item) + const canonical = historyFilePath(storagePath, item.id) + const backup = path.join(path.dirname(canonical), ".history_item.json.bak_old.tmp") + await fs.writeFile(backup, JSON.stringify(item)) + const error = Object.assign(new Error("backup busy"), { code: "EACCES" }) + vi.mocked(fs.unlink).mockImplementation(async (file) => { + if (file === backup) throw error + return actualFs.unlink(file) + }) + const log = vi.spyOn(console, "warn").mockImplementation(() => {}) + try { + if (entry === "delete") await store.delete(item.id) + else await store.deleteMany([item.id]) + expect(JSON.parse(await fs.readFile(canonical, "utf8"))).toEqual(item) + expect(JSON.parse(await fs.readFile(backup, "utf8"))).toEqual(item) + expect(log).toHaveBeenCalledWith(expect.stringContaining("Failed to delete"), error) + expect(store.get(item.id)).toBeUndefined() + } finally { + log.mockRestore() + } + }) + describe("delete()", () => { it("unlinks under the shared per-file lock, evicts cache and mtime, and writes through once", async () => { const store = createStore() 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..0cac13bd09 --- /dev/null +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.initialization.spec.ts @@ -0,0 +1,317 @@ +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" + +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") + +function nestedItems(): HistoryItem[] { + return ( + [ + { id: "grandparent", status: "delegated", awaitingChildId: "parent" }, + { id: "parent", status: "delegated", awaitingChildId: "child", parentTaskId: "grandparent" }, + { id: "child", status: "active", parentTaskId: "parent" }, + { id: "broken", status: "delegated" }, + ] satisfies Pick[] + ).map((item, index) => ({ + number: index, + ts: index + 1, + task: item.id, + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + ...item, + })) +} + +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()) + } + + async function seedNestedItems() { + const items = nestedItems() + for (const item of items) { + const directory = path.join(root, "tasks", item.id) + await fs.mkdir(directory, { recursive: true }) + await fs.writeFile(path.join(directory, "history_item.json"), JSON.stringify(item)) + } + // The nested repair must commit before the unrelated failure. + const reconcile = store.reconcile.bind(store) + vi.spyOn(store, "reconcile").mockImplementation(async (options) => { + await reconcile(options) + store["cache"] = new Map(items.map(({ id }) => [id, store.get(id)!])) + }) + } + + 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() + const pending = store.initialize() + void pending.then(settled) + 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 + 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 }) + 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" }) + 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.each(["ELOCKED", "EBUSY"])("keeps a repaired nested parent active after a later %s failure", async (code) => { + await seedNestedItems() + const write = store["writeTaskFile"].bind(store) + let failed = false + store["writeTaskFile"] = vi.fn(async (item, delta) => { + if (item.id === "broken" && !failed) { + failed = true + throw Object.assign(new Error("repair busy"), { code }) + } + return write(item, delta) + }) + const pending = store.initialize() + await waitForRetry() + expect(store.get("parent")?.status).toBe("active") + expect(store.get("child")?.status).toBe("interrupted") + await vi.advanceTimersByTimeAsync(1_000) + await pending + expect(store.isHealthy).toBe(true) + expect(store.get("grandparent")).toMatchObject({ status: "delegated", awaitingChildId: "parent" }) + expect(store.get("parent")?.status).toBe("active") + expect(store.get("child")?.status).toBe("interrupted") + const disk = JSON.parse(await fs.readFile(path.join(root, "tasks", "parent", "history_item.json"), "utf8")) + expect(disk.status).toBe("active") + }) + + it("retries explicitly after a terminal partial repair failure and releases its snapshot on success", async () => { + await seedNestedItems() + const write = store["writeTaskFile"].bind(store) + let failed = false + store["writeTaskFile"] = async (item, delta) => { + if (item.id === "broken" && !failed) { + failed = true + throw Object.assign(new Error("repair failed"), { code: "EIO" }) + } + return write(item, delta) + } + await expect(store.initialize()).rejects.toMatchObject({ code: "EIO" }) + expect(store.isHealthy).toBe(false) + expect(store.get("parent")?.status).toBe("active") + expect(store["initializationActiveIds"]).toEqual(new Set(["child"])) + const retry = store.initialize() + expect(store.initialize()).toBe(retry) + await retry + expect(store.isHealthy).toBe(true) + expect(store.get("grandparent")).toMatchObject({ status: "delegated", awaitingChildId: "parent" }) + expect(store.get("parent")?.status).toBe("active") + expect(store["initializationActiveIds"]).toBeUndefined() + }) + + it.each(["ELOCKED", "EBUSY"])( + "preserves a repaired nested parent when legacy migration retries %s", + async (code) => { + const items = nestedItems() + for (const item of items) await fs.mkdir(path.join(root, "tasks", item.id), { recursive: true }) + await store.initialize() + const write = store["writeTaskFile"].bind(store) + let failed = false + store["writeTaskFile"] = async (item, delta) => { + if (item.id === "broken" && !failed) { + failed = true + throw Object.assign(new Error("migration busy"), { code }) + } + return write(item, delta) + } + await expect(store.migrateFromGlobalState(items)).rejects.toMatchObject({ code }) + expect(store.get("parent")?.status).toBe("active") + await store.migrateFromGlobalState(items) + expect(store.get("grandparent")).toMatchObject({ status: "delegated", awaitingChildId: "parent" }) + expect(store.get("parent")?.status).toBe("active") + expect(store.get("child")?.status).toBe("interrupted") + expect(store["migrationActiveIds"]).toBeUndefined() + }, + ) + + it("retains the migration snapshot until its completion marker is committed", async () => { + const items = nestedItems() + for (const item of items) await fs.mkdir(path.join(root, "tasks", item.id), { recursive: true }) + await store.initialize() + const commit = vi + .fn<() => Promise>() + .mockRejectedValueOnce(Object.assign(new Error("marker write failed"), { code: "EIO" })) + .mockResolvedValue(undefined) + await expect(store.migrateFromGlobalState(items, commit)).rejects.toMatchObject({ code: "EIO" }) + expect(store.get("parent")?.status).toBe("active") + expect(store["migrationActiveIds"]).toEqual(new Set(["child"])) + await store.migrateFromGlobalState(items, commit) + expect(commit).toHaveBeenCalledTimes(2) + expect(store.get("grandparent")).toMatchObject({ status: "delegated", awaitingChildId: "parent" }) + expect(store.get("parent")?.status).toBe("active") + expect(store["migrationActiveIds"]).toBeUndefined() + }) + + it("keeps a completed nested migration idempotent after releasing its snapshot", async () => { + const items = nestedItems() + for (const item of items) await fs.mkdir(path.join(root, "tasks", item.id), { recursive: true }) + await store.initialize() + await Promise.all([store.migrateFromGlobalState(items), store.migrateFromGlobalState(items)]) + expect(store["migrationActiveIds"]).toBeUndefined() + expect(store.get("grandparent")).toMatchObject({ status: "delegated", awaitingChildId: "parent" }) + expect(store.get("parent")?.status).toBe("active") + }) + + 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) + 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 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..b43c97f8b7 --- /dev/null +++ b/src/core/task-persistence/__tests__/TaskHistoryStore.recovery.spec.ts @@ -0,0 +1,213 @@ +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 * as jsonIo from "../../../utils/safeWriteJson" +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) + }) + it.each(["ELOCKED", "EACCES", "EIO"])("invalidate retains its cached record on %s", async (code) => { + await store.initialize() + vi.mocked(fs.readFile).mockImplementation(async (...args) => { + if (String(args[0]) === canonical) throw Object.assign(new Error(code), { code }) + return actual.readFile(...args) + }) + await expect(store.invalidate(child.id)).rejects.toMatchObject({ code }) + expect(store.get(child.id)).toEqual(child) + }) + it.each(["forced reconcile", "background reconcile", "invalidate"] as const)( + "retains its last record after recovery is locked during %s", + async (entry) => { + await store.initialize() + await fs.rename(canonical, backup) + const error = Object.assign(new Error("recovery locked"), { code: "ELOCKED" }) + const recover = vi.spyOn(jsonIo, "recoverJsonFile").mockRejectedValueOnce(error) + try { + const pending = + entry === "invalidate" + ? store.invalidate(child.id) + : store.reconcile({ forceRefresh: entry === "forced reconcile" }) + if (entry === "background reconcile") await expect(pending).resolves.toBeUndefined() + else await expect(pending).rejects.toBe(error) + expect(recover).toHaveBeenCalledWith(canonical) + expect(store.get(child.id)).toEqual(child) + expect(JSON.parse(await fs.readFile(backup, "utf8"))).toEqual(child) + } finally { + recover.mockRestore() + } + }, + ) +}) 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__/apiMessages.spec.ts b/src/core/task-persistence/__tests__/apiMessages.spec.ts index c74ef6b150..4dc4bfde5b 100644 --- a/src/core/task-persistence/__tests__/apiMessages.spec.ts +++ b/src/core/task-persistence/__tests__/apiMessages.spec.ts @@ -4,10 +4,12 @@ import * as os from "os" import * as path from "path" import * as fs from "fs/promises" -const hoisted = vi.hoisted(() => ({ readFileMock: vi.fn() })) +const hoisted = vi.hoisted(() => ({ readFileMock: vi.fn(), renameMock: vi.fn(), unlinkMock: vi.fn() })) vi.mock("fs/promises", async (importOriginal) => ({ ...(await importOriginal()), readFile: hoisted.readFileMock, + rename: hoisted.renameMock, + unlink: hoisted.unlinkMock, })) import { readApiMessages, saveApiMessages } from "../apiMessages" @@ -17,6 +19,8 @@ let tmpBaseDir: string beforeEach(async () => { const actualFs = await vi.importActual("fs/promises") hoisted.readFileMock.mockReset().mockImplementation(actualFs.readFile) + hoisted.renameMock.mockReset().mockImplementation(actualFs.rename) + hoisted.unlinkMock.mockReset().mockImplementation(actualFs.unlink) tmpBaseDir = await fs.mkdtemp(path.join(os.tmpdir(), "roo-test-api-")) }) @@ -98,6 +102,23 @@ describe("apiMessages.readApiMessages", () => { await expect(fs.access(oldPath)).rejects.toMatchObject({ code: "ENOENT" }) }) + it.each(["write", "unlink"])("preserves the legacy source when migration %s fails", async (operation) => { + const taskId = "failed-legacy-migration" + const taskDir = path.join(tmpBaseDir, "tasks", taskId) + await fs.mkdir(taskDir, { recursive: true }) + const legacy = path.join(taskDir, "claude_messages.json") + const current = path.join(taskDir, "api_conversation_history.json") + const messages = [{ role: "user", content: "committed" }] + await fs.writeFile(legacy, JSON.stringify(messages)) + const error = Object.assign(new Error("migration failed"), { code: "EIO" }) + if (operation === "write") hoisted.renameMock.mockRejectedValueOnce(error) + else hoisted.unlinkMock.mockRejectedValueOnce(error) + await expect(readApiMessages({ taskId, globalStoragePath: tmpBaseDir })).rejects.toThrow() + expect(JSON.parse(await fs.readFile(legacy, "utf8"))).toEqual(messages) + if (operation === "write") await expect(fs.access(current)).rejects.toMatchObject({ code: "ENOENT" }) + else expect(JSON.parse(await fs.readFile(current, "utf8"))).toEqual(messages) + }) + it("retries one transient missing-file read", async () => { vi.spyOn(Math, "random").mockReturnValue(0) const missing = Object.assign(new Error("missing"), { code: "ENOENT" }) 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/tools/AttemptCompletionTool.ts b/src/core/tools/AttemptCompletionTool.ts index 4fe03ce94c..00777ce849 100644 --- a/src/core/tools/AttemptCompletionTool.ts +++ b/src/core/tools/AttemptCompletionTool.ts @@ -26,7 +26,10 @@ export interface AttemptCompletionCallbacks extends ToolCallbacks { */ interface DelegationProvider { log(message: string): void - getTaskWithId(id: string): Promise<{ historyItem: HistoryItem }> + getTaskWithId( + id: string, + options?: { includeApiConversationHistory?: boolean }, + ): Promise<{ historyItem: HistoryItem }> setPendingTaskAction(taskId: string, pendingAction: PendingTaskAction): Promise clearPendingTaskAction(taskId: string, actionId: string): Promise emitDelegatedTaskCompleted( @@ -110,7 +113,9 @@ export class AttemptCompletionTool extends BaseTool<"attempt_completion"> { if (provider) { let historyLookupTaskId = task.taskId try { - const { historyItem } = await provider.getTaskWithId(task.taskId) + const { historyItem } = await provider.getTaskWithId(task.taskId, { + includeApiConversationHistory: false, + }) const status = historyItem?.status if (status === "completed") { @@ -121,7 +126,9 @@ export class AttemptCompletionTool extends BaseTool<"attempt_completion"> { isStaleHistoryReplay = true } else if (status === "active" || status === "interrupted") { historyLookupTaskId = task.parentTaskId - const { historyItem: parentHistory } = await provider.getTaskWithId(task.parentTaskId) + const { historyItem: parentHistory } = await provider.getTaskWithId(task.parentTaskId, { + includeApiConversationHistory: false, + }) if ( (parentHistory?.status === "delegated" || parentHistory?.status === "active") && diff --git a/src/core/webview/ClineProvider.ts b/src/core/webview/ClineProvider.ts index 869a96f65d..5ced8ab9ab 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" @@ -263,6 +263,8 @@ export class ClineProvider private recentTasksCache?: string[] public readonly taskHistoryStore: TaskHistoryStore private taskHistoryStoreInitialized = false + private taskHistoryInitializationPromise: Promise | undefined + private taskHistoryInitializationError: unknown public static readonly PENDING_OPERATION_TIMEOUT_MS = 30000 // 30 seconds private providerProfileMutationQueue = Promise.resolve() private historyTaskCreationQueue = Promise.resolve() @@ -493,9 +495,21 @@ export class ClineProvider /** * Initialize the TaskHistoryStore and migrate from globalState if needed. */ - private async initializeTaskHistoryStore(): Promise { + private initializeTaskHistoryStore(): Promise { + if (!this.taskHistoryInitializationPromise) { + this.taskHistoryInitializationPromise = this.initializeTaskHistoryStoreAttempt().finally(() => { + this.taskHistoryInitializationPromise = undefined + }) + } + return this.taskHistoryInitializationPromise + } + + private async initializeTaskHistoryStoreAttempt(): Promise { + this.taskHistoryStoreInitialized = false + this.taskHistoryInitializationError = undefined try { await this.taskHistoryStore.initialize() + if (this._disposed) return // Migration: backfill per-task files from globalState on first run const migrationKey = "taskHistoryMigratedToFiles" @@ -506,16 +520,38 @@ export class ClineProvider if (legacyHistory.length > 0) { this.log(`[initializeTaskHistoryStore] Migrating ${legacyHistory.length} entries from globalState`) - await this.taskHistoryStore.migrateFromGlobalState(legacyHistory) + await this.taskHistoryStore.migrateFromGlobalState(legacyHistory, async () => { + if (this._disposed) throw new Error("Provider disposed during history migration") + await this.context.globalState.update(migrationKey, true) + }) + } else { + if (this._disposed) return + await this.context.globalState.update(migrationKey, true) } - - await this.context.globalState.update(migrationKey, true) this.log("[initializeTaskHistoryStore] Migration complete") } + if (this._disposed) return this.taskHistoryStoreInitialized = true + this.recentTasksCache = undefined } catch (error) { - this.log(`[initializeTaskHistoryStore] Error: ${error instanceof Error ? error.message : String(error)}`) + if (this._disposed) return + this.taskHistoryInitializationError = error + this.log( + `[initializeTaskHistoryStore] History unavailable; displaying legacy history in degraded mode. ` + + `Opening a task will retry initialization. Code: ${getErrorCode(error) ?? "unknown"}. ` + + `${error instanceof Error ? (error.stack ?? error.message) : String(error)}`, + ) + return + } + if (this.isViewLaunched && !this._disposed) { + try { + await this.postStateToWebview() + } catch (error) { + this.log( + `[initializeTaskHistoryStore] History is ready but state publication failed: ${error instanceof Error ? (error.stack ?? error.message) : String(error)}`, + ) + } } } @@ -708,7 +744,9 @@ export class ClineProvider try { await this.runDelegationTransition(parentTaskId, async () => { - const { historyItem: parentHistory } = await this.getTaskWithId(parentTaskId) + const { historyItem: parentHistory } = await this.getTaskWithId(parentTaskId, { + includeApiConversationHistory: false, + }) if (parentHistory?.status !== "delegated" || parentHistory?.awaitingChildId !== childTaskId) { this.log( @@ -722,7 +760,8 @@ export class ClineProvider // getTaskWithId reads from disk and may return an incomplete record (missing // parentTaskId) if the child was evicted before its first saveClineMessages(). const childHistory = - this.taskHistoryStore.get(childTaskId) ?? (await this.getTaskWithId(childTaskId)).historyItem + this.taskHistoryStore.get(childTaskId) ?? + (await this.getTaskWithId(childTaskId, { includeApiConversationHistory: false })).historyItem // Re-check inside the lock to close the TOCTOU window with cancelTask() or // a concurrent completion. Only proceed when the child is still "active"; @@ -2405,52 +2444,85 @@ export class ClineProvider // Task history + private getAvailableTaskHistory(): HistoryItem[] { + return this.taskHistoryStoreInitialized && this.taskHistoryStore.isHealthy + ? this.taskHistoryStore.getAll() + : (this.contextProxy.getValue("taskHistory") ?? []) + } + 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 } return (this.getGlobalState("taskHistory") ?? []).find((item) => item.id === id) } - async getTaskWithId(id: string): Promise<{ + private async requireTaskHistoryItem(id: string, waitForInitialization = true): Promise { + // Runtime metadata reads must not gate cancellation or completion on startup. + const cached = this.taskHistoryStore.get(id) + if (cached && !waitForInitialization) return cached + // Opening/exporting is an explicit operation: wait for a complete migration + // instead of interpreting a partial startup cache as a missing task. + if ( + !this.taskHistoryStoreInitialized && + (this.taskHistoryInitializationError || + this.context.globalState.get("taskHistoryMigratedToFiles") || + !this.getTaskHistoryItem(id)) + ) { + await this.initializeTaskHistoryStore() + if (this.taskHistoryInitializationError) { + throw new Error("Task history is unavailable; try opening the task again", { + cause: this.taskHistoryInitializationError, + }) + } + } + const historyItem = this.getTaskHistoryItem(id) + + if (!historyItem) { + throw new Error("Task not found") + } + + return historyItem + } + + async getTaskWithId( + id: string, + options: { includeApiConversationHistory?: boolean; waitForInitialization?: boolean } = {}, + ): Promise<{ historyItem: HistoryItem taskDirPath: string apiConversationHistoryFilePath: string uiMessagesFilePath: string apiConversationHistory: Anthropic.MessageParam[] }> { - const historyItem = this.getTaskHistoryItem(id) - - if (!historyItem) { - throw new Error("Task not found") - } + const historyItem = await this.requireTaskHistoryItem( + id, + options.waitForInitialization ?? options.includeApiConversationHistory !== false, + ) const { getTaskDirectoryPath } = await import("../../utils/storage") const globalStoragePath = this.contextProxy.globalStorageUri.fsPath 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) { + if (options.includeApiConversationHistory !== false) { try { - apiConversationHistory = JSON.parse(await fs.readFile(apiConversationHistoryFilePath, "utf8")) + 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 corrupted for task ${id}, returning empty history: ${error instanceof Error ? error.message : String(error)}`, + `[getTaskWithId] API history unavailable for task ${id}, returning empty history: ${error instanceof Error ? error.message : String(error)}`, ) } - } else { - console.warn( - `[getTaskWithId] api_conversation_history.json missing for task ${id}, returning empty history`, - ) } return { @@ -2466,12 +2538,9 @@ export class ClineProvider historyItem: HistoryItem aggregatedCosts: AggregatedCosts }> { - const { historyItem } = await this.getTaskWithId(taskId) + const historyItem = await this.requireTaskHistoryItem(taskId) - const aggregatedCosts = await aggregateTaskCostsRecursive(taskId, async (id: string) => { - const result = await this.getTaskWithId(id) - return result.historyItem - }) + const aggregatedCosts = await aggregateTaskCostsRecursive(taskId, (id) => this.requireTaskHistoryItem(id)) return { historyItem, aggregatedCosts } } @@ -2479,7 +2548,7 @@ export class ClineProvider async showTaskWithId(id: string) { if (id !== this.getCurrentTask()?.taskId) { // Non-current task. - const { historyItem } = await this.getTaskWithId(id) + const historyItem = await this.requireTaskHistoryItem(id) await this.createTaskWithHistoryItem(historyItem) // Clears existing task. } @@ -2541,7 +2610,7 @@ export class ClineProvider // If the task has subtasks (childIds), they will also be deleted recursively async deleteTaskWithId(id: string, cascadeSubtasks: boolean = true) { try { - await this.getTaskWithId(id) + await this.requireTaskHistoryItem(id) // Collect all task IDs to delete (parent + all subtasks) const allIdsToDelete: string[] = [id] @@ -2550,7 +2619,7 @@ export class ClineProvider // Recursively collect all child IDs const collectChildIds = async (taskId: string): Promise => { try { - const { historyItem: item } = await this.getTaskWithId(taskId) + const item = await this.requireTaskHistoryItem(taskId) if (item.childIds && item.childIds.length > 0) { for (const childId of item.childIds) { allIdsToDelete.push(childId) @@ -2630,8 +2699,13 @@ export class ClineProvider } async postStateToWebview() { + const historyWasReady = this.taskHistoryStoreInitialized const clineMessagesSeq = ++this.clineMessagesSeq const state = await this.getStateToPostToWebview() + // A delayed startup snapshot must not replace a newer healthy history list. + if (!historyWasReady && this.taskHistoryStoreInitialized) { + state.taskHistory = this.getAvailableTaskHistory().filter((item) => item.ts && item.task) + } state.clineMessagesSeq = clineMessagesSeq await this.postMessageToWebview({ type: "state", state }) } @@ -2793,8 +2867,8 @@ export class ClineProvider } async getStateToPostToWebview({ includeTaskHistory = true }: GetStateOptions = {}): Promise { - // Ensure the store is initialized before reading task history - await this.taskHistoryStore.initialized + // Use legacy history until initialization and migration are ready. + // Runtime metadata reads can independently use already-cached task records. const { apiConfiguration, @@ -2986,7 +3060,7 @@ export class ClineProvider currentTaskTodos: currentTask?.todoList || [], messageQueue: currentTask?.messageQueueService?.messages, taskHistory: includeTaskHistory - ? this.taskHistoryStore.getAll().filter((item: HistoryItem) => item.ts && item.task) + ? this.getAvailableTaskHistory().filter((item) => item.ts && item.task) : [], soundEnabled: soundEnabled ?? false, ttsEnabled: ttsEnabled ?? false, @@ -3226,7 +3300,7 @@ export class ClineProvider allowedMaxCost: stateValues.allowedMaxCost, autoCondenseContext: stateValues.autoCondenseContext ?? true, autoCondenseContextPercent: stateValues.autoCondenseContextPercent ?? 100, - taskHistory: includeTaskHistory ? this.taskHistoryStore.getAll() : [], + taskHistory: includeTaskHistory ? this.getAvailableTaskHistory() : [], allowedCommands: stateValues.allowedCommands, deniedCommands: stateValues.deniedCommands, soundEnabled: stateValues.soundEnabled ?? false, @@ -3362,7 +3436,7 @@ export class ClineProvider return } - const taskHistory = history ?? this.taskHistoryStore.getAll() + const taskHistory = history ?? this.getAvailableTaskHistory() // Sort and filter the history the same way as getStateToPostToWebview const sortedHistory = taskHistory @@ -3515,7 +3589,7 @@ export class ClineProvider return this.recentTasksCache } - const history = this.taskHistoryStore.getAll() + const history = this.getAvailableTaskHistory() const workspaceTasks: HistoryItem[] = [] for (const item of history) { @@ -3681,7 +3755,7 @@ export class ClineProvider private async cancelTaskInternal(task: Task): Promise { let historyItem: HistoryItem | undefined try { - const history = await this.getTaskWithId(task.taskId) + const history = await this.getTaskWithId(task.taskId, { includeApiConversationHistory: false }) historyItem = history.historyItem } catch (error) { // During task startup there is a short window where currentTask exists @@ -3764,14 +3838,17 @@ export class ClineProvider if (task.parentTaskId) { try { await this.runDelegationTransition(task.parentTaskId, async () => { - const { historyItem: parentHistory } = await this.getTaskWithId(task.parentTaskId!) + const { historyItem: parentHistory } = await this.getTaskWithId(task.parentTaskId!, { + includeApiConversationHistory: false, + }) if (parentHistory?.status === "delegated" && parentHistory?.awaitingChildId === task.taskId) { // Refresh the child after acquiring the parent transition lock. The pre-abort // history snapshot can be stale if another serialized path interrupted it. historyItem = this.taskHistoryStore.get(task.taskId) ?? - (await this.getTaskWithId(task.taskId)).historyItem + (await this.getTaskWithId(task.taskId, { includeApiConversationHistory: false })) + .historyItem // Mark the child interrupted and leave parent delegated with awaitingChildId // intact — the user can resume this child later and it will report back. // A previous cancellation may already have persisted the interrupted status @@ -4246,7 +4323,9 @@ export class ClineProvider // this process, so leave the parent unrestored. Restart recovery also // settles interrupted create-subtask actions before allowing replay. if (!settlementFailed) { - const { historyItem: parentHistory } = await this.getTaskWithId(parentTaskId) + const { historyItem: parentHistory } = await this.getTaskWithId(parentTaskId, { + includeApiConversationHistory: false, + }) await this.createTaskWithHistoryItem(parentHistory) } } catch (rollbackError) { @@ -4324,7 +4403,7 @@ export class ClineProvider const globalStoragePath = this.contextProxy.globalStorageUri.fsPath // 1) Load parent from history and current persisted messages - const { historyItem } = await this.getTaskWithId(parentTaskId) + const { historyItem } = await this.getTaskWithId(parentTaskId, { includeApiConversationHistory: false }) const childHistory = this.taskHistoryStore.get(childTaskId) if (pendingActionId && childHistory?.pendingAction?.actionId !== pendingActionId) { this.log( @@ -4664,7 +4743,9 @@ export class ClineProvider * links are cleared so a later resume-and-complete cannot reattach it. */ public async abandonSubtask(childTaskId: string): Promise { - const { historyItem: childHistory } = await this.getTaskWithId(childTaskId) + const { historyItem: childHistory } = await this.getTaskWithId(childTaskId, { + includeApiConversationHistory: false, + }) const parentTaskId = childHistory.parentTaskId if (!parentTaskId) { @@ -4682,7 +4763,9 @@ export class ClineProvider } return this.runDelegationTransition(parentTaskId, async () => { - const { historyItem: parentHistory } = await this.getTaskWithId(parentTaskId) + const { historyItem: parentHistory } = await this.getTaskWithId(parentTaskId, { + includeApiConversationHistory: false, + }) if (parentHistory?.status !== "delegated" || parentHistory?.awaitingChildId !== childTaskId) { this.log( diff --git a/src/core/webview/__tests__/ClineProvider.spec.ts b/src/core/webview/__tests__/ClineProvider.spec.ts index 779313d385..8949305529 100644 --- a/src/core/webview/__tests__/ClineProvider.spec.ts +++ b/src/core/webview/__tests__/ClineProvider.spec.ts @@ -1,5 +1,7 @@ // pnpm --filter roo-cline test core/webview/__tests__/ClineProvider.spec.ts +import type { HistoryItem } from "@roo-code/types" + import fs from "fs" import * as path from "path" import { TaskRegistry } from "../../task/TaskRegistry" @@ -30,7 +32,8 @@ 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 { attemptCompletionTool, type AttemptCompletionCallbacks } from "../../tools/AttemptCompletionTool" +import { recoverJsonFile, safeWriteJson } from "../../../utils/safeWriteJson" import { ClineProvider } from "../ClineProvider" import { webviewMessageHandler } from "../webviewMessageHandler" @@ -1485,7 +1488,482 @@ 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() + } + }) + + describe("history initialization availability", () => { + const item: HistoryItem = { + id: "waiting-history", + number: 1, + ts: 1, + task: "legacy", + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + } + + async function unavailableInitialization(phase: "pending" | "failed") { + await provider["initializeTaskHistoryStore"]() + await mockContext.globalState.update("taskHistoryMigratedToFiles", true) + provider["taskHistoryStoreInitialized"] = false + let release!: () => void + const waiting = new Promise((resolve) => { + release = resolve + }) + const failure = Object.assign(new Error("history unavailable"), { code: "EIO" }) + const initialize = vi.spyOn(provider.taskHistoryStore, "initialize") + if (phase === "pending") initialize.mockReturnValue(waiting) + else initialize.mockRejectedValue(failure) + const pending = provider["initializeTaskHistoryStore"]() + if (phase === "failed") await pending + return { + initialize, + async finish() { + release() + await pending + initialize.mockRestore() + }, + } + } + + it.each(["pending", "failed"] as const)("cancels a cached task while initialization is %s", async (phase) => { + const initialization = await unavailableInitialization(phase) + const task = new Task({ ...defaultTaskOptions, historyItem: item }) + const replacement = new Task({ ...defaultTaskOptions, historyItem: { ...item, id: "replacement" } }) + Object.assign(replacement, { instanceId: "replacement-instance", isStreaming: false }) + const current = vi.spyOn(provider, "getCurrentTask").mockReturnValue(task) + const abort = vi.fn().mockImplementation(async () => { + current.mockReturnValue(replacement) + }) + const cancel = vi.fn() + Object.assign(task, { + instanceId: "original-instance", + isStreaming: false, + abortTask: abort, + cancelCurrentRequest: cancel, + setAbortReason: vi.fn(), + requestAbandon: vi.fn(), + } satisfies Partial) + provider.taskHistoryStore["cache"].set(item.id, item) + initialization.initialize.mockClear() + try { + await provider.cancelTask() + expect(cancel).toHaveBeenCalledOnce() + expect(abort).toHaveBeenCalledOnce() + expect(initialization.initialize).not.toHaveBeenCalled() + } finally { + current.mockRestore() + await initialization.finish() + } + }) + + it.each(["pending", "failed"] as const)( + "completes a cached delegated child while initialization is %s", + async (phase) => { + const initialization = await unavailableInitialization(phase) + const child = { ...item, id: "cached-child", status: "active" as const, parentTaskId: "cached-parent" } + const parent = { ...item, id: "cached-parent", status: "delegated" as const, awaitingChildId: child.id } + provider.taskHistoryStore["cache"].set(child.id, child) + provider.taskHistoryStore["cache"].set(parent.id, parent) + const task = new Task({ ...defaultTaskOptions, historyItem: child }) + Object.assign(task, { + parentTaskId: parent.id, + providerRef: new WeakRef(provider), + say: vi.fn().mockResolvedValue(undefined), + flushTelemetryInstallment: vi.fn(), + waitForCurrentAssistantMessagePersistence: vi + .fn() + .mockResolvedValue(true), + emitFinalTokenUsageUpdate: vi.fn(), + getTokenUsage: vi + .fn() + .mockReturnValue({ totalTokensIn: 0, totalTokensOut: 0, totalCost: 0, contextTokens: 0 }), + toolUsage: {}, + } satisfies Partial) + const reopen = vi.spyOn(provider, "reopenParentFromDelegation").mockResolvedValue(true) + const completed = vi.spyOn(provider, "emitDelegatedTaskCompleted").mockImplementation(() => {}) + const callbacks: AttemptCompletionCallbacks = { + askApproval: vi.fn().mockResolvedValue(true), + handleError: vi.fn(), + pushToolResult: vi.fn(), + toolCallId: "", + askFinishSubTaskApproval: vi.fn().mockResolvedValue(true), + toolDescription: () => "complete", + } + initialization.initialize.mockClear() + try { + await attemptCompletionTool.execute({ result: "done" }, task, callbacks) + expect(reopen).toHaveBeenCalledWith({ + parentTaskId: parent.id, + childTaskId: child.id, + completionResultSummary: "done", + }) + expect(completed).toHaveBeenCalledOnce() + expect(callbacks.handleError).not.toHaveBeenCalled() + expect(initialization.initialize).not.toHaveBeenCalled() + } finally { + reopen.mockRestore() + completed.mockRestore() + await initialization.finish() + } + }, + ) + + it("uses unmigrated legacy history without starting initialization", async () => { + await provider["initializeTaskHistoryStore"]() + await mockContext.globalState.update("taskHistoryMigratedToFiles", false) + await provider["contextProxy"].setValue("taskHistory", [item]) + expect(mockContext.globalState.get("taskHistory")).toEqual([item]) + provider.taskHistoryStore["cache"].clear() + provider["taskHistoryStoreInitialized"] = false + const initialize = vi.spyOn(provider.taskHistoryStore, "initialize") + try { + expect( + (await provider.getTaskWithId(item.id, { includeApiConversationHistory: false })).historyItem, + ).toEqual(item) + expect(initialize).not.toHaveBeenCalled() + } finally { + initialize.mockRestore() + } + }) + + it.each(["costs", "open", "resume"] as const)( + "serves cached runtime metadata while explicit %s waits for fresh history", + async (action) => { + const initialization = await unavailableInitialization("pending") + const stale = { ...item, totalCost: 1 } + const fresh = { ...item, totalCost: 2 } + provider.taskHistoryStore["cache"].set(item.id, stale) + let querySettled = false + const operation = + action === "costs" + ? provider.getTaskWithAggregatedCosts(item.id) + : provider.getTaskWithId( + item.id, + action === "resume" + ? { includeApiConversationHistory: false, waitForInitialization: true } + : {}, + ) + const query = operation.then((result) => { + querySettled = true + return result + }) + try { + expect( + (await provider.getTaskWithId(item.id, { includeApiConversationHistory: false })).historyItem, + ).toEqual(stale) + expect(querySettled).toBe(false) + expect(initialization.initialize).toHaveBeenCalledOnce() + provider.taskHistoryStore["cache"].set(item.id, fresh) + await initialization.finish() + expect((await query).historyItem).toEqual(fresh) + } finally { + await initialization.finish() + } + }, + ) + + it("does not let a delayed legacy snapshot overwrite the initialization-complete post", async () => { + const initialization = await unavailableInitialization("pending") + await provider["contextProxy"].setValue("taskHistory", [item]) + const fresh = { ...item, task: "ready" } + provider.taskHistoryStore["cache"].set(item.id, fresh) + let captured!: () => void + const didCapture = new Promise((resolve) => { + captured = resolve + }) + let release!: () => void + const waiting = new Promise((resolve) => { + release = resolve + }) + const getState = provider.getStateToPostToWebview.bind(provider) + const state = vi.spyOn(provider, "getStateToPostToWebview").mockImplementationOnce(async () => { + const legacy = await getState() + expect(legacy.taskHistory).toEqual([item]) + captured() + await waiting + return legacy + }) + const post = vi.spyOn(provider, "postMessageToWebview").mockResolvedValue(undefined) + provider.isViewLaunched = true + const first = provider.postStateToWebview() + try { + await didCapture + await initialization.finish() + expect(post).toHaveBeenCalledOnce() + release() + await first + const histories = post.mock.calls.flatMap(([message]) => + message.type === "state" ? [message.state?.taskHistory] : [], + ) + expect(histories).toEqual([[fresh], [fresh]]) + } finally { + release() + await first + provider.isViewLaunched = false + state.mockRestore() + post.mockRestore() + await initialization.finish() + } + }) + + it("keeps history ready if the initialization-complete state post fails", async () => { + await provider["initializeTaskHistoryStore"]() + const post = vi.spyOn(provider, "postStateToWebview").mockRejectedValue(new Error("post failed")) + provider.isViewLaunched = true + provider["recentTasksCache"] = ["stale"] + try { + await provider["initializeTaskHistoryStore"]() + expect(provider["taskHistoryStoreInitialized"]).toBe(true) + expect(provider["taskHistoryInitializationError"]).toBeUndefined() + expect(provider["recentTasksCache"]).toBeUndefined() + expect(mockOutputChannel.appendLine).toHaveBeenCalledWith( + expect.stringContaining("History is ready but state publication failed"), + ) + } finally { + provider.isViewLaunched = false + post.mockRestore() + } + }) + + it("does not log degraded history when disposal interrupts initialization", async () => { + await provider["initializeTaskHistoryStore"]() + let reject!: () => void + const initialize = vi.spyOn(provider.taskHistoryStore, "initialize").mockReturnValue( + new Promise((_resolve, rejectPromise) => { + reject = () => rejectPromise(new Error("disposed during initialization")) + }), + ) + const pending = provider["initializeTaskHistoryStore"]() + provider["_disposed"] = true + vi.mocked(mockOutputChannel.appendLine).mockClear() + try { + reject() + await pending + expect(provider["taskHistoryInitializationError"]).toBeUndefined() + expect(mockOutputChannel.appendLine).not.toHaveBeenCalled() + } finally { + provider["_disposed"] = false + initialize.mockRestore() + } + }) + + it("shares pending initialization with an open instead of reporting a missing task", async () => { + await provider["initializeTaskHistoryStore"]() + await mockContext.globalState.update("taskHistoryMigratedToFiles", true) + provider["taskHistoryStoreInitialized"] = false + let release!: () => void + const waiting = new Promise((resolve) => { + release = resolve + }) + const initialize = vi.spyOn(provider.taskHistoryStore, "initialize").mockImplementation(async () => { + await waiting + provider.taskHistoryStore["cache"].set(item.id, item) + }) + try { + const initialization = provider["initializeTaskHistoryStore"]() + const opening = provider.getTaskWithId(item.id) + expect(initialize).toHaveBeenCalledOnce() + release() + await initialization + expect((await opening).historyItem).toEqual(item) + } finally { + initialize.mockRestore() + } + }) + + it.each(["scan", "migration"])( + "keeps legacy state after a failed %s and retries on the next open", + async (phase) => { + await provider["initializeTaskHistoryStore"]() + await mockContext.globalState.update("taskHistoryMigratedToFiles", phase === "scan") + await mockContext.globalState.update("taskHistory", [item]) + await provider["contextProxy"].setValue("taskHistory", [item]) + const repaired = { ...item, task: "repaired" } + provider["taskHistoryStoreInitialized"] = false + provider.taskHistoryStore["cache"].set(item.id, repaired) + const failure = Object.assign(new Error("history disk failed"), { code: "EIO" }) + const initialize = vi.spyOn(provider.taskHistoryStore, "initialize").mockResolvedValue() + const migrate = vi.spyOn(provider.taskHistoryStore, "migrateFromGlobalState").mockResolvedValue() + if (phase === "scan") initialize.mockRejectedValueOnce(failure) + else migrate.mockRejectedValueOnce(failure) + const health = vi.spyOn(provider.taskHistoryStore, "isHealthy", "get").mockReturnValue(true) + try { + await provider["initializeTaskHistoryStore"]() + expect(provider["taskHistoryStoreInitialized"]).toBe(false) + expect((await provider.getStateToPostToWebview()).taskHistory).toEqual([item]) + expect((await provider.getState()).taskHistory).toEqual([item]) + expect(mockOutputChannel.appendLine).toHaveBeenCalledWith( + expect.stringMatching(/degraded mode.*Code: EIO.*Error: history disk failed/s), + ) + expect((await provider.getTaskWithId(item.id)).historyItem).toEqual(repaired) + expect(provider["taskHistoryStoreInitialized"]).toBe(true) + expect((await provider.getStateToPostToWebview()).taskHistory).toEqual([repaired]) + } finally { + initialize.mockRestore() + migrate.mockRestore() + health.mockRestore() + } + }, + ) + + it("reports unavailable history rather than a missing task after a terminal retry", async () => { + await provider["initializeTaskHistoryStore"]() + await mockContext.globalState.update("taskHistoryMigratedToFiles", true) + provider["taskHistoryStoreInitialized"] = false + const failure = Object.assign(new Error("cannot read history"), { code: "EACCES" }) + const initialize = vi.spyOn(provider.taskHistoryStore, "initialize").mockRejectedValue(failure) + try { + await expect(provider.getTaskWithId(item.id)).rejects.toMatchObject({ + message: expect.stringContaining("Task history is unavailable"), + cause: failure, + }) + } finally { + initialize.mockRestore() + } + }) + + it.each([false, true])( + "publishes healthy history when the first post finishes after initialization: %s", + async (finishInitializationFirst) => { + await provider["initializeTaskHistoryStore"]() + await provider["contextProxy"].setValue("taskHistory", [item]) + const repaired = { ...item, task: "ready" } + provider.taskHistoryStore["cache"].set(item.id, repaired) + provider["taskHistoryStoreInitialized"] = false + let releaseInitialization!: () => void + const waiting = new Promise((resolve) => { + releaseInitialization = resolve + }) + const initialize = vi.spyOn(provider.taskHistoryStore, "initialize").mockReturnValue(waiting) + const post = vi.spyOn(provider, "postMessageToWebview").mockResolvedValue(undefined) + const getState = provider.getState.bind(provider) + let releaseFirstPost!: () => void + const firstWaiting = new Promise((resolve) => { + releaseFirstPost = resolve + }) + const state = vi.spyOn(provider, "getState").mockImplementationOnce(async (options) => { + if (finishInitializationFirst) await firstWaiting + return getState(options) + }) + provider.isViewLaunched = true + try { + const initialization = provider["initializeTaskHistoryStore"]() + const firstPost = provider.postStateToWebview() + if (!finishInitializationFirst) await firstPost + releaseInitialization() + await initialization + releaseFirstPost() + await firstPost + const histories = post.mock.calls.flatMap(([message]) => + message.type === "state" ? [message.state?.taskHistory] : [], + ) + expect(histories).toEqual( + finishInitializationFirst ? [[repaired], [repaired]] : [[item], [repaired]], + ) + } finally { + provider.isViewLaunched = false + initialize.mockRestore() + post.mockRestore() + state.mockRestore() + } + }, + ) + + it("skips API history for metadata-only lookups", async () => { + await provider["initializeTaskHistoryStore"]() + provider.taskHistoryStore["cache"].set(item.id, item) + const fsp = await import("fs/promises") + const read = vi + .spyOn(fsp, "readFile") + .mockClear() + .mockRejectedValue(Object.assign(new Error("busy API history"), { code: "ELOCKED" })) + try { + expect( + (await provider.getTaskWithId(item.id, { includeApiConversationHistory: false })).historyItem, + ).toEqual(item) + expect(read).not.toHaveBeenCalled() + } finally { + read.mockRestore() + } + }) + + it("reads metadata for costs without opening locked API history", async () => { + await provider["initializeTaskHistoryStore"]() + provider.taskHistoryStore["cache"].set(item.id, item) + const conversation = vi + .spyOn(provider, "getTaskWithId") + .mockRejectedValue(Object.assign(new Error("busy conversation"), { code: "ELOCKED" })) + try { + expect((await provider.getTaskWithAggregatedCosts(item.id)).historyItem).toEqual(item) + expect(conversation).not.toHaveBeenCalled() + } finally { + conversation.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]) + await provider["contextProxy"].setValue("taskHistory", [item, { ...item, id: "invalid", ts: 0 }]) + try { + provider["taskHistoryStoreInitialized"] = true + const state = await provider.getStateToPostToWebview({ includeTaskHistory }) + expect(state.taskHistory).toEqual(includeTaskHistory ? [healthy ? cached : item] : []) + expect(getAll).toHaveBeenCalledTimes(healthy && includeTaskHistory ? 1 : 0) + } finally { + health.mockRestore() + getAll.mockRestore() + } + }, + ) + test("getStateToPostToWebview computes task history once after its base state resolves", async () => { + provider["taskHistoryStoreInitialized"] = true + const health = vi.spyOn(provider.taskHistoryStore, "isHealthy", "get").mockReturnValue(true) const historyItem = { id: "history-task", number: 1, @@ -1515,6 +1993,7 @@ describe("ClineProvider", () => { expect(getAllSpy).toHaveBeenCalledOnce() expect(historyReadPhases).toEqual([true]) expect(state.taskHistory).toEqual([historyItem]) + health.mockRestore() }) describe("postStateToWebviewThrottled", () => { @@ -3019,6 +3498,57 @@ 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 initialize = vi.spyOn(provider.taskHistoryStore, "initialize").mockResolvedValue() + 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 { + initialize.mockRestore() + current.mockRestore() + update.mockRestore() + health.mockRestore() + } + }, + ) + }) + describe("handleModeSwitch", () => { beforeEach(async () => { // Set up webview for each test @@ -5805,6 +6335,19 @@ describe("ClineProvider - Comprehensive Edit/Delete Edge Cases", () => { }) describe("getTaskWithId", () => { + const apiHistoryPath = path.join("/test/task/path", "api_conversation_history.json") + + beforeEach(async () => { + provider["taskHistoryStoreInitialized"] = true + 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", @@ -5829,14 +6372,32 @@ describe("ClineProvider - Comprehensive Edit/Delete Edge Cases", () => { await expect(provider.getTaskWithId(historyItem.id)).rejects.toThrow("Task not found") }) - it("rejects a missing task before file-backed history initialization", async () => { + it("rejects a missing task after waiting for file-backed history initialization", async () => { + const initialize = vi.fn(provider["initializeTaskHistoryStore"].bind(provider)).mockResolvedValue(undefined) + const originalInitialize = provider["initializeTaskHistoryStore"] + provider["initializeTaskHistoryStore"] = initialize + provider["taskHistoryInitializationError"] = undefined provider["taskHistoryStoreInitialized"] = false vi.mocked(mockContext.globalState.get).mockReturnValue(undefined) - await expect(provider.getTaskWithId("cold-start-missing-task")).rejects.toThrow("Task not found") + try { + await expect(provider.getTaskWithId("cold-start-missing-task")).rejects.toThrow("Task not found") + expect(initialize).toHaveBeenCalledOnce() + } finally { + provider["initializeTaskHistoryStore"] = originalInitialize + } }) it("returns empty apiConversationHistory when file is missing", async () => { - const historyItem = { id: "missing-api-file-task", task: "test task", ts: Date.now() } + const historyItem = { + id: "missing-api-file-task", + task: "test task", + ts: Date.now(), + number: 1, + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + } + provider.taskHistoryStore["cache"].set(historyItem.id, historyItem) vi.mocked(mockContext.globalState.get).mockImplementation((key: string) => { if (key === "taskHistory") { return [historyItem] @@ -5846,15 +6407,75 @@ 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(), + number: 1, + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + } + provider.taskHistoryStore["cache"].set(historyItem.id, historyItem) + 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(), + number: 1, + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + } + provider.taskHistoryStore["cache"].set(historyItem.id, historyItem) + 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() } + const historyItem = { + id: "corrupt-api-task", + task: "test task", + ts: Date.now(), + number: 1, + tokensIn: 0, + tokensOut: 0, + totalCost: 0, + } + provider.taskHistoryStore["cache"].set(historyItem.id, historyItem) vi.mocked(mockContext.globalState.get).mockImplementation((key: string) => { if (key === "taskHistory") { return [historyItem] @@ -5862,24 +6483,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 7b6223e2e2..5eb316b894 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__/checkpointRestoreHandler.spec.ts b/src/core/webview/__tests__/checkpointRestoreHandler.spec.ts index 21e9405125..86fa3c9264 100644 --- a/src/core/webview/__tests__/checkpointRestoreHandler.spec.ts +++ b/src/core/webview/__tests__/checkpointRestoreHandler.spec.ts @@ -188,7 +188,9 @@ describe("checkpointRestoreHandler", () => { }) // Verify getTaskWithId was called - expect(mockProvider.getTaskWithId).toHaveBeenCalledWith("test-task-123") + expect(mockProvider.getTaskWithId).toHaveBeenCalledWith("test-task-123", { + includeApiConversationHistory: false, + }) // Verify createTaskWithHistoryItem was called with the correct history item expect(mockProvider.createTaskWithHistoryItem).toHaveBeenCalledWith(expectedHistoryItem) diff --git a/src/core/webview/__tests__/diagnosticsHandler.spec.ts b/src/core/webview/__tests__/diagnosticsHandler.spec.ts index 38d55e01c5..14e9104d89 100644 --- a/src/core/webview/__tests__/diagnosticsHandler.spec.ts +++ b/src/core/webview/__tests__/diagnosticsHandler.spec.ts @@ -24,9 +24,9 @@ vi.mock("../../../utils/storage", () => ({ getTaskDirectoryPath: vi.fn(async () => "/mock/task-dir"), })) -// Mock fs utilities -vi.mock("../../../utils/fs", () => ({ - fileExistsAtPath: vi.fn(), +vi.mock("../../task-persistence/readFileWithMissingRetry", async (importOriginal) => ({ + ...(await importOriginal()), + readFileWithMissingRetry: vi.fn(), })) // Mock fs/promises @@ -46,7 +46,7 @@ vi.mock("fs/promises", () => { import * as vscode from "vscode" import * as fs from "fs/promises" -import * as fsUtils from "../../../utils/fs" +import { readFileWithMissingRetry } from "../../task-persistence/readFileWithMissingRetry" import { generateErrorDiagnostics } from "../diagnosticsHandler" describe("generateErrorDiagnostics", () => { @@ -54,11 +54,14 @@ describe("generateErrorDiagnostics", () => { beforeEach(() => { vi.clearAllMocks() + vi.mocked(readFileWithMissingRetry) + .mockReset() + .mockRejectedValue(Object.assign(new Error("missing"), { code: "ENOENT" })) + vi.mocked(fs.writeFile).mockReset().mockResolvedValue() }) it("generates a diagnostics file with error metadata and history", async () => { - vi.mocked(fsUtils.fileExistsAtPath).mockResolvedValue(true as any) - vi.mocked(fs.readFile).mockResolvedValue('[{"role": "user", "content": "test"}]' as any) + vi.mocked(readFileWithMissingRetry).mockResolvedValue('[{"role": "user", "content": "test"}]') const result = await generateErrorDiagnostics({ taskId: "test-task-id", @@ -77,7 +80,9 @@ describe("generateErrorDiagnostics", () => { expect(result.filePath).toContain("zoo-diagnostics-") // Verify we attempted to read API history - expect(fs.readFile).toHaveBeenCalledWith(path.join("/mock/task-dir", "api_conversation_history.json"), "utf8") + expect(readFileWithMissingRetry).toHaveBeenCalledWith( + path.join("/mock/task-dir", "api_conversation_history.json"), + ) // Verify we wrote a diagnostics file with the expected content expect(fs.writeFile).toHaveBeenCalledTimes(1) @@ -100,8 +105,6 @@ describe("generateErrorDiagnostics", () => { }) it("uses empty history when API history file does not exist", async () => { - vi.mocked(fsUtils.fileExistsAtPath).mockResolvedValue(false as any) - const result = await generateErrorDiagnostics({ taskId: "test-task-id", globalStoragePath: "/mock/global/storage", @@ -117,8 +120,8 @@ describe("generateErrorDiagnostics", () => { expect(result.success).toBe(true) - // Should not attempt to read file when it doesn't exist - expect(fs.readFile).not.toHaveBeenCalled() + // The recovery reader must decide absence, rather than a canonical-only existence check. + expect(readFileWithMissingRetry).toHaveBeenCalledOnce() // Verify empty history in output const [, writtenContent] = vi.mocked(fs.writeFile).mock.calls[0] @@ -126,8 +129,6 @@ describe("generateErrorDiagnostics", () => { }) it("uses default values when values are not provided", async () => { - vi.mocked(fsUtils.fileExistsAtPath).mockResolvedValue(false as any) - const result = await generateErrorDiagnostics({ taskId: "test-task-id", globalStoragePath: "/mock/global/storage", @@ -145,8 +146,7 @@ describe("generateErrorDiagnostics", () => { }) it("handles JSON parse error gracefully", async () => { - vi.mocked(fsUtils.fileExistsAtPath).mockResolvedValue(true as any) - vi.mocked(fs.readFile).mockResolvedValue("invalid json" as any) + vi.mocked(readFileWithMissingRetry).mockResolvedValue("invalid json") const result = await generateErrorDiagnostics({ taskId: "test-task-id", @@ -171,7 +171,6 @@ describe("generateErrorDiagnostics", () => { }) it("returns error result when file write fails", async () => { - vi.mocked(fsUtils.fileExistsAtPath).mockResolvedValue(false as any) vi.mocked(fs.writeFile).mockRejectedValue(new Error("Write failed")) const result = await generateErrorDiagnostics({ @@ -185,4 +184,14 @@ describe("generateErrorDiagnostics", () => { expect(mockLog).toHaveBeenCalledWith("Error generating diagnostics: Write failed") expect(vscode.window.showErrorMessage).toHaveBeenCalledWith("Failed to generate diagnostics: Write failed") }) + it.each(["ELOCKED", "EIO"])("reports %s instead of generating diagnostics with missing history", async (code) => { + vi.mocked(readFileWithMissingRetry).mockRejectedValue(Object.assign(new Error(code), { code })) + const result = await generateErrorDiagnostics({ + taskId: "test-task-id", + globalStoragePath: "/mock/global/storage", + log: mockLog, + }) + expect(result.success).toBe(false) + expect(fs.writeFile).not.toHaveBeenCalled() + }) }) diff --git a/src/core/webview/__tests__/webviewMessageHandler.spec.ts b/src/core/webview/__tests__/webviewMessageHandler.spec.ts index 685a7b11c1..cce396ec1f 100644 --- a/src/core/webview/__tests__/webviewMessageHandler.spec.ts +++ b/src/core/webview/__tests__/webviewMessageHandler.spec.ts @@ -119,6 +119,7 @@ const mockClineProvider = { globalStorageUri: { fsPath: "/mock/global/storage" }, }, contextProxy: { + globalStorageUri: { fsPath: "/mock/global/storage" }, context: { extensionPath: "/mock/extension/path", globalStorageUri: { fsPath: "/mock/global/storage" }, @@ -2803,6 +2804,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 @@ -3053,3 +3067,40 @@ describe("webviewMessageHandler - renameTaskWithId", () => { expect(vi.mocked(mockClineProvider.renameTaskWithId).mock.calls).toEqual(expectedCalls) }) }) + +describe("debug history recovery boundary", () => { + it.each( + (["openDebugApiHistory", "openDebugUiHistory"] as const).flatMap((type) => + (["available", "ENOENT", "ELOCKED"] as const).map((outcome) => ({ type, outcome })), + ), + )("uses recovery for $type with $outcome", async ({ type, outcome }) => { + const { webviewMessageHandler: handle } = await import("../webviewMessageHandler") + const storage = await import("../../../utils/storage") + const reader = await import("../../task-persistence/readFileWithMissingRetry") + const directory = vi.spyOn(storage, "getTaskDirectoryPath").mockResolvedValue("/mock/task") + const read = vi.spyOn(reader, "readFileWithMissingRetry") + // This debug-history action reads only taskId from the active Task. + const task = { taskId: "debug-history" } as import("../../task/Task").Task + const current = vi.spyOn(mockClineProvider, "getCurrentTask").mockReturnValue(task) + vi.mocked(fs.writeFile).mockClear() + vi.mocked(vscode.window.showErrorMessage).mockClear() + if (outcome === "available") read.mockResolvedValue("[]") + else read.mockRejectedValue(Object.assign(new Error(outcome), { code: outcome })) + try { + await handle(mockClineProvider, { type }) + const file = type === "openDebugApiHistory" ? "api_conversation_history.json" : "ui_messages.json" + expect(read).toHaveBeenCalledWith(path.join("/mock/task", file)) + if (outcome === "available") expect(fs.writeFile).toHaveBeenCalled() + else { + expect(fs.writeFile).not.toHaveBeenCalled() + expect(vscode.window.showErrorMessage).toHaveBeenCalledWith( + outcome === "ENOENT" ? `File not found: ${file}` : "Failed to open debug history: ELOCKED", + ) + } + } finally { + directory.mockRestore() + read.mockRestore() + current.mockRestore() + } + }) +}) diff --git a/src/core/webview/checkpointRestoreHandler.ts b/src/core/webview/checkpointRestoreHandler.ts index bf276e46bc..adcc1a5e9f 100644 --- a/src/core/webview/checkpointRestoreHandler.ts +++ b/src/core/webview/checkpointRestoreHandler.ts @@ -72,7 +72,9 @@ export async function handleCheckpointRestoreOperation(config: CheckpointRestore }) // Get the updated history item and reinitialize - const { historyItem } = await provider.getTaskWithId(currentCline.taskId) + const { historyItem } = await provider.getTaskWithId(currentCline.taskId, { + includeApiConversationHistory: false, + }) await provider.createTaskWithHistoryItem(historyItem) } // For edit operations, the task cancellation in checkpointRestore diff --git a/src/core/webview/diagnosticsHandler.ts b/src/core/webview/diagnosticsHandler.ts index 6d242531c1..27a95258da 100644 --- a/src/core/webview/diagnosticsHandler.ts +++ b/src/core/webview/diagnosticsHandler.ts @@ -4,7 +4,7 @@ import * as fs from "fs/promises" import * as vscode from "vscode" import { getTaskDirectoryPath } from "../../utils/storage" -import { fileExistsAtPath } from "../../utils/fs" +import { getErrorCode, readFileWithMissingRetry } from "../task-persistence/readFileWithMissingRetry" export interface ErrorDiagnosticsValues { timestamp?: string @@ -42,14 +42,16 @@ export async function generateErrorDiagnostics(params: GenerateDiagnosticsParams const apiHistoryPath = path.join(taskDirPath, "api_conversation_history.json") let history: unknown = [] - if (await fileExistsAtPath(apiHistoryPath)) { - const content = await fs.readFile(apiHistoryPath, "utf8") + try { + const content = await readFileWithMissingRetry(apiHistoryPath) try { history = JSON.parse(content) } catch { // If parsing fails, fall back to empty history but still generate diagnostics file vscode.window.showErrorMessage("Failed to parse api_conversation_history.json") } + } catch (error) { + if (getErrorCode(error) !== "ENOENT") throw error } const diagnostics = { diff --git a/src/core/webview/webviewMessageHandler.ts b/src/core/webview/webviewMessageHandler.ts index bd7c589958..81355d4fbe 100644 --- a/src/core/webview/webviewMessageHandler.ts +++ b/src/core/webview/webviewMessageHandler.ts @@ -1,3 +1,4 @@ +import { getErrorCode, readFileWithMissingRetry } from "../task-persistence/readFileWithMissingRetry" import { safeWriteJson } from "../../utils/safeWriteJson" import * as path from "path" import * as os from "os" @@ -596,6 +597,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 +702,6 @@ export const webviewMessageHandler = async ( ), ) - provider.isViewLaunched = true break case "newTask": // Initializing new instance of Cline will make sure that any @@ -4084,14 +4087,14 @@ export const webviewMessageHandler = async ( message.type === "openDebugApiHistory" ? "api_conversation_history.json" : "ui_messages.json" const sourceFilePath = path.join(taskDirPath, fileName) - // Check if file exists - if (!(await fileExistsAtPath(sourceFilePath))) { + let content: string + try { + content = await readFileWithMissingRetry(sourceFilePath) + } catch (error) { + if (getErrorCode(error) !== "ENOENT") throw error vscode.window.showErrorMessage(`File not found: ${fileName}`) break } - - // Read the source file - const content = await fs.readFile(sourceFilePath, "utf8") let jsonContent: unknown try { diff --git a/src/eslint-suppressions.json b/src/eslint-suppressions.json index 8a9e1fa4df..db7c3179ea 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": { @@ -1039,11 +1039,6 @@ "count": 3 } }, - "core/webview/__tests__/diagnosticsHandler.spec.ts": { - "@typescript-eslint/no-explicit-any": { - "count": 7 - } - }, "core/webview/__tests__/messageEnhancer.test.ts": { "@typescript-eslint/no-explicit-any": { "count": 8 @@ -1679,11 +1674,6 @@ "count": 2 } }, - "utils/safeWriteJson.ts": { - "@typescript-eslint/no-explicit-any": { - "count": 4 - } - }, "vitest.setup.ts": { "@typescript-eslint/no-explicit-any": { "count": 1 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..8407556746 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" @@ -265,7 +267,10 @@ export class API extends EventEmitter implements RooCodeAPI { await vscode.commands.executeCommand(`${Package.name}.SidebarProvider.focus`) await this.waitForWebviewLaunch(5_000) - const { historyItem } = await this.sidebarProvider.getTaskWithId(taskId) + const { historyItem } = await this.sidebarProvider.getTaskWithId(taskId, { + includeApiConversationHistory: false, + waitForInitialization: true, + }) await this.sidebarProvider.createTaskWithHistoryItem(historyItem) if (this.sidebarProvider.viewLaunched) { @@ -279,7 +284,7 @@ export class API extends EventEmitter implements RooCodeAPI { public async isTaskInHistory(taskId: string): Promise { try { - await this.sidebarProvider.getTaskWithId(taskId) + await this.sidebarProvider.getTaskWithId(taskId, { includeApiConversationHistory: false }) return true } catch { return false @@ -355,15 +360,22 @@ export class API extends EventEmitter implements RooCodeAPI { let uiMessages: Awaited> try { // Reject unknown ids first: readTaskMessages creates the task directory. - await this.sidebarProvider.getTaskWithId(taskId) + await this.sidebarProvider.getTaskWithId(taskId, { includeApiConversationHistory: false }) uiMessages = await readTaskMessages({ 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..80abb6aac3 --- /dev/null +++ b/src/utils/__tests__/safeWriteJson.recovery.test.ts @@ -0,0 +1,463 @@ +import * as fs from "fs/promises" +import { constants } from "fs" +import { execFileSync } from "child_process" +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), + unlink: vi.fn(actual.unlink), + 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.unlink).mockReset().mockImplementation(actual.unlink) + 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.each(["before", "opened", "after"] as const)( + "rejects non-regular %s metadata even when identity is unchanged", + async (phase) => { + let sourceOpened = false + let checked = false + vi.mocked(fs.open).mockImplementation(async (file, flags, mode) => { + const source = await actual.open(file, flags, mode) + if (file === backup) { + sourceOpened = true + if (phase === "opened") { + const stats = await source.stat({ bigint: true }) + Object.defineProperty(stats, "isFile", { value: () => false }) + vi.spyOn(source, "stat").mockResolvedValue(stats) + checked = true + } + } + return source + }) + vi.mocked(fs.lstat).mockImplementation(async (...args) => { + const stats = await actual.lstat(...args) + if ( + args[0] === backup && + args[1]?.bigint && + phase !== "opened" && + sourceOpened === (phase === "after") + ) { + Object.defineProperty(stats, "isFile", { value: () => false }) + checked = true + } + return stats + }) + await expect(recoverJsonFile(canonical)).rejects.toMatchObject({ code: "EINVAL" }) + expect(checked).toBe(true) + await expect(fs.access(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + expect(JSON.parse(await fs.readFile(backup, "utf8"))).toEqual({ committed: true }) + }, + ) + + it.skipIf(process.platform === "win32" || !constants.O_NOFOLLOW)( + "refuses a symlink swap at the open syscall", + async () => { + const secret = path.join(dir, "secret.json") + await fs.writeFile(secret, '{"secret":true}') + vi.mocked(fs.open).mockImplementation(async (file, flags, mode) => { + if (file === backup) { + // Assert before opening: the guard must apply even before descriptor validation. + expect(typeof flags).toBe("number") + if (typeof flags === "number") expect(flags & constants.O_NOFOLLOW).toBe(constants.O_NOFOLLOW) + await actual.rename(backup, backup + ".saved") + await fs.symlink(secret, backup) + } + return actual.open(file, flags, mode) + }) + await expect(recoverJsonFile(canonical)).rejects.toMatchObject({ code: "ELOOP" }) + await expect(fs.access(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + expect(await fs.readFile(secret, "utf8")).toBe('{"secret":true}') + }, + ) + + it.skipIf(process.platform === "win32" || !constants.O_NONBLOCK)( + "rejects a FIFO swapped in before open without blocking", + async () => { + vi.mocked(fs.open).mockImplementation(async (file, flags, mode) => { + if (file === backup) { + // Fail safely before a possibly blocking syscall if this flag is removed. + expect(typeof flags).toBe("number") + if (typeof flags === "number") expect(flags & constants.O_NONBLOCK).toBe(constants.O_NONBLOCK) + await actual.rename(backup, backup + ".saved") + execFileSync("mkfifo", [backup]) + } + return actual.open(file, flags, mode) + }) + await expect(recoverJsonFile(canonical)).rejects.toMatchObject({ code: "EINVAL" }) + expect((await fs.lstat(backup)).isFIFO()).toBe(true) + await expect(fs.access(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + expect(JSON.parse(await fs.readFile(backup + ".saved", "utf8"))).toEqual({ committed: true }) + }, + ) + + 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 swapped = false + let sourceOpened = false + vi.mocked(fs.open).mockImplementation(async (file, flags, mode) => { + const handle = await actual.open(file, flags, mode) + if (file === backup) sourceOpened = true + return handle + }) + vi.mocked(fs.lstat).mockImplementation(async (...args) => { + const stats = await actual.lstat(...args) + if (args[0] === backup && sourceOpened && !swapped) { + swapped = true + await fs.rename(backup, backup + ".saved") + await fs.symlink(secret, backup) + } + return stats + }) + await recoverJsonFile(canonical) + expect(swapped).toBe(true) + expect((await fs.lstat(backup + ".saved")).isFile()).toBe(true) + 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.each( + (["dev", "ino"] as const).flatMap((field) => (["before", "after"] as const).map((phase) => ({ field, phase }))), + )("rejects a regular backup with a changed $phase $field identity", async ({ field, phase }) => { + let sourceOpened = false + let changed = false + vi.mocked(fs.open).mockImplementation(async (file, flags, mode) => { + const handle = await actual.open(file, flags, mode) + if (file === backup) sourceOpened = true + return handle + }) + vi.mocked(fs.lstat).mockImplementation(async (...args) => { + const stats = await actual.lstat(...args) + if (args[0] === backup && args[1]?.bigint && sourceOpened === (phase === "after")) { + const value = stats[field] + Object.defineProperty(stats, field, { value: typeof value === "bigint" ? value + 1n : value + 1 }) + changed = true + } + return stats + }) + await expect(recoverJsonFile(canonical)).rejects.toMatchObject({ code: "EINVAL" }) + expect(changed).toBe(true) + expect(await fs.readdir(dir)).toEqual([path.basename(backup)]) + }) + + it.each(["before-open", "after-open"])("rejects a different regular inode swapped %s", async (stage) => { + let swapped = false + const swap = async () => { + await actual.rename(backup, backup + ".saved") + await fs.writeFile(backup, JSON.stringify({ replacement: true })) + swapped = true + } + vi.mocked(fs.open).mockImplementation(async (file, flags, mode) => { + if (file !== backup) return actual.open(file, flags, mode) + if (stage === "before-open") await swap() + const source = await actual.open(file, flags, mode) + if (stage === "after-open") await swap() + return source + }) + await expect(recoverJsonFile(canonical)).rejects.toMatchObject({ code: "EINVAL" }) + expect(swapped).toBe(true) + await expect(fs.access(canonical)).rejects.toMatchObject({ code: "ENOENT" }) + expect((await fs.readdir(dir)).filter((name) => name.includes(".new_"))).toEqual([]) + expect(JSON.parse(await fs.readFile(backup + ".saved", "utf8"))).toEqual({ committed: true }) + }) + + it("keeps restored data readable when backup cleanup fails", async () => { + const error = ioError("EACCES") + vi.mocked(fs.unlink).mockImplementation(async (file) => { + if (file === backup) throw error + return actual.unlink(file) + }) + const log = vi.spyOn(console, "error").mockImplementation(() => {}) + const lines: string[] = [] + setPersistenceTraceSink((line) => lines.push(line)) + await recoverJsonFile(canonical) + expect(JSON.parse(await fs.readFile(canonical, "utf8"))).toEqual({ committed: true }) + expect(JSON.parse(await fs.readFile(backup, "utf8"))).toEqual({ committed: true }) + expect(log).toHaveBeenCalledWith(expect.stringContaining("leftover"), error) + expect(lines.map((line) => JSON.parse(line.slice("[persistence-trace] ".length)))).toContainEqual( + expect.objectContaining({ stage: "json-cleanup-failed", detail: "EACCES" }), + ) + }) + + 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((await fs.readdir(dir)).filter((name) => name.includes(".new_"))).toEqual([]) + 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("breaks equal-mtime backup ties by name and discards incomplete replacements", async () => { + const newest = path.join(dir, ".history.json.bak_9_new.tmp") + const incomplete = path.join(dir, ".history.json.new_99_uncommitted.tmp") + await fs.writeFile(newest, JSON.stringify({ newest: true })) + await fs.writeFile(incomplete, '{"partial":') + for (const file of [backup, newest]) await fs.utimes(file, new Date(1_000), new Date(1_000)) + await recoverJsonFile(canonical) + expect(JSON.parse(await fs.readFile(canonical, "utf8"))).toEqual({ newest: true }) + expect(await fs.readdir(dir)).toEqual(["history.json"]) + }) + + 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([ + "json-recovered", + "ui-messages-recovery", + "ui-messages-write-start", + "ui-messages-replacement-rename", + "ui-messages-write-complete", + ]) + expect( + events.filter((event) => event.stage.startsWith("ui-messages")).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..19e417e846 --- /dev/null +++ b/src/utils/persistenceTrace.ts @@ -0,0 +1,66 @@ +/** + * 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" + | "json-recovered" + | "json-cleanup-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..c8c2707da1 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,24 +38,250 @@ 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 + tracePersistenceEvent("json-recovered", { filePath: absoluteFilePath }) + } + } + + for (const orphanPath of orphanedPaths) { + try { + await fs.unlink(orphanPath) + } catch (cleanupError) { + tracePersistenceEvent("json-cleanup-failed", { + filePath: absoluteFilePath, + detail: getErrorCode(cleanupError) ?? "IO_ERROR", + }) + 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) ?? "IO_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. * * @param {string} filePath - The absolute path to the target file. - * @param {any} data - The data to serialize to JSON and write. + * @param {unknown} data - The data to serialize to JSON and write. * @param {SafeWriteJsonOptions} options - Optional configuration for JSON formatting. * @returns {Promise} */ -async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJsonOptions): Promise { +async function safeWriteJson(filePath: string, data: unknown, options?: SafeWriteJsonOptions): Promise { const absoluteFilePath = path.resolve(filePath) let releaseLock = async () => {} // Initialized to a no-op @@ -57,7 +295,7 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso // Verify directory exists after creation attempt await fs.access(dirPath) - } catch (dirError: any) { + } catch (dirError) { console.error(`Failed to create or access directory for ${absoluteFilePath}:`, dirError) throw dirError } @@ -74,8 +312,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) ?? "IO_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 +345,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 +406,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 +432,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, @@ -209,7 +456,7 @@ async function safeWriteJson(filePath: string, data: any, options?: SafeWriteJso * @param prettyPrint Whether to format the JSON with indentation. * @returns Promise */ -async function _streamDataToFile(targetPath: string, data: any, prettyPrint = false): Promise { +async function _streamDataToFile(targetPath: string, data: unknown, prettyPrint = false): Promise { // Stream data to avoid high memory usage for large JSON objects. const fileWriteStream = fsSync.createWriteStream(targetPath, { encoding: "utf8" })