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 <noreply@paperclip.ing>
This commit is contained in:
Priya RamanandPaperclip committed 2026-09-04 00:43:13 +00:00
1 parent a661caf74e
commit 140dbc8bf0
7 files changed
+346 -16

No files matched your search

+2 -1
View File
@@ -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",
@@ -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");
}
@@ -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), []);
});
@@ -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"
);
}
@@ -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<CodexRpcNotification> {
#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",
@@ -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()
@@ -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<T>(
label: string,
callback: () => T | Promise<T>,
): Promise<T> {
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));
}
}