From 9d0f7e2ddd59c188df9d07ac8e74b366ae040a57 Mon Sep 17 00:00:00 2001 From: Nicky Leach Date: Fri, 2 Oct 2026 08:17:03 -0700 Subject: [PATCH] fix(adapter-utils): make the directory merge lock crash test deterministic (#14881) ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - A workspace restore merges a directory, and a cross-process lock serializes that merge > - The lock must recover after the process that holds it crashes > - One test proves that recovery: it kills the holder process and then acquires the lock > - That test failed intermittently for two independent reasons, and this pull request removes both > - First, it spawned the holder through the tsx command-line entry point, which re-spawns the evaluated code in a further child process, so the kill signal reached only the wrapper and the real holder kept the lock > - Second, it replaced the global clock to force a timeout, which left the acquisition with zero real retries, so a single transient busy result failed the test > - The benefit is a deterministic crash-recovery test and a reliable continuous-integration signal ## Linked Issues or Issue Description **What happened?** The test `recovers a killed holder even when its recorded PID has been reused` in `packages/adapter-utils/src/directory-merge-lock.test.ts` failed intermittently in continuous integration. The failure reported `ERR_WORKSPACE_RESTORE_LOCK_TIMEOUT` with `waitMs: 3` and `knownLocalHolder: false`. A rerun of the same job on the same commit passed. **Expected behavior** The test must pass every run. It must acquire the lock after the holder process dies. **Steps to reproduce** 1. Check out `master`. 2. Run `npx vitest run packages/adapter-utils/src/directory-merge-lock.test.ts`. 3. Repeat the run. The named test fails intermittently. **Paperclip version or commit** `32e9f3ba0ec000578936731990d23bb0e77493fa` **Deployment mode** Built from source. The failure appears in the general test job of continuous integration. **Agent adapter(s) involved** Not adapter-specific (core bug). **Relevant logs or output** ``` ERR_WORKSPACE_RESTORE_LOCK_TIMEOUT workspaceRestoreLock: { ownerState: 'alive', knownLocalHolder: false, waitMs: 3, ownerSameProcess: true, ownerAgeMs: 60030, ownerPredatesProcess: true } ``` ## What Changed The test file had two independent defects. This pull request removes both. **1. The kill signal did not reach the real lock holder.** The test spawned its holder through the tsx command-line entry point. That entry point re-spawns the evaluated code in a further child process. `SIGKILL` therefore killed only the wrapper, and the process that had opened the lock database survived as an orphan that still held the lock. The test now loads tsx as an `--import` hook, so the spawned process is the real holder and the kill releases the lock at once. This also stops the test from leaking an orphan process. **2. The forced clock left the acquisition with zero retries.** A test helper replaced `Date.now` to force a timeout. The implementation reads `Date.now()` one time, to compute its deadline, so that single read consumed the forced value and every later read returned a time already past the deadline. The retry loop therefore got one attempt and no retries. That is correct for a test that asserts a timeout, but the crash-recovery test asserts a *successful* acquisition, so any transient busy result on the first attempt failed it. The fix removes the clock replacement from the whole file and gives each test a real, short, explicit wait budget: - `withDirectoryMergeLock` takes a new optional wait-budget parameter. It threads through to the lock acquisition function. The production default is the existing 30-second budget, and no production call site changed. - The five tests that assert a timeout pass a real 200-millisecond budget. Each one still times out for the real reason, because the lock is genuinely held or the legacy lock directory genuinely exists. Each one now exercises at least four real retries of the 50-millisecond retry interval. - The crash-recovery test passes a real 5-second budget. A failure now reports the structured `ERR_WORKSPACE_RESTORE_LOCK_TIMEOUT` diagnostic well inside the test timeout, instead of a bare test timeout. **No test timeout increased.** Every `it(..., N)` timeout in the file equals its value on `master`. ## Verification - Measured the first cause rather than assumed it: the spawned wrapper process reported one process id, and the process that opened the lock database reported a different process id and named the wrapper as its parent. The real holder kept the lock for about 50 to 60 milliseconds after the kill. - Reproduced the failure deterministically before the change, with no artificial processor load: 15 of 15 runs failed. Confirmed the fix: 15 of 15 runs passed. - Ran the lock test file 15 times in series: 12 of 12 tests passed every time. - Confirmed the clock replacement is gone: a search for a `Date.now` override in the file returns nothing. - Confirmed the production default is unchanged at 30 seconds, and that the diff touches no production call site. - Proved the diagnostic still surfaces: with a temporary edit that held the lock with a genuine live holder, the test failed with `ERR_WORKSPACE_RESTORE_LOCK_TIMEOUT` and the full `workspaceRestoreLock` block at about 5 seconds, inside the 15-second test timeout. The temporary edit was reverted. - `workspace-restore-merge.test.ts` passed 56 of 56. The adapter test files that cover every production caller passed 116 of 116 and 52 of 52. `agent-directory-working-copies.test.ts` passed 70 of 70. - The `adapter-utils` and `server` type-checks passed with no error. - Confirmed that no spawned process survives the test run. ## Risks Low risk. The production change is one optional parameter with the existing default, so every production caller keeps the real 30-second budget and no production call site changed. The remaining change is limited to one test file. The `--import` form of the tsx hook is already used elsewhere in this repository, in the container image command and in an end-to-end test configuration. Test coverage does not drop: the owner record is diagnostic only, the SQLite reserved lock remains the authority that the tests exercise, and the timeout-asserting tests now exercise the real retry loop instead of a replaced clock. The file costs about 0.5 to 0.9 seconds more wall clock than `master`, which is the cost of the short real waits that replace the instant forced timeout. ## Model Used Claude Sonnet 5 (`claude-sonnet-5`), used with extended thinking and tool use for the diagnosis, the measurement, and the change. ## Checklist Check every box that the state of the pull request satisfies. The local test runs and the type checks are complete. Reconcile the continuous-integration and review boxes after the checks reach their terminal state. ## Test plan - [x] Continuous integration is green on every check, including the general test job. - [x] The general test job passes the file `packages/adapter-utils/src/directory-merge-lock.test.ts`. - [x] Greptile returns 5 of 5 with no open item. - [x] `mergeable: MERGEABLE` is terminal. --------- Co-authored-by: Paperclip --- .../src/directory-merge-lock.test.ts | 50 +++++++++---------- .../src/workspace-restore-merge.ts | 9 ++-- 2 files changed, 29 insertions(+), 30 deletions(-) diff --git a/packages/adapter-utils/src/directory-merge-lock.test.ts b/packages/adapter-utils/src/directory-merge-lock.test.ts index c05305fb8d6..a2b71aac55d 100644 --- a/packages/adapter-utils/src/directory-merge-lock.test.ts +++ b/packages/adapter-utils/src/directory-merge-lock.test.ts @@ -10,7 +10,13 @@ import { afterEach, describe, expect, it, vi } from "vitest"; import { withDirectoryMergeLock, WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE } from "./workspace-restore-merge.js"; describe("directory merge lock process lifetime", () => { - const loader = fileURLToPath(new URL("../../../cli/node_modules/tsx/dist/cli.mjs", import.meta.url)); + // Load tsx as an --import hook, not tsx's own CLI entry point. The CLI entry + // point re-spawns the evaluated code in a further child process, so killing + // the process this file spawns would leave that further child as an orphan + // that still holds the lock. The --import hook runs the evaluated code in + // the process this file spawns directly, so killing it really does release + // the lock. + const loader = fileURLToPath(new URL("../../../cli/node_modules/tsx/dist/loader.mjs", import.meta.url)); const module = fileURLToPath(new URL("./workspace-restore-merge.ts", import.meta.url)); const directories: string[] = []; const children: ChildProcess[] = []; @@ -38,7 +44,7 @@ describe("directory merge lock process lifetime", () => { } async function holder(target: string, env: NodeJS.ProcessEnv) { - const child = spawn(process.execPath, [loader, "--eval", ` + const child = spawn(process.execPath, ["--import", loader, "--eval", ` import { withDirectoryMergeLock } from ${JSON.stringify(module)}; withDirectoryMergeLock(${JSON.stringify(target)}, async () => { process.send?.("locked"); @@ -63,10 +69,15 @@ describe("directory merge lock process lifetime", () => { return await access(`${lock}.owner.json`).then(() => `${lock}.owner.json`, () => path.join(lock, "owner.json")); } - function expireWait() { - const now = Date.now(); - return vi.spyOn(Date, "now").mockReturnValueOnce(now).mockReturnValue(now + 60_000); - } + // A short real wait budget for a test that asserts a timeout. 200 ms still + // lets the implementation's 50 ms retry interval run at least 4 retries, so + // the timeout is reached because the lock is genuinely held, not because + // the clock was replaced. + const TIMEOUT_ASSERTION_WAIT_MS = 200; + // A short real wait budget for the crash-recovery test, which asserts a + // successful acquisition. It must absorb ordinary scheduling jitter around + // the crash while still resolving well inside the test timeout below. + const CRASH_RECOVERY_WAIT_MS = 5_000; it("recovers a killed holder even when its recorded PID has been reused", async () => { const { target, env, lock } = await fixture(); @@ -77,10 +88,7 @@ describe("directory merge lock process lifetime", () => { const recordPath = await ownerPath(lock); const record = JSON.parse(await readFile(recordPath, "utf8")); await writeFile(recordPath, JSON.stringify({ ...record, pid: process.pid })); - const clock = expireWait(); - try { - await expect(withDirectoryMergeLock(target, async () => "restored", env)).resolves.toBe("restored"); - } finally { clock.mockRestore(); } + await expect(withDirectoryMergeLock(target, async () => "restored", env, undefined, CRASH_RECOVERY_WAIT_MS)).resolves.toBe("restored"); }, 15_000); it("protects a live holder in another process regardless of diagnostic PID or age", async () => { @@ -89,10 +97,7 @@ describe("directory merge lock process lifetime", () => { const recordPath = await ownerPath(lock); await writeFile(recordPath, JSON.stringify({ pid: 2_147_483_647, createdAt: "2000-01-01T00:00:00.000Z" })); const contender = vi.fn(); - const clock = expireWait(); - try { - await expect(withDirectoryMergeLock(target, contender, env)).rejects.toMatchObject({ code: WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE }); - } finally { clock.mockRestore(); } + await expect(withDirectoryMergeLock(target, contender, env, undefined, TIMEOUT_ASSERTION_WAIT_MS)).rejects.toMatchObject({ code: WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE }); expect(contender).not.toHaveBeenCalled(); const exited = once(child, "exit"); child.send("release"); @@ -109,18 +114,12 @@ describe("directory merge lock process lifetime", () => { it("keeps the OS lock when a same-process contender closes its connection", async () => { const { target, env } = await fixture(); await withDirectoryMergeLock(target, async () => { - const clock = expireWait(); - try { - await expect(withDirectoryMergeLock(target, async () => undefined, env)).rejects.toMatchObject({ code: WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE }); - } finally { clock.mockRestore(); } + await expect(withDirectoryMergeLock(target, async () => undefined, env, undefined, TIMEOUT_ASSERTION_WAIT_MS)).rejects.toMatchObject({ code: WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE }); // A same-process test alone cannot prove that the OS lock survived: on // POSIX, closing an unmanaged descriptor can drop process-wide locks. - const result = await promisify(execFile)(process.execPath, [loader, "--eval", ` + const result = await promisify(execFile)(process.execPath, ["--import", loader, "--eval", ` import { withDirectoryMergeLock, WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE } from ${JSON.stringify(module)}; - const now = Date.now(); - let calls = 0; - Date.now = () => now + calls++ * 60_000; - withDirectoryMergeLock(${JSON.stringify(target)}, async () => "entered") + withDirectoryMergeLock(${JSON.stringify(target)}, async () => "entered", undefined, undefined, ${TIMEOUT_ASSERTION_WAIT_MS}) .then(() => { console.error("Entered a live holder's lock"); process.exit(1); }) .catch(error => { if (error.code !== WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE) { console.error(error); process.exit(1); } @@ -162,10 +161,7 @@ describe("directory merge lock process lifetime", () => { await mkdir(lock, { recursive: true }); if (kind !== "missing") await writeFile(path.join(lock, "owner.json"), kind === "malformed" ? "{broken" : JSON.stringify({ pid: 2_147_483_647, createdAt: "2000-01-01T00:00:00.000Z" })); const contender = vi.fn(); - const clock = expireWait(); - try { - await expect(withDirectoryMergeLock(target, contender, env)).rejects.toMatchObject({ code: WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE }); - } finally { clock.mockRestore(); } + await expect(withDirectoryMergeLock(target, contender, env, undefined, TIMEOUT_ASSERTION_WAIT_MS)).rejects.toMatchObject({ code: WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE }); expect(contender).not.toHaveBeenCalled(); expect((await stat(lock)).isDirectory()).toBe(true); }); diff --git a/packages/adapter-utils/src/workspace-restore-merge.ts b/packages/adapter-utils/src/workspace-restore-merge.ts index 6b05b135b90..14c58371b35 100644 --- a/packages/adapter-utils/src/workspace-restore-merge.ts +++ b/packages/adapter-utils/src/workspace-restore-merge.ts @@ -341,9 +341,9 @@ export function describeWorkspaceRestoreFailure(code: WorkspaceRestoreFailureCod } } -async function acquireDirectoryMergeLock(lockDir: string, operation?: DirectoryMergeLockOperation): Promise<() => Promise> { +async function acquireDirectoryMergeLock(lockDir: string, operation?: DirectoryMergeLockOperation, waitMs: number = LOCK_WAIT_MS): Promise<() => Promise> { const startedAt = performance.now(); - const deadline = Date.now() + LOCK_WAIT_MS; + const deadline = Date.now() + waitMs; const databasePath = `${lockDir}.sqlite`; const ownerPath = `${lockDir}.owner.json`; async function waitForLock(diagnosticOwnerPath: string) { @@ -496,13 +496,16 @@ export async function withDirectoryMergeLock( fn: (canonicalTargetDir: string) => Promise, env: NodeJS.ProcessEnv = process.env, diagnosticOperation?: DirectoryMergeLockOperation, + // Test seam only: overrides how long acquisition waits before it reports a + // timeout. Production callers must omit this and keep the real budget. + waitMs: number = LOCK_WAIT_MS, ): Promise { // Canonicalize before we hash or lock: a retargeted symlink must not let the // lock protect one directory while the caller mutates another. const canonicalTargetDir = await fs.realpath(targetDir); const lockRoot = await resolveDirectoryMergeLockRoot(env); const lockKey = createHash("sha256").update(canonicalTargetDir).digest("hex"); - const releaseLock = await acquireDirectoryMergeLock(path.join(lockRoot, `${lockKey}.lock`), diagnosticOperation); + const releaseLock = await acquireDirectoryMergeLock(path.join(lockRoot, `${lockKey}.lock`), diagnosticOperation, waitMs); try { return await fn(canonicalTargetDir); } finally {