From fd9985b5713605ce5eff3c458620490f7bb5dfcb Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Thu, 12 Nov 2026 03:00:32 -0600 Subject: [PATCH] fix(native): say what a Runner command waited behind when it times out (#21056) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - Native runs on remote sandboxes talk to a Runner through durable PRP commands. The controller waits for each command's result > - After a server replacement, the new controller reattached to live Runners. For runs it reached later than about 115 s after detach, `session.snapshot` got no answer within 30 s > - The failure said only `provider_transport_failed: PRP command session.snapshot timed out`. The run log could not tell whether the Runner was disconnected, whether the command waited behind older commands, or when the Runner last sent an event > - This pull request adds that evidence to the timeout message. It names types, counts and durations only, never payloads > - The benefit is that the next upgrade's failures explain the stall, so the runner-side cause can be fixed ## Linked Issues or Issue Description Refs #21053, #21052, #21039 **What happened?** At the 07:10Z staging swap, 9 remote native runs that the new controller reached 114–152 s after detach failed. Each recovery read ended with `PRP command session.snapshot timed out`. The transport had authenticated, and in some runs the same Runner process was verified. The Runner journal recorded no diagnostic other than "WebSocket peer closed the connection". Runs reached within 39–116 s succeeded. **What did you expect to happen?** A command timeout should say what the command waited behind, so the cause can be found from the run log. **Steps to reproduce** 1. Start a remote native run and replace the server while a provider turn is active. 2. Let the new controller reach the Runner more than about two minutes after detach. 3. Read the run log. The failure says only "timed out". ## What Changed - `packages/paperclip-runner/src/live/runnerd-codex-transport.ts`: `waitForRunnerCommand` accepts an optional `describeStall`. When a command times out, the message ends with a bounded description, for example `(runner connected; pending ahead 1 [semantic_tool.result] oldest 188s; last runner event seq 152 181s ago)`. The description covers whether a Runner is connected or how long it has been disconnected, the pending commands ahead of this one (types and count, up to 6 types, and the age of the oldest), and the last committed Runner event's sequence and age. A failing or empty description keeps the plain message. - The transport passes this description for every command it waits on. The last event's age comes from the PRP payload's `emittedAt`. - `server/src/services/native-runtime/native-session-executor.ts`: the startup `session.open` timeout classifier accepts the optional description, so a startup timeout stays `provider_session_open_timeout` and keeps its bounded same-run retry. A regression case covers each startup code with the suffix. - Tests: the exact message for the staging shape, the plain message when there is nothing to describe or the description throws, and a disconnected Runner with no events. ## Verification - `cd packages/paperclip-runner && npx vitest run src/live/runnerd-codex-transport.test.ts -t "a Runner command that gets no answer"` passes 3 of 3. These tests fail on `origin/master`, which has no `describeRunnerCommandStall` export and no description in the message. - The full `runnerd-codex-transport.test.ts` file passes 307 of 308. The one failure (`stops a lost runnerd's provider and escaped tool job from its lineage journal`) is a process-timing test that passes alone and does not touch this code. - `npx tsc --noEmit -p packages/paperclip-runner/tsconfig.json` passes. - Message matchers: the only matcher anchored on the end of the timeout text was the startup `session.open` classifier. It now accepts the suffix. `cd server && npx vitest run src/services/native-runtime/native-session-executor.test.ts -t "classifies a startup session.open timeout"` passes. Without the classifier change it fails, because the suffix turns the timeout into `native_session_interrupted`. ## Risks - Low. Only the text of a timeout message changes, by appending text. No control flow, persisted state or Runner behavior changes. - The description holds command types, counts and durations only. It holds no payloads, identifiers or provider text. - No wait is added before a turn start. > For core feature work, check [`ROADMAP.md`](ROADMAP.md) first and discuss it in `#dev` before opening the PR. Feature PRs that overlap with planned core work may need to be redirected — check the roadmap first. See `CONTRIBUTING.md`. ## Model Used - Claude (Anthropic) via Claude Code, with tool use (shell, file edits, test runs, read-only staging API reads). Model ID as attributed in the commit trailer: Claude Fable 5.2. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [ ] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [ ] All Paperclip CI gates are green - [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Fable 5.2 --- .../src/live/runnerd-codex-transport.test.ts | 44 ++++++++++++++++- .../src/live/runnerd-codex-transport.ts | 49 ++++++++++++++++++- .../native-session-executor.test.ts | 3 ++ .../native-runtime/native-session-executor.ts | 2 +- 4 files changed, 95 insertions(+), 3 deletions(-) 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