mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-14 00:26:28 +01:00
fix(runner): do not count time the control plane was stopped against a Runner command wait (#20704)
## 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 <noreply@anthropic.com>
This commit is contained in:
1 parent
200c6e40e2
commit
6d1eae73c0
2 files changed
+201
-11
No files matched your search
@@ -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 {
|
||||
|
||||
@@ -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<string, unknown>,
|
||||
): Promise<Record<string, unknown>> {
|
||||
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<void> {
|
||||
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<T>(work: () => Promise<T>): Promise<T> {
|
||||
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<void> {
|
||||
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<void> {
|
||||
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<void> {
|
||||
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<void> {
|
||||
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<void> {
|
||||
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<boolean>;
|
||||
failureCode: () => string;
|
||||
}): Promise<void> {
|
||||
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}`);
|
||||
|
||||
Reference in new issue
Block a user