From 140dbc8bf0e3c1d0648f985a76803d256e4f899a Mon Sep 17 00:00:00 2001 From: Priya Raman Date: Fri, 4 Sep 2026 00:06:49 +0000 Subject: [PATCH] test(runner): close the real-process wait gap in the second live test file The Rust and TypeScript interpretation test in runnerd-codex-transport.test.ts spawned the real paperclip-runnerd binary and a real fake-codex-app-server process, ran one turn, and polled two provider trace files for a terminal status with vitest's default 1,000ms expect.poll deadline. Measurement showed the real envelope for this path (534ms to 640ms across 12 uncontended samples) sits inside that default, so the poll could time out under load even though the trace files would still arrive. Move the real-process wait helper out of live-session.test.ts into a shared test/ module and export it, so both real-process test files import the same helper and deadline instead of one file re-declaring a marker meant only for waits that settle in-process. Replace the bare expect.poll with the shared helper, keeping the same toEqual/objectContaining assertion. Extend the bare-real-process-wait check script to also reject a bare expect.poll( in src/live/**, on the same terms as vi.waitFor(: accept the in-process marker or an explicit timeout option that already states its own envelope. Rewrite the deadline's evidence comment with the reliable, uncontended measurements for both real-process waits it now covers (163ms-187ms and 534ms-640ms) and correct file:line anchors, and state the actual margin the deadline keeps (over 15 times the larger observed maximum) instead of an inflated one. Co-authored-by: Paperclip --- packages/paperclip-runner/package.json | 3 +- .../scripts/check-bare-real-process-waits.mjs | 16 ++ .../check-bare-real-process-waits.test.mjs | 92 ++++++++++++ .../scripts/lib/bare-real-process-wait.mjs | 137 ++++++++++++++++++ .../src/live/live-session.test.ts | 27 +++- .../src/live/runnerd-codex-transport.test.ts | 19 ++- .../test/wait-for-live-process.ts | 68 +++++++++ 7 files changed, 346 insertions(+), 16 deletions(-) create mode 100644 packages/paperclip-runner/scripts/check-bare-real-process-waits.mjs create mode 100644 packages/paperclip-runner/scripts/check-bare-real-process-waits.test.mjs create mode 100644 packages/paperclip-runner/scripts/lib/bare-real-process-wait.mjs create mode 100644 packages/paperclip-runner/test/wait-for-live-process.ts 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)); + } +}