diff --git a/packages/paperclip-runner/package.json b/packages/paperclip-runner/package.json index 07ce418ba92..e2735ae9606 100644 --- a/packages/paperclip-runner/package.json +++ b/packages/paperclip-runner/package.json @@ -94,7 +94,7 @@ "check:semantic-contracts": "pnpm run build:typescript && node scripts/generate-semantic-contracts.mjs --check", "generate:semantic-action-catalog": "pnpm run build:typescript && node scripts/generate-semantic-action-catalog.mjs", "check:semantic-action-catalog": "pnpm run build:typescript && node scripts/generate-semantic-action-catalog.mjs --check", - "check:protocol": "pnpm run typecheck:typescript && pnpm run check:protocol-manifest && pnpm run test:typescript && pnpm run check:replay-goldens", + "check:protocol": "pnpm run typecheck:typescript && pnpm run check:protocol-manifest && pnpm run check:bare-real-process-waits && pnpm run test:typescript && pnpm run check:replay-goldens", "check:runner": "pnpm run typecheck:rust && pnpm run test:rust && pnpm run check:conformance-parity && pnpm run check:replay-parity", "check:all": "pnpm run check:eval-kernel && pnpm run check:protocol && pnpm run check:runner", "generate:replay-goldens": "pnpm run build:typescript && node scripts/generate-replay-goldens.mjs", @@ -102,6 +102,7 @@ "check:browser-tokens": "node scripts/check-browser-tokens.mjs", "check:forbidden-imports": "node scripts/check-forbidden-imports.mjs", "check:tracked-imports": "node scripts/check-tracked-imports.mjs", + "check:bare-real-process-waits": "node scripts/check-bare-real-process-waits.mjs", "check:numbered-milestones": "node scripts/check-numbered-milestones.mjs", "check:package-boundaries": "node scripts/check-package-boundaries.mjs", "check:clean-consumers": "node scripts/check-clean-consumers.mjs", diff --git a/packages/paperclip-runner/scripts/check-bare-real-process-waits.mjs b/packages/paperclip-runner/scripts/check-bare-real-process-waits.mjs new file mode 100644 index 00000000000..13b89d43c25 --- /dev/null +++ b/packages/paperclip-runner/scripts/check-bare-real-process-waits.mjs @@ -0,0 +1,16 @@ +import { + checkBareRealProcessWaits, + formatBareRealProcessWaitViolation, +} from "./lib/bare-real-process-wait.mjs"; + +const violations = await checkBareRealProcessWaits(); +if (violations.length > 0) { + process.stderr.write( + `Bare real-process wait check failed:\n${violations + .map((violation) => `- ${formatBareRealProcessWaitViolation(violation)}`) + .join("\n")}\n`, + ); + process.exitCode = 1; +} else { + process.stdout.write("Bare real-process wait check passed.\n"); +} diff --git a/packages/paperclip-runner/scripts/check-bare-real-process-waits.test.mjs b/packages/paperclip-runner/scripts/check-bare-real-process-waits.test.mjs new file mode 100644 index 00000000000..742a6b1c8c2 --- /dev/null +++ b/packages/paperclip-runner/scripts/check-bare-real-process-waits.test.mjs @@ -0,0 +1,92 @@ +import assert from "node:assert/strict"; +import { test } from "node:test"; + +import { findBareRealProcessWaits } from "./lib/bare-real-process-wait.mjs"; + +test("rejects a vi.waitFor( with no in-process marker on the line above", () => { + const source = [ + "async function example() {", + " await vi.waitFor(() => expect(x).toBe(1));", + "}", + ].join("\n"); + + assert.deepEqual(findBareRealProcessWaits(source), [ + { line: 2, pattern: "vi.waitFor(" }, + ]); +}); + +test("allows a vi.waitFor( marked as settling fully in-process", () => { + const source = [ + "async function example() {", + " // bare-wait-ok: settles fully in-process, no spawned OS process.", + " await vi.waitFor(() => expect(x).toBe(1));", + "}", + ].join("\n"); + + assert.deepEqual(findBareRealProcessWaits(source), []); +}); + +test("allows the named real-process wait helper instead of vi.waitFor", () => { + const source = [ + "async function example() {", + ' await waitForCapabilityLiveProcess("label", () => expect(x).toBe(1));', + "}", + ].join("\n"); + + assert.deepEqual(findBareRealProcessWaits(source), []); +}); + +test("flags every unmarked vi.waitFor( in a file with a mix of marked and unmarked calls", () => { + const source = [ + "async function example() {", + " await vi.waitFor(() => expect(a).toBe(1));", + " // bare-wait-ok: settles fully in-process, no spawned OS process.", + " await vi.waitFor(() => expect(b).toBe(2));", + " await vi.waitFor(() => expect(c).toBe(3));", + "}", + ].join("\n"); + + assert.deepEqual(findBareRealProcessWaits(source), [ + { line: 2, pattern: "vi.waitFor(" }, + { line: 5, pattern: "vi.waitFor(" }, + ]); +}); + +test("rejects a bare expect.poll( with no in-process marker on the line above", () => { + const source = [ + "async function example() {", + " await expect", + " .poll(async () => readFile(path, 'utf8'))", + " .toBe('done');", + "}", + ].join("\n"); + + assert.deepEqual(findBareRealProcessWaits(source), [ + { line: 2, pattern: "expect.poll(" }, + ]); +}); + +test("allows an expect.poll( marked as settling fully in-process", () => { + const source = [ + "async function example() {", + " // bare-wait-ok: settles fully in-process, no spawned OS process.", + " await expect", + " .poll(async () => readFile(path, 'utf8'))", + " .toBe('done');", + "}", + ].join("\n"); + + assert.deepEqual(findBareRealProcessWaits(source), []); +}); + +test("allows an expect.poll( that passes an explicit timeout option", () => { + const source = [ + "async function example() {", + " await expect", + " .poll(async () => readFile(path, 'utf8'), { timeout: 10_000 })", + " .toBe('done');", + "}", + ].join("\n"); + + assert.deepEqual(findBareRealProcessWaits(source), []); +}); diff --git a/packages/paperclip-runner/scripts/lib/bare-real-process-wait.mjs b/packages/paperclip-runner/scripts/lib/bare-real-process-wait.mjs new file mode 100644 index 00000000000..ba684754fdc --- /dev/null +++ b/packages/paperclip-runner/scripts/lib/bare-real-process-wait.mjs @@ -0,0 +1,137 @@ +import { readdir, readFile } from "node:fs/promises"; +import { relative, resolve } from "node:path"; +import { fileURLToPath } from "node:url"; + +const libraryDirectory = fileURLToPath(new URL(".", import.meta.url)); +export const defaultPackageRoot = resolve(libraryDirectory, "../.."); + +const SCANNED_EXTENSIONS = new Set([".ts", ".tsx"]); + +// A wait against a spawned operating-system process can run far longer than +// vitest's default `vi.waitFor` or `expect.poll` deadline (see the helper +// and its evidence comment in test/wait-for-live-process.ts). A wait that +// settles fully in-process never needs that deadline, so this check does +// not force every wait onto the real-process helper — it only requires that +// a bare call in this directory carries an explicit note that the wait +// settles in-process, or an explicit `timeout` option that states its own +// envelope. +const IN_PROCESS_WAIT_MARKER = "bare-wait-ok:"; + +// `expect.poll(` can span two lines as `expect\n .poll(`, so each pattern +// allows whitespace (including a newline) around the dot. +const BARE_WAIT_PATTERNS = [ + { name: "vi.waitFor(", regex: /\bvi\s*\.\s*waitFor\(/g }, + { name: "expect.poll(", regex: /\bexpect\s*\.\s*poll\(/g }, +]; + +const EXPLICIT_TIMEOUT_PATTERN = /\btimeout\s*:/; + +function extension(path) { + const match = path.match(/\.[^./\\]+$/); + return match?.[0] ?? ""; +} + +async function collectSourceFiles(target) { + const entries = await readdir(target, { withFileTypes: true }); + const files = []; + for (const entry of entries) { + if (["dist", "node_modules", ".git"].includes(entry.name)) { + continue; + } + const path = resolve(target, entry.name); + if (entry.isDirectory()) { + files.push(...(await collectSourceFiles(path))); + } else if (entry.isFile() && SCANNED_EXTENSIONS.has(extension(entry.name))) { + files.push(path); + } + } + return files; +} + +// Find the index of the close paren that matches the open paren at +// `openParenIndex`, tracking nested `()`, `{}`, and `[]`, and skipping over +// string and template literals so a brace or paren inside one never throws +// off the count. +function findMatchingCloseParenIndex(source, openParenIndex) { + let depth = 0; + for (let index = openParenIndex; index < source.length; index += 1) { + const character = source[index]; + if (character === "(" || character === "{" || character === "[") { + depth += 1; + } else if (character === ")" || character === "}" || character === "]") { + depth -= 1; + if (depth === 0) return index; + } else if (character === "'" || character === '"' || character === "`") { + const quote = character; + index += 1; + while (index < source.length && source[index] !== quote) { + if (source[index] === "\\") index += 1; + index += 1; + } + } + } + return source.length; +} + +/** + * Find each real-process-shaped wait call (`vi.waitFor(`, or `expect.poll(`, + * including the two-line `expect\n .poll(` form) in `source` that has + * neither an `IN_PROCESS_WAIT_MARKER` note on the line directly above it + * nor an explicit `timeout` option in its own argument list. A call site + * with the marker declares, in place, that it settles fully in-process. A + * call site with an explicit `timeout` option already states its own + * envelope. Either one needs no real-process deadline. + */ +export function findBareRealProcessWaits(source) { + const lines = source.split("\n"); + const found = []; + for (const { name, regex } of BARE_WAIT_PATTERNS) { + regex.lastIndex = 0; + for ( + let match = regex.exec(source); + match !== null; + match = regex.exec(source) + ) { + const line = source.slice(0, match.index).split("\n").length; + const precedingLine = lines[line - 2] ?? ""; + if (precedingLine.includes(IN_PROCESS_WAIT_MARKER)) { + continue; + } + const openParenIndex = match.index + match[0].length - 1; + const closeParenIndex = findMatchingCloseParenIndex(source, openParenIndex); + const callArguments = source.slice(openParenIndex + 1, closeParenIndex); + if (EXPLICIT_TIMEOUT_PATTERN.test(callArguments)) { + continue; + } + found.push({ line, pattern: name }); + } + } + found.sort((a, b) => a.line - b.line); + return found; +} + +export async function checkBareRealProcessWaits({ + packageRoot = defaultPackageRoot, + scanRoot = "src/live", +} = {}) { + const root = resolve(packageRoot, scanRoot); + const files = (await collectSourceFiles(root)).sort(); + const violations = []; + for (const file of files) { + const source = await readFile(file, "utf8"); + for (const { line, pattern } of findBareRealProcessWaits(source)) { + violations.push({ file, line, pattern }); + } + } + return violations; +} + +export function formatBareRealProcessWaitViolation(violation, packageRoot = defaultPackageRoot) { + return ( + `${relative(packageRoot, violation.file)}:${violation.line} calls a bare ${violation.pattern}: ` + + "use waitForCapabilityLiveProcess (test/wait-for-live-process.ts) for a wait bound to a real " + + "spawned process, mark a wait that settles fully in-process with a comment containing " + + `"${IN_PROCESS_WAIT_MARKER}" on the line above the call, or pass an explicit timeout option ` + + "that states the wait's own envelope" + ); +} diff --git a/packages/paperclip-runner/src/live/live-session.test.ts b/packages/paperclip-runner/src/live/live-session.test.ts index 9ed9cbaf049..c0d7bf2e67f 100644 --- a/packages/paperclip-runner/src/live/live-session.test.ts +++ b/packages/paperclip-runner/src/live/live-session.test.ts @@ -24,6 +24,7 @@ import { import { DurableCapabilityLiveSessionStore } from "./durable-live-session-store.js"; import { defaultCapabilityRunnerdBinary } from "./runnerd-codex-transport.js"; import { captureTurnRejection } from "../../test/capture-turn-rejection.js"; +import { waitForCapabilityLiveProcess } from "../../test/wait-for-live-process.js"; class AsyncNotifications implements AsyncIterable { #values: CodexRpcNotification[] = []; @@ -420,6 +421,7 @@ describe("Capability live runnerd and Codex session", () => { "transient terminal-notification store failure", ); + // bare-wait-ok: settles fully in-process, no spawned OS process. await vi.waitFor(async () => { expect((await store.load(session.id))?.status).toBe("failed"); }); @@ -448,6 +450,7 @@ describe("Capability live runnerd and Codex session", () => { await expect(session.sendMessage("finish after consecutive store failures")).rejects.toThrow( "transient terminal-notification store failure", ); + // bare-wait-ok: settles fully in-process, no spawned OS process. await vi.waitFor(async () => { expect(session.snapshot().status).toBe("failed"); expect(store.terminalSaveFailureCount()).toBeGreaterThanOrEqual(2); @@ -484,6 +487,7 @@ describe("Capability live runnerd and Codex session", () => { await expect(session.sendMessage("fail before shutdown cleanup")).rejects.toThrow( "transient terminal-notification store failure", ); + // bare-wait-ok: settles fully in-process, no spawned OS process. await vi.waitFor(() => expect(session.snapshot().status).toBe("failed")); const cleanupFailure = new Error("provider cleanup failed"); state.closeError = cleanupFailure; @@ -571,10 +575,12 @@ describe("Capability live runnerd and Codex session", () => { await session.sendMessage("warm response"); expect(session.snapshot().status).toBe("warm_idle"); expect(state.transports[0]?.processInfo().exited).toBe(false); + // bare-wait-ok: settles fully in-process, no spawned OS process. await vi.waitFor(() => expect(session.snapshot().status).toBe("suspended"), { timeout: 500 }); expect(state.transports[0]?.processInfo().exited).toBe(true); const active = session.sendMessage("start a long turn"); + // bare-wait-ok: settles fully in-process, no spawned OS process. await vi.waitFor(() => expect(session.snapshot().activeTurnId).not.toBeNull()); expect(session.snapshot().status).toBe("running"); await session.interrupt("test cleanup"); @@ -614,6 +620,7 @@ describe("Capability live runnerd and Codex session", () => { const abandonedTurn = session.sendMessage("start a provider request that never returns"); void abandonedTurn.catch(() => undefined); + // bare-wait-ok: settles fully in-process, no spawned OS process. await vi.waitFor(() => { expect(state.transports[0]?.requests.some((request) => request.method === "turn/start")) .toBe(true); @@ -1049,6 +1056,7 @@ describe("Capability live runnerd and Codex session", () => { requestedModel: "openrouter/deepseek/deepseek-v4-flash-0731", }); const longTurn = session.sendMessage("Start a long turn."); + // bare-wait-ok: settles fully in-process, no spawned OS process. await vi.waitFor(() => expect(session.snapshot().activeTurnId).not.toBeNull()); await session.interrupt("bounded test interrupt"); await expect(longTurn).resolves.toMatchObject({ status: "interrupted" }); @@ -1095,6 +1103,7 @@ describe("Capability live runnerd and Codex session", () => { }); state.holdAfterTool = true; const killedTurn = captureTurnRejection(first.sendMessage("Apply idempotent progress once.")); + // bare-wait-ok: settles fully in-process, no spawned OS process. await vi.waitFor(async () => { expect((await firstStore.load(binding.sessionId))?.mockState).toContain( "Progress persisted through the live Codex tool loop.", @@ -1232,6 +1241,7 @@ describe("Capability live runnerd and Codex session", () => { }); state.holdAfterTool = true; const killedTurn = captureTurnRejection(first.sendMessage("Apply idempotent progress once.")); + // bare-wait-ok: settles fully in-process, no spawned OS process. await vi.waitFor(async () => { expect((await store.load(first.id))?.mockState).toContain("progress-governed-once"); }); @@ -1428,13 +1438,16 @@ describe("Capability live runnerd and Codex session", () => { turnTimeoutMs: 2_000, }); const killedTurn = captureTurnRejection(first.sendMessage("Apply the governed idempotent effect.")); - await vi.waitFor(async () => { - const checkpoint = await store.load(binding.sessionId); - expect(checkpoint?.mockState).toContain("One durable governed effect."); - expect(checkpoint?.activeTurnId).toBe("turn-1"); - expect(checkpoint?.process?.runnerPid).not.toBeNull(); - expect(checkpoint?.process?.codexPid).not.toBeNull(); - }); + await waitForCapabilityLiveProcess( + "durable checkpoint reflects the applied governed effect", + async () => { + const checkpoint = await store.load(binding.sessionId); + expect(checkpoint?.mockState).toContain("One durable governed effect."); + expect(checkpoint?.activeTurnId).toBe("turn-1"); + expect(checkpoint?.process?.runnerPid).not.toBeNull(); + expect(checkpoint?.process?.codexPid).not.toBeNull(); + }, + ); await first.recordUsage({ receiptId: "real-response-1", providerResponseId: "fixture-response-1", diff --git a/packages/paperclip-runner/src/live/runnerd-codex-transport.test.ts b/packages/paperclip-runner/src/live/runnerd-codex-transport.test.ts index ca5bc841d95..e442b08c284 100644 --- a/packages/paperclip-runner/src/live/runnerd-codex-transport.test.ts +++ b/packages/paperclip-runner/src/live/runnerd-codex-transport.test.ts @@ -31,6 +31,7 @@ import { codexSemanticToolSpecs, } from "../drivers/codex/codex-app-server-driver.js"; import { releaseMaterializedNativeRuntimeSkills } from "../drivers/runtime-context-materializer.js"; +import { waitForCapabilityLiveProcess } from "../../test/wait-for-live-process.js"; import { createCapabilityRunnerdCodexTransport, @@ -1209,20 +1210,22 @@ it("captures exact provider frames and correlates Rust and TypeScript interpreta canonicalEventIds.add(`runner-codex:run-provider-trace:${sourceSeq}`); } - await expect - .poll(async () => { + await waitForCapabilityLiveProcess( + "native and rehydration trace files reach a terminal status", + async () => { const [nativeTrace, rehydrationTrace] = await Promise.all([ readFile(tracePath, "utf8"), readFile(`${tracePath}.rehydration`, "utf8"), ]); - return [nativeTrace, rehydrationTrace].map((contents) => + const parsed = [nativeTrace, rehydrationTrace].map((contents) => JSON.parse(contents.trim().split("\n").at(-1) ?? "{}"), ); - }) - .toEqual([ - expect.objectContaining({ status: "complete" }), - expect.objectContaining({ status: "complete" }), - ]); + expect(parsed).toEqual([ + expect.objectContaining({ status: "complete" }), + expect.objectContaining({ status: "complete" }), + ]); + }, + ); const nativeEntries = (await readFile(tracePath, "utf8")) .trim() diff --git a/packages/paperclip-runner/test/wait-for-live-process.ts b/packages/paperclip-runner/test/wait-for-live-process.ts new file mode 100644 index 00000000000..b57e1f1c943 --- /dev/null +++ b/packages/paperclip-runner/test/wait-for-live-process.ts @@ -0,0 +1,68 @@ +// A wait against a real spawned OS process can run behind a far larger +// envelope than an in-process fake transport. Two waits in `src/live/**` +// use this helper and its deadline. +// +// The first wait (live-session.test.ts:1414, its wait at :1441) spawns the +// real `paperclip-runnerd` binary and a real Node child process for +// `test/fixtures/fake-durable-codex-app-server.mjs`, completes a transport +// handshake, runs one full turn that applies a governed effect, and writes +// and hashes a durable checkpoint to a temporary directory — all before the +// checkpoint first contains the applied effect. The enclosing test budgets +// 30 seconds for this (live-session.test.ts:1501-1502: "CI exercises two +// real process generations here and can exceed the unit default under +// load"). 20 uncontended samples of this path ranged from 163ms to 187ms +// (median 173ms). A deterministic 1,200ms SIGSTOP/SIGCONT stall of the real +// runnerd process reproduces a failure against vitest's default 1,000ms +// deadline and passes cleanly against the 10,000ms deadline below. +// +// The second wait (runnerd-codex-transport.test.ts:1155, its wait at :1213) +// spawns the same real `paperclip-runnerd` binary and a real +// `fake-codex-app-server` process, runs one full turn, and waits for the +// runnerd process to write two provider trace files to a terminal status. +// 12 uncontended samples of the time from the start of the turn to both +// trace files first holding `status: "complete"` ranged from 534ms to +// 640ms (median 574.5ms). +// +// The deadline below is over 15 times the larger of the two observed +// maximums (640ms), for machine load worse than either local reproduction +// and for this helper's own 50ms poll granularity. +export const CAPABILITY_LIVE_PROCESS_WAIT_DEADLINE_MS = 10_000; + +/** + * Poll a capability-live operation that settles only after a real spawned + * operating-system process does work. Use a deadline derived from the real + * process envelope described above. Unlike a bare `vi.waitFor` or + * `expect.poll`, report the last observed error when the deadline expires, + * together with `label` and the elapsed time, so a failure names what the + * wait was waiting for and how long it waited. + */ +export async function waitForCapabilityLiveProcess( + label: string, + callback: () => T | Promise, +): Promise { + const start = Date.now(); + const deadline = start + CAPABILITY_LIVE_PROCESS_WAIT_DEADLINE_MS; + let lastError: unknown = new Error( + `no attempt of "${label}" settled before the deadline`, + ); + for (;;) { + try { + return await callback(); + } catch (error) { + lastError = error; + } + const elapsedMs = Date.now() - start; + if (Date.now() >= deadline) { + const detail = + lastError instanceof Error + ? (lastError.stack ?? lastError.message) + : String(lastError); + throw new Error( + `Wait for "${label}" did not settle within ${CAPABILITY_LIVE_PROCESS_WAIT_DEADLINE_MS}ms ` + + `(observed ${elapsedMs}ms). Last observed error: ${detail}`, + { cause: lastError }, + ); + } + await new Promise((resolve) => setTimeout(resolve, 50)); + } +}