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 4141ad151d2..cce59af2f7f 100644 --- a/packages/paperclip-runner/src/live/runnerd-codex-transport.test.ts +++ b/packages/paperclip-runner/src/live/runnerd-codex-transport.test.ts @@ -4,7 +4,7 @@ import { runnerLaunchRequirementsDigest, type RunnerProviderLaunchRequirements, } from "./runner-provider-launch.js"; -import { coldAdmissionTimeoutMs, RUNNER_MAX_STOPPED_CREDIT_MS, RUNNER_POST_STOP_GRACE_MS, RunnerStallLedger, waitForRunnerCommand } from "./runnerd-codex-transport.js"; +import { coldAdmissionTimeoutMs, describeRunnerCommandStall, RUNNER_MAX_STOPPED_CREDIT_MS, RUNNER_POST_STOP_GRACE_MS, RunnerStallLedger, waitForRunnerCommand } from "./runnerd-codex-transport.js"; import { configuredEnvironmentProjection } from "../configured-environment.js"; import { chmod, cp, mkdir, mkdtemp, readFile, readdir, realpath, rename, rm, stat, truncate, writeFile } from "node:fs/promises"; import { createHash } from "node:crypto"; @@ -6999,3 +6999,45 @@ it("launches and closes native Codex without materializing or editing the precon await rm(root, { force: true, recursive: true }); } }, 30_000); + +// Staging: after a server replacement the new controller's session.snapshot +// got no answer and the failure said only "timed out". The timeout now names +// what the command waited behind, so the next occurrence explains the stall. +describe("a Runner command that gets no answer", () => { + const now = Date.parse("2026-11-12T07:13:28.000Z"); + const command = (seq: number, type: string, status: string, issuedAt: string) => + ({ commandId: `command-${seq}`, controllerSeq: seq, type, status, issuedAt }); + + it("says what it waited behind in the timeout", async () => { + let failure: unknown; + try { + await waitForRunnerCommand({ type: "session.snapshot", deadline: Date.now() + 20, abortOnClose: false, + isClosed: () => false, throwIfFailed: () => {}, command: () => ({ status: "pending" }), + runnerHasExited: async () => false, failureCode: () => "provider_transport_failed", + describeStall: () => describeRunnerCommandStall({ now, connectedRunners: 1, disconnectedForMs: null, + commandId: "command-9", + commands: [command(7, "semantic_tool.result", "pending", "2026-11-12T07:10:20.000Z"), + command(8, "turn.steer", "completed", "2026-11-12T07:10:21.000Z"), + command(9, "session.snapshot", "pending", "2026-11-12T07:12:58.000Z")], + committedEvents: [{ sourceSeq: 152, envelope: { runId: "run-1", payload: { eventType: "item.completed", emittedAt: "2026-11-12T07:10:27.000Z" } } }] }) }); + } catch (error) { failure = error; } + expect((failure as Error).message).toBe("provider_transport_failed: PRP command session.snapshot timed out " + + "(runner connected; pending ahead 1 [semantic_tool.result] oldest 188s; last runner event seq 152 181s ago)"); + }); + + it("keeps the plain timeout when there is nothing to describe or the description fails", async () => { + for (const describeStall of [undefined, () => null, () => { throw new Error("state unavailable"); }]) { + const failure = await waitForRunnerCommand({ type: "session.snapshot", deadline: Date.now() + 10, abortOnClose: false, + isClosed: () => false, throwIfFailed: () => {}, command: () => ({ status: "pending" }), + runnerHasExited: async () => false, failureCode: () => "provider_transport_failed", describeStall }) + .catch((error: unknown) => error); + expect((failure as Error).message).toBe("provider_transport_failed: PRP command session.snapshot timed out"); + } + }); + + it("reports a disconnected Runner and no events", () => { + expect(describeRunnerCommandStall({ now, connectedRunners: 0, disconnectedForMs: 125_400, commandId: "command-1", + commands: [command(1, "session.snapshot", "pending", "2026-11-12T07:13:00.000Z")], committedEvents: [] })) + .toBe("runner disconnected 125s; pending ahead 0; last runner event none"); + }); +}); diff --git a/packages/paperclip-runner/src/live/runnerd-codex-transport.ts b/packages/paperclip-runner/src/live/runnerd-codex-transport.ts index e855cd3e0ef..39cbf01287a 100644 --- a/packages/paperclip-runner/src/live/runnerd-codex-transport.ts +++ b/packages/paperclip-runner/src/live/runnerd-codex-transport.ts @@ -7951,6 +7951,14 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { : this.#core?.getCommand(commandId), runnerHasExited: () => this.#runnerHasExited(), failureCode: () => this.#startupComplete ? "provider_transport_failed" : this.#startupFailureCode, + describeStall: () => this.#core === null ? null : describeRunnerCommandStall({ + commands: this.#core.store.state.commands, + commandId: commandId ?? this.#core.store.state.commands.find(candidate => candidate.type === type)?.commandId, + connectedRunners: this.#core.activeRunnerConnectionCount(), + disconnectedForMs: this.#core.runnerDisconnectedForMs(), + committedEvents: this.#core.store.state.committedEvents, + now: Date.now(), + }), }); } @@ -9594,6 +9602,8 @@ export async function waitForRunnerCommand(input: { command: () => { status: string; result?: unknown } | undefined; runnerHasExited: () => Promise; failureCode: () => string; + /** Bounded, content-free evidence of what the command waited behind. */ + describeStall?: () => string | null; }): Promise { const now = () => input.clock ? input.clock.now() : Date.now(); while (now() < input.deadline) { @@ -9618,5 +9628,42 @@ export async function waitForRunnerCommand(input: { } await new Promise((resolveWait) => setTimeout(resolveWait, 10)); } - throw new Error(`${input.failureCode()}: PRP command ${input.type} timed out`); + let stall: string | null = null; + try { stall = input.describeStall?.() ?? null; } catch { stall = null; } + throw new Error(`${input.failureCode()}: PRP command ${input.type} timed out${stall ? ` (${stall})` : ""}`); +} + +/** + * What a command that got no answer was waiting behind: whether a Runner was + * connected, the older commands still pending ahead of it (types only), and + * how long ago the last Runner event arrived. Types, counts and durations + * only, never payloads, so it is safe in run logs. + */ +export function describeRunnerCommandStall(input: { + commands: ReadonlyArray<{ commandId: string; controllerSeq: number; type: string; status: string; issuedAt: string }>; + commandId: string | undefined; + connectedRunners: number; + disconnectedForMs: number | null; + committedEvents: ReadonlyArray<{ sourceSeq: number; envelope?: Record }>; + now: number; +}): string { + const target = input.commands.find(command => command.commandId === input.commandId); + const ahead = target === undefined ? [] : input.commands.filter(command => + command.status === "pending" && command.controllerSeq < target.controllerSeq); + const types = [...new Set(ahead.map(command => command.type))].slice(0, 6); + const oldestAhead = ahead.reduce((oldest, command) => { + const issued = Date.parse(command.issuedAt); + return Number.isFinite(issued) && (oldest === null || issued < oldest) ? issued : oldest; + }, null); + const last = input.committedEvents.at(-1); + // A committed event keeps the Runner's emission time inside its PRP payload. + const emittedAt = (last?.envelope?.payload as Record | undefined)?.emittedAt + ?? last?.envelope?.emittedAt; + const lastEmitted = typeof emittedAt === "string" ? Date.parse(emittedAt) : NaN; + const seconds = (ms: number) => `${Math.max(0, Math.round(ms / 1000))}s`; + return [ + `runner ${input.connectedRunners > 0 ? "connected" : input.disconnectedForMs === null ? "never connected" : `disconnected ${seconds(input.disconnectedForMs)}`}`, + `pending ahead ${ahead.length}${types.length ? ` [${types.join(",")}]` : ""}${oldestAhead === null ? "" : ` oldest ${seconds(input.now - oldestAhead)}`}`, + `last runner event ${last === undefined ? "none" : `seq ${last.sourceSeq}${Number.isFinite(lastEmitted) ? ` ${seconds(input.now - lastEmitted)} ago` : ""}`}`, + ].join("; "); } diff --git a/server/src/services/native-runtime/native-session-executor.test.ts b/server/src/services/native-runtime/native-session-executor.test.ts index fe2a000a75f..81a80f99f1d 100644 --- a/server/src/services/native-runtime/native-session-executor.test.ts +++ b/server/src/services/native-runtime/native-session-executor.test.ts @@ -22016,6 +22016,9 @@ it("classifies a startup session.open timeout as a bounded transient startup fai for (const startupCode of ["runner_local_connect_failed", "runner_direct_wss_failed", "runner_ingress_unavailable"]) { const code = nativeSessionFailureSourceCode(new Error(`${startupCode}: PRP command session.open timed out`)); expect(code).toBe("provider_session_open_timeout"); + // The timeout can end with the description of what the command waited behind. + expect(nativeSessionFailureSourceCode(new Error(`${startupCode}: PRP command session.open timed out ` + + "(runner connected; pending ahead 0; last runner event none)"))).toBe("provider_session_open_timeout"); expect(nativeSessionFailureDisposition(1, new Date(), code)).toMatchObject({ phase: "retryable_failure" }); expect(nativeSessionFailureDisposition(3, new Date(), code)).toMatchObject({ phase: "terminal_failure", failureCode: "native_session_retry_exhausted", nextAttemptAt: null, diff --git a/server/src/services/native-runtime/native-session-executor.ts b/server/src/services/native-runtime/native-session-executor.ts index 00c2035846d..0cd6a81a2db 100644 --- a/server/src/services/native-runtime/native-session-executor.ts +++ b/server/src/services/native-runtime/native-session-executor.ts @@ -8995,7 +8995,7 @@ export function nativeSessionFailureSourceCode( // before startup completes, and session.open precedes every prompt. The // outcome is unknown, so durable evidence (no provider event, no checkpoint) // still decides whether a same-run bootstrap retry is safe. - if (/^(?:runner_local_connect_failed|runner_direct_wss_failed|runner_ingress_unavailable): PRP command session\.open timed out$/.test(message)) { + if (/^(?:runner_local_connect_failed|runner_direct_wss_failed|runner_ingress_unavailable): PRP command session\.open timed out(?: \([^()]*\))?$/.test(message)) { return "provider_session_open_timeout"; } // This process has no HTTP listener (graceful shutdown closes it first), so