From 6d1eae73c0fd8f42884e7910b4a835d3215c8f31 Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Tue, 10 Nov 2026 22:16:27 -0600 Subject: [PATCH] fix(runner): do not count time the control plane was stopped against a Runner command wait (#20704) 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 > - The native runtime resumes a run after a control-plane restart. It launches a Runner and waits for recovery barriers (`run.attach`, a `runner.drain` probe, the provider identity). > - These waits poll with a wall-clock deadline. When the control plane and its Runner are stopped together (SIGSTOP, host sleep), the wall clock passes the deadline before either process can act. > - On thaw, the wait reports a timeout although nothing was slow. Recovery then spends an attempt and a retry delay. > - This pull request gives each startup or recovery admission a clock that does not count stopped time. > - The benefit is that a freeze or host sleep during an admission no longer turns into a false `PRP command ... timed out` failure. ## Linked Issues or Issue Description **What happened?** A restart-chaos wave (local, codex, fault TM2) stopped the server and its Runner tree for 44 s, 1 s after a resumed Runner started. The resume barrier `runner.drain` had a 30 s deadline. On thaw, the server reported `runner_local_connect_failed: PRP command runner.drain timed out` 45 s after the wait began (`provider.session.load` span 45130 ms). Recovery spent attempt 1 and waited 30 s more before attempt 2. **Expected behavior** Time that the waiting process spends stopped does not count as waiting time. A real timeout still fires when the Runner does not answer while both processes run. **Steps to reproduce** 1. Start a Runner command wait with a 30 s deadline. 2. After 1 s, stop the process for 44 s (the test moves the system clock without running timers). 3. Let the Runner complete the command 2 s after thaw. 4. Before this change, the wait rejects with `runner.drain timed out`. After this change, it resolves. Note: in that chaos task, this false timeout was not the reason that the task needed a manual Retry. An earlier SIGKILL of the whole server tree stopped the Codex turn while a foreground shell command (`./bench.sh`) was running. On restore, Codex had no active turn (`provider_turn_lost_on_restore`). Recovery correctly blocked automatic replay (`uncertain_provider_action`), because no durable record proves that the interrupted command had no side effect. The manual Retry then completed the task. This PR does not change that policy. Refs #20675 ## What Changed - `packages/paperclip-runner/src/live/runnerd-codex-transport.ts`: add `RunnerStallLedger`, the clock of one startup or recovery admission. `now()` is wall time minus the stopped time observed since the admission began. Its poll loops and a 1 s ticker share one last-observation time, so each stop is credited once, wherever the process was when it stopped (a poll loop, a checkpoint flush, a spawn). Only the part of a gap beyond 5 s is credited. - `#start` and `#resume` run under one ledger (`#withAdmissionClock`). A nested startup keeps the outer ledger. The ticker stops when the admission ends. - During an admission, `waitForRunnerCommand`, the provider-identity wait, the cold admission deadline, the recovery admission deadline, and the default 30 s command deadline all use this clock. - Waits after admission, including `turn.start` and its event and snapshot waits, keep wall-clock deadlines. Their behavior does not change. - Tests in `runnerd-codex-transport.test.ts`: the chaos sequence (red before, green after), the unchanged wall-clock timeout outside an admission, a barrier that still times out after a freeze, a 70 s freeze between two barriers on one cold deadline, and a slow-but-running process that still reaches its deadline. ## Verification - Red: `cd packages/paperclip-runner && npx vitest run src/live/runnerd-codex-transport.test.ts -t "stopped"` failed before the fix with `runner_local_connect_failed: PRP command runner.drain timed out`. - Green: the same command passes after the fix. - `npx vitest run src/live/runnerd-codex-transport.test.ts`: 301/301 pass, including the existing "shares Pi's absolute cold deadline across recovery barriers and rejects a late ACK" test. - `npx tsc --noEmit -p packages/paperclip-runner/tsconfig.json`: clean. - `pnpm verify` exits 2 (changes outside resolved test graphs). Required CI supplies the broad coverage. - Not run: a new chaos wave. The unit tests reproduce the exact wait and clock sequence from the artifacts. ## Risks - A real event-loop hang longer than 5 s during an admission now extends that admission by the hang minus 5 s. The Runner answer could not be observed during the hang either. Each credited gap still costs 5 s of budget, so a process that is slow on every observation still reaches its deadline. - The ticker runs only while a startup or recovery admission runs (an active operation), every 1 s, does no I/O, and is cleared in `finally`. It does not keep an idle process awake. - A `turn.start` that is cut by a freeze still reports a wall-clock timeout, as before. That case needs its own change, because its event and snapshot waits share one deadline. - No persisted state, launch identity, or saved-session shape changes. Old saved runs resume through the same code. A deploy mid-run only changes how long an in-process admission wait tolerates a stop. No new wait or file operation runs before `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), model ID `claude-opus-5-5`, run in Claude Code with tool use (shell, file edit) and extended reasoning. ## 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 - [x] 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 --- .../src/live/runnerd-codex-transport.test.ts | 105 ++++++++++++++++- .../src/live/runnerd-codex-transport.ts | 107 ++++++++++++++++-- 2 files changed, 201 insertions(+), 11 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 88ebd100055..ab762e4d317 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, waitForRunnerCommand } from "./runnerd-codex-transport.js"; +import { coldAdmissionTimeoutMs, RUNNER_STALL_THRESHOLD_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"; @@ -6703,6 +6703,109 @@ it("shares Pi's absolute cold deadline across recovery barriers and rejects a la } finally { vi.useRealTimers(); } }); +// Chaos w-20261111T011704-s9107/t01: the control plane was stopped (SIGSTOP, as in +// a host sleep) 1 s into the resume barrier, together with the Runner it waits on. +// On thaw, the wall clock had passed the 30 s deadline before either process could +// act, so recovery reported "runner.drain timed out" and spent a recovery attempt. +describe("admission waits do not count time this process was stopped", () => { + const pending = (clock: RunnerStallLedger | undefined, deadline: number, status: () => string, type = "runner.drain") => + waitForRunnerCommand({ + type, deadline, clock, abortOnClose: true, isClosed: () => false, + throwIfFailed: () => undefined, command: () => ({ status: status() }), + runnerHasExited: async () => false, failureCode: () => "runner_local_connect_failed", + }); + + it("completes a resume barrier that the Runner answers after a 44 s freeze", async () => { + vi.useFakeTimers(); + const clock = new RunnerStallLedger(); + const stop = clock.watch(); + try { + let status = "pending"; + const drain = pending(clock, clock.now() + 30_000, () => status); + await vi.advanceTimersByTimeAsync(1_000); + // Stopped for 44 s: the wall clock moves, but no timer of this process runs. + vi.setSystemTime(Date.now() + 44_000); + await vi.advanceTimersByTimeAsync(2_000); + status = "completed"; + await vi.advanceTimersByTimeAsync(10); + await expect(drain).resolves.toBeUndefined(); + } finally { stop(); vi.useRealTimers(); } + }); + + it("keeps the wall-clock timeout for a wait outside an admission", async () => { + vi.useFakeTimers(); + try { + const drain = pending(undefined, Date.now() + 30_000, () => "pending"); + const rejection = expect(drain).rejects.toThrow("runner_local_connect_failed: PRP command runner.drain timed out"); + await vi.advanceTimersByTimeAsync(1_000); + vi.setSystemTime(Date.now() + 44_000); + await vi.advanceTimersByTimeAsync(10); + await rejection; + } finally { vi.useRealTimers(); } + }); + + it("still times out a barrier that the Runner never answers after a freeze", async () => { + vi.useFakeTimers(); + const clock = new RunnerStallLedger(); + const stop = clock.watch(); + try { + const drain = pending(clock, clock.now() + 30_000, () => "pending"); + const rejection = expect(drain).rejects.toThrow("runner_local_connect_failed: PRP command runner.drain timed out"); + await vi.advanceTimersByTimeAsync(1_000); + vi.setSystemTime(Date.now() + 44_000); + // Running time reaches the deadline: 1 s before, the uncredited 5 s of the + // gap, then the rest of the 30 s budget. + await vi.advanceTimersByTimeAsync(30_000); + await rejection; + } finally { stop(); vi.useRealTimers(); } + }); + + it("credits a freeze outside any poll loop to the next barrier on the same deadline", async () => { + vi.useFakeTimers(); + const clock = new RunnerStallLedger(); + const stop = clock.watch(); + try { + const deadline = clock.now() + coldAdmissionTimeoutMs("acpx", "pi", true); + let status = "pending"; + const prepared = pending(clock, clock.now() + 30_000, () => status, "run.prepare"); + await vi.advanceTimersByTimeAsync(5_000); + status = "completed"; + await vi.advanceTimersByTimeAsync(10); + await prepared; + // Stopped for 70 s between barriers (a checkpoint flush, a spawn): only the ticker observes it. + vi.setSystemTime(Date.now() + 70_000); + await vi.advanceTimersByTimeAsync(1_000); + status = "pending"; + const opened = pending(clock, deadline, () => status, "session.open"); + await vi.advanceTimersByTimeAsync(20_000); + status = "completed"; + await vi.advanceTimersByTimeAsync(10); + await expect(opened).resolves.toBeUndefined(); + } finally { stop(); vi.useRealTimers(); } + }); + + it("credits only stalls, so a slow but running process still reaches its deadline", () => { + let wall = 0; + const clock = new RunnerStallLedger(() => wall); + const deadline = clock.now() + 30_000; + // Every observation is 4.9 s apart on a loaded host: that is running time. + while (clock.now() < deadline) wall += 4_900; + expect(wall).toBeGreaterThanOrEqual(30_000); + expect(wall).toBeLessThan(35_000); + expect(clock.creditedMs).toBe(0); + // A 6 s gap is credited only beyond the stall threshold, and only once. + wall += 6_000; + clock.now(); + clock.now(); + expect(clock.creditedMs).toBe(6_000 - RUNNER_STALL_THRESHOLD_MS); + // A wall-clock grace taken now moves onto the clock without the earlier + // credit, so it keeps exactly its own running-time budget. + const wallGrace = wall + 5_000; + const onClock = wallGrace - clock.creditedMs; + expect(onClock - clock.now()).toBe(5_000); + }); +}); + it("aborts startup promptly on close while allowing the owned cleanup command to drain", async () => { vi.useFakeTimers(); try { diff --git a/packages/paperclip-runner/src/live/runnerd-codex-transport.ts b/packages/paperclip-runner/src/live/runnerd-codex-transport.ts index 3e38d1e2fb0..15cb01e41f8 100644 --- a/packages/paperclip-runner/src/live/runnerd-codex-transport.ts +++ b/packages/paperclip-runner/src/live/runnerd-codex-transport.ts @@ -4064,6 +4064,8 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { #nextTraceDebugSequence = 1; #traceRehydrationSpoolOverflow = false; readonly #traceFrameIndex = new RunnerdTraceFrameIndex(); + /** Clock of the startup or recovery admission in progress, if any. */ + #admissionClock: RunnerStallLedger | null = null; #startupSteps: { begin(name: RunnerdStartupStep["name"]): void; /** Move on only from the named open step (later reconnects are not startup milestones). */ @@ -5967,7 +5969,7 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { async #start( params: Record, ): Promise> { - const work = () => this.#withStartupSteps("bootstrap", () => this.#startWork(params)); + const work = () => this.#withAdmissionClock(() => this.#withStartupSteps("bootstrap", () => this.#startWork(params))); return this.options.measureOperation ? this.options.measureOperation("runner.transport.cold_start", work) : work(); } @@ -6219,10 +6221,42 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { } async #resume(): Promise { - const work = () => this.#withStartupSteps("resume", () => this.#resumeWork()); + const work = () => this.#withAdmissionClock(() => this.#withStartupSteps("resume", () => this.#resumeWork())); return this.options.measureOperation ? this.options.measureOperation("runner.transport.resume", work) : work(); } + /** + * One stopped-time clock per admission; a nested startup keeps the outer one. + * It covers the Runner command barriers and the provider-identity wait. The + * warm-transition and source-attachment reconnect polls keep their own + * wall-clock grace deadlines. + */ + async #withAdmissionClock(work: () => Promise): Promise { + if (this.#admissionClock !== null) return work(); + const clock = new RunnerStallLedger(); + const stopWatching = clock.watch(); + this.#admissionClock = clock; + try { + return await work(); + } finally { + stopWatching(); + if (this.#admissionClock === clock) this.#admissionClock = null; + } + } + + /** Wall time, or the admission clock while a startup or recovery runs. */ + #waitNow(): number { + return this.#admissionClock?.now() ?? Date.now(); + } + + /** Moves a wall-clock deadline onto the admission clock, without the stops already credited. */ + #onWaitClock(wallDeadline: number): number { + const clock = this.#admissionClock; + if (clock === null) return wallDeadline; + clock.now(); + return wallDeadline - clock.creditedMs; + } + async #resumeWork(): Promise { if (this.options.acpxCandidateAdmission?.agent === "antigravity") throw new Error("ACPX candidate durable runner recovery is not admitted"); this.#startupSteps?.begin("runner.runtime.stage"); @@ -6943,7 +6977,7 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { this.#assertStartupOpen(); const admissionDeadline = this.#sourceAttachmentDeadline === null ? this.#coldAdmissionDeadline(adoptedRunner === undefined) - : Math.min(Date.now() + 30_000, this.#sourceAttachmentDeadline); + : Math.min(this.#waitNow() + 30_000, this.#onWaitClock(this.#sourceAttachmentDeadline)); // An adopted runner is already live: no launch step (a launch span means a fresh process). if (adoptedRunner) this.#startupSteps?.end(); else this.#startupSteps?.begin("runner.process.launch"); @@ -7690,21 +7724,21 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { #coldAdmissionDeadline(coldProcess = true): number | undefined { const timeout = coldAdmissionTimeoutMs(this.options.provider, this.options.acpxAgent, coldProcess); // Preserve the existing independent waits for other providers and live adoption. - return timeout === 60_000 ? Date.now() + timeout : undefined; + return timeout === 60_000 ? this.#waitNow() + timeout : undefined; } async #waitForProviderIdentity( expectedEventType?: "harness.ready" | "session.started" | "session.resumed", - deadline = Date.now() + 30_000, + deadline = this.#waitNow() + 30_000, ): Promise { return this.options.measureOperation ? this.options.measureOperation("runner.transport.provider_identity", () => this.#waitForProviderIdentityWork(expectedEventType, deadline)) : this.#waitForProviderIdentityWork(expectedEventType, deadline); } async #waitForProviderIdentityWork( expectedEventType?: "harness.ready" | "session.started" | "session.resumed", - deadline = Date.now() + 30_000, + deadline = this.#waitNow() + 30_000, ): Promise { - while (Date.now() < deadline) { + while (this.#waitNow() < deadline) { this.#throwIfFailed(); if (this.#closed) throw new Error("runnerd transport closed during provider startup"); this.#pumpEvents(); @@ -7728,7 +7762,7 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { async #waitCommand( type: string, commandId?: string, - deadline = Date.now() + 30_000, + deadline = this.#waitNow() + 30_000, abortOnClose = false, ): Promise { return this.options.measureOperation ? this.options.measureOperation("runner.transport.command_ack", () => this.#waitCommandWork(type, commandId, deadline, abortOnClose)) : this.#waitCommandWork(type, commandId, deadline, abortOnClose); @@ -7737,12 +7771,13 @@ class DurablePrpCodexTransport implements CodexAppServerTransport { async #waitCommandWork( type: string, commandId?: string, - deadline = Date.now() + 30_000, + deadline = this.#waitNow() + 30_000, abortOnClose = false, ): Promise { await waitForRunnerCommand({ type, deadline, + clock: this.#admissionClock, abortOnClose, isClosed: () => this.#closed, throwIfFailed: () => this.#throwIfFailed(), @@ -9165,10 +9200,61 @@ function closedAcpxRejection(message: unknown): string | null { ? message : null; } +/** + * A gap this long between two observations by a running process (its poll + * loops sleep 10 ms, its ticker 1 s) means the process was not running: + * SIGSTOP, host sleep, or a whole-process stall. + */ +export const RUNNER_STALL_THRESHOLD_MS = 5_000; +const RUNNER_STALL_TICK_MS = 1_000; + +/** + * The clock for one startup or recovery admission. Time this process spends + * stopped is not waiting time: the Runner it waits on is usually stopped with + * it (same host sleep or process tree), and could not answer. The wall clock + * still passes the deadline, so a thaw used to report a timeout before either + * process ran (chaos t01: "runner.drain timed out" 45 s into a 30 s wait that + * held a 44 s freeze). + * + * `now()` is wall time minus the stopped time observed since the ledger + * started. Poll loops and a 1 s ticker share one last-observation time, so a + * stop is credited once, wherever the process was when it stopped (a poll + * loop, a checkpoint flush, a spawn). Only the part of a gap beyond the + * threshold is credited, so a slow but running process still reaches its + * deadlines. Deadlines compared with `now()` must be taken from `now()`. + */ +export class RunnerStallLedger { + #creditedMs = 0; + #last: number; + constructor(private readonly wallNow: () => number = Date.now) { + this.#last = wallNow(); + } + + get creditedMs(): number { + return this.#creditedMs; + } + + now(): number { + const at = this.wallNow(); + if (at - this.#last > RUNNER_STALL_THRESHOLD_MS) this.#creditedMs += at - this.#last - RUNNER_STALL_THRESHOLD_MS; + this.#last = Math.max(this.#last, at); + return at - this.#creditedMs; + } + + /** Observes stops between poll loops; runs only while its admission runs. */ + watch(): () => void { + const ticker = setInterval(() => this.now(), RUNNER_STALL_TICK_MS); + ticker.unref?.(); + return () => clearInterval(ticker); + } +} + /** Shared polling path keeps startup cancellation separate from owned cleanup commands. */ export async function waitForRunnerCommand(input: { type: string; deadline: number; + /** Startup or recovery admission clock; `deadline` was taken from it. */ + clock?: RunnerStallLedger | null; abortOnClose: boolean; isClosed: () => boolean; throwIfFailed: () => void; @@ -9176,7 +9262,8 @@ export async function waitForRunnerCommand(input: { runnerHasExited: () => Promise; failureCode: () => string; }): Promise { - while (Date.now() < input.deadline) { + const now = () => input.clock ? input.clock.now() : Date.now(); + while (now() < input.deadline) { input.throwIfFailed(); if (input.abortOnClose && input.isClosed()) { throw new Error(`runnerd transport closed while waiting for ${input.type}`);