diff --git a/packages/paperclip-runner/src/drivers/acpx/runtime-host.test.ts b/packages/paperclip-runner/src/drivers/acpx/runtime-host.test.ts index 8ec2e7cbdc..b5e714b066 100644 --- a/packages/paperclip-runner/src/drivers/acpx/runtime-host.test.ts +++ b/packages/paperclip-runner/src/drivers/acpx/runtime-host.test.ts @@ -25,6 +25,131 @@ const admissionControllers: AbortController[] = []; const pendingAdmissionOpenings = new Set>(); const pendingAdmissionCleanups = new Set>(); +// A credential or sandbox poll in this file can run behind a real retry +// envelope, not a mocked one. `stageManagedCodexCredential` first joins any +// in-flight quarantine recovery (codex-credentials.ts:183, :610-625). That +// recovery makes up to `MAX_AUTONOMOUS_CREDENTIAL_CLEANUP_ATTEMPTS` (8) +// attempts (codex-credentials.ts:19). The backoff between attempts is 10, +// 20, 40, 80, 160, 320, and 640 ms — 1,270 ms in total +// (codex-credentials.ts:558, :578-582). Each attempt can also run one real +// directory fsync. `DIRECTORY_SYNC_OPERATION_TIMEOUT_MS` (1,000 ms, +// codex-credentials.ts:18, :569, :1304) bounds that fsync. So one full +// recovery pass can cost up to 1,270 ms of backoff plus 8,000 ms of bounded +// fsync waits. +// +// When a pass does not clear the quarantine, +// `recoverQuarantinedCredentialCleanup` joins one more bounded attempt (up +// to 1,000 ms) before it gives up (codex-credentials.ts:616-619). So the +// full documented recovery path costs at least 8,000 + 1,270 + 1,000 = +// 10,270 ms. The vitest default `vi.waitFor` deadline is 1,000 ms, smaller +// than a single one of those inner bounds. So a poll can time out even +// though the call is still in progress. +// +// The helper deadline below adds margin on top of the 10,270 ms documented +// floor for the real filesystem work each attempt also does (two file +// removals and an intent-file delete, none of them bounded by +// `DIRECTORY_SYNC_OPERATION_TIMEOUT_MS`) and for this helper's own 50 ms +// poll granularity and Node event-loop scheduling jitter. A 30-second +// per-test budget keeps this wait reachable under the vitest per-test +// timeout, even for a test that runs the helper more than once. +const ACPX_OPERATION_WAIT_DEADLINE_MS = 15_000; +const ACPX_LONG_WAIT_TEST_TIMEOUT_MS = 30_000; + +/** + * Poll a credential or sandbox operation. Use a deadline derived from the + * real retry envelope described above. Unlike a bare `vi.waitFor`, report + * the last observed error when the deadline expires. Each attempt of + * `callback` is itself bounded by the remaining deadline, so a callback + * that stays pending cannot outlast the helper deadline and reach the + * enclosing vitest per-test timeout instead. + */ +async function waitForAcpxOperation( + callback: () => T | Promise, +): Promise { + const deadline = Date.now() + ACPX_OPERATION_WAIT_DEADLINE_MS; + let lastError: unknown = new Error( + "no attempt of this ACPX operation settled before the deadline", + ); + for (;;) { + try { + return await runAcpxOperationAttempt(callback, deadline); + } catch (error) { + lastError = error; + } + if (Date.now() >= deadline) { + const detail = + lastError instanceof Error + ? (lastError.stack ?? lastError.message) + : String(lastError); + throw new Error( + `ACPX operation did not settle within ${ACPX_OPERATION_WAIT_DEADLINE_MS}ms. Last observed error: ${detail}`, + { cause: lastError }, + ); + } + await new Promise((resolve) => setTimeout(resolve, 50)); + } +} + +/** + * Run one attempt of `callback`, bounded by the time remaining until + * `deadline`. A callback that is still pending when the remaining time + * runs out rejects with a timeout error instead of blocking the retry + * loop past the helper deadline. + * + * A rejected attempt does not cancel `callback`. If `callback` later + * resolves to a `ManagedCodexCredentialLease`, close that lease so its + * kernel lock and active lease generation do not stay allocated for the + * rest of the test run. + */ +async function runAcpxOperationAttempt( + callback: () => T | Promise, + deadline: number, +): Promise { + const remainingMs = Math.max(0, deadline - Date.now()); + let timer: ReturnType | undefined; + let timedOut = false; + const callbackResult = Promise.resolve().then(callback); + void callbackResult.then( + (value) => { + if (timedOut) void closeLateCredentialLease(value); + }, + () => undefined, + ); + try { + return await Promise.race([ + callbackResult, + new Promise((_resolve, reject) => { + timer = setTimeout(() => { + timedOut = true; + reject( + new Error( + `ACPX operation attempt did not settle within the remaining ${remainingMs}ms of the helper deadline`, + ), + ); + }, remainingMs); + }), + ]); + } finally { + if (timer) clearTimeout(timer); + } +} + +/** + * Close `value` if it is a `ManagedCodexCredentialLease` (or another lease + * with the same `close()` shape). Swallow a close failure so cleanup of one + * late lease cannot mask the original test failure. + */ +async function closeLateCredentialLease(value: unknown): Promise { + if ( + typeof value === "object" && + value !== null && + "close" in value && + typeof (value as { close: unknown }).close === "function" + ) { + await (value as { close(): Promise }).close().catch(() => undefined); + } +} + afterEach(async () => { for (const controller of admissionControllers.splice(0)) { if (!controller.signal.aborted) { @@ -211,7 +336,7 @@ describe("ACPX runtime host", () => { expect(createRuntime).not.toHaveBeenCalled(); expect(fixture.commandClose).toHaveBeenCalledOnce(); const authPath = join(credentialHome, "auth.json"); - const contender = await vi.waitFor(() => + const contender = await waitForAcpxOperation(() => stageManagedCodexCredential({ agentHomeDirectory: credentialHome, environment: { @@ -235,7 +360,7 @@ describe("ACPX runtime host", () => { ); await retryHost.close({ reason: "retry admission complete" }); expect(retryRuntime.close).toHaveBeenCalledOnce(); - }); + }, ACPX_LONG_WAIT_TEST_TIMEOUT_MS); it("composes admission, isolation, model verification, and cleanup", async () => { const fixture = await hostFixture(); @@ -575,7 +700,7 @@ describe("ACPX runtime host", () => { ), ).rejects.toThrow(/initialization and cleanup failed/); - await vi.waitFor(() => expect(runtime.close).toHaveBeenCalledTimes(2)); + await waitForAcpxOperation(() => expect(runtime.close).toHaveBeenCalledTimes(2)); await expect(readFile(authPath, "utf8")).resolves.toContain( "failed-admission", ); @@ -589,19 +714,21 @@ describe("ACPX runtime host", () => { ).rejects.toThrow("already has an active lease"); resolveRetryClose(); - await vi.waitFor(async () => { + await waitForAcpxOperation(async () => { await expect(readFile(authPath)).rejects.toMatchObject({ code: "ENOENT", }); }); - const contender = await stageManagedCodexCredential({ - agentHomeDirectory: credentialHome, - environment: { - PAPERCLIP_ACPX_CODEX_AUTH_JSON_SECRET: '{"owner":"contender"}', - }, - }); + const contender = await waitForAcpxOperation(() => + stageManagedCodexCredential({ + agentHomeDirectory: credentialHome, + environment: { + PAPERCLIP_ACPX_CODEX_AUTH_JSON_SECRET: '{"owner":"contender"}', + }, + }), + ); await contender.close(); - }); + }, ACPX_LONG_WAIT_TEST_TIMEOUT_MS); it("bounds post-handshake model verification and cleans the runtime", async () => { const fixture = await hostFixture(); @@ -716,14 +843,16 @@ describe("ACPX runtime host", () => { host.close({ reason: "retry close" }), ).resolves.toBeUndefined(); await expect(readFile(authPath)).rejects.toMatchObject({ code: "ENOENT" }); - const contender = await stageManagedCodexCredential({ - agentHomeDirectory: join(host.runtimeRoot(), "codex-home"), - environment: { - PAPERCLIP_ACPX_CODEX_AUTH_JSON_SECRET: '{"owner":"contender"}', - }, - }); + const contender = await waitForAcpxOperation(() => + stageManagedCodexCredential({ + agentHomeDirectory: join(host.runtimeRoot(), "codex-home"), + environment: { + PAPERCLIP_ACPX_CODEX_AUTH_JSON_SECRET: '{"owner":"contender"}', + }, + }), + ); await contender.close(); - }); + }, ACPX_LONG_WAIT_TEST_TIMEOUT_MS); it("scrubs credentials only after the exact pending runtime close resolves", async () => { const fixture = await hostFixture(); @@ -748,8 +877,8 @@ describe("ACPX runtime host", () => { const authPath = join(credentialHome, "auth.json"); const first = host.close({ reason: "runtime close pending" }); - await vi.waitFor(() => expect(runtime.close).toHaveBeenCalledOnce()); - await vi.waitFor(() => expect(fixture.commandClose).toHaveBeenCalledOnce()); + await waitForAcpxOperation(() => expect(runtime.close).toHaveBeenCalledOnce()); + await waitForAcpxOperation(() => expect(fixture.commandClose).toHaveBeenCalledOnce()); const second = host.close({ reason: "same exact close" }); await expect(readFile(authPath, "utf8")).resolves.toBe("{}"); await expect( @@ -768,14 +897,16 @@ describe("ACPX runtime host", () => { undefined, ]); await expect(readFile(authPath)).rejects.toMatchObject({ code: "ENOENT" }); - const contender = await stageManagedCodexCredential({ - agentHomeDirectory: credentialHome, - environment: { - PAPERCLIP_ACPX_CODEX_AUTH_JSON_SECRET: '{"owner":"contender"}', - }, - }); + const contender = await waitForAcpxOperation(() => + stageManagedCodexCredential({ + agentHomeDirectory: credentialHome, + environment: { + PAPERCLIP_ACPX_CODEX_AUTH_JSON_SECRET: '{"owner":"contender"}', + }, + }), + ); await contender.close(); - }); + }, ACPX_LONG_WAIT_TEST_TIMEOUT_MS); it("retains the exact pending cleanup while independent resources close", async () => { const fixture = await hostFixture(); @@ -798,7 +929,7 @@ describe("ACPX runtime host", () => { ); const first = host.close({ reason: "first close stalls" }); - await vi.waitFor(() => expect(runtime.close).toHaveBeenCalledOnce()); + await waitForAcpxOperation(() => expect(runtime.close).toHaveBeenCalledOnce()); const second = host.close({ reason: "same pending owner" }); let settled = false; void Promise.all([first, second]).finally(() => { @@ -808,7 +939,7 @@ describe("ACPX runtime host", () => { expect(settled).toBe(false); expect(runtime.close).toHaveBeenCalledOnce(); expect(fixture.commandClose).toHaveBeenCalledOnce(); - }); + }, ACPX_LONG_WAIT_TEST_TIMEOUT_MS); it("retries only after the exact close outcome settles with failure", async () => { const fixture = await hostFixture(); @@ -1079,9 +1210,9 @@ describe("ACPX runtime host", () => { close: lateCommandClose, }); - await vi.waitFor(() => expect(lateCommandClose).toHaveBeenCalledOnce()); + await waitForAcpxOperation(() => expect(lateCommandClose).toHaveBeenCalledOnce()); expect(openRuntime).not.toHaveBeenCalled(); - }); + }, ACPX_LONG_WAIT_TEST_TIMEOUT_MS); it("closes a credential lease that resolves after admission is aborted", async () => { const fixture = await hostFixture(); @@ -1140,10 +1271,10 @@ describe("ACPX runtime host", () => { close: lateCredentialClose, }); - await vi.waitFor(() => + await waitForAcpxOperation(() => expect(lateCredentialClose).toHaveBeenCalledTimes(2), ); - await vi.waitFor(async () => + await waitForAcpxOperation(async () => expect(readFile(lateCredentialPath)).rejects.toMatchObject({ code: "ENOENT", }), @@ -1156,7 +1287,7 @@ describe("ACPX runtime host", () => { }); expect(openRuntime).not.toHaveBeenCalled(); expect(fixture.commandClose).not.toHaveBeenCalled(); - }); + }, ACPX_LONG_WAIT_TEST_TIMEOUT_MS); it("retains managed credentials until an aborted late runtime is closed", async () => { const fixture = await hostFixture(); @@ -1219,7 +1350,7 @@ describe("ACPX runtime host", () => { ).rejects.toThrow("already has an active lease"); runtimeAdmission.resolve(lateRuntime); - await vi.waitFor(() => expect(lateRuntime.close).toHaveBeenCalledTimes(2)); + await waitForAcpxOperation(() => expect(lateRuntime.close).toHaveBeenCalledTimes(2)); expect(lateRuntime.close).toHaveBeenNthCalledWith(1, { reason: "ACPX runtime admission aborted", }); @@ -1234,14 +1365,14 @@ describe("ACPX runtime host", () => { ).rejects.toThrow("already has an active lease"); retryClose.resolve(undefined); - await vi.waitFor(async () => { + await waitForAcpxOperation(async () => { await expect(readFile(authPath)).rejects.toMatchObject({ code: "ENOENT", }); }); // File removal precedes kernel lease release. Wait for the lease itself so // this assertion cannot race between those two ordered cleanup steps. - const contender = await vi.waitFor(() => + const contender = await waitForAcpxOperation(() => stageManagedCodexCredential({ agentHomeDirectory: credentialHome, environment: { @@ -1250,7 +1381,7 @@ describe("ACPX runtime host", () => { }), ); await contender.close(); - }); + }, ACPX_LONG_WAIT_TEST_TIMEOUT_MS); it("scrubs credentials after rejected runtime cleanup is proven", async () => { const fixture = await hostFixture(); @@ -1298,8 +1429,8 @@ describe("ACPX runtime host", () => { expect(fixture.commandClose).toHaveBeenCalledOnce(); providerCleanup.resolve(undefined); - await vi.waitFor(() => expect(credentialClose).toHaveBeenCalledOnce()); - }); + await waitForAcpxOperation(() => expect(credentialClose).toHaveBeenCalledOnce()); + }, ACPX_LONG_WAIT_TEST_TIMEOUT_MS); }); function runtimePort(