From 7964433cd011270a859915b624de1c1deef85f33 Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Tue, 10 Nov 2026 04:09:54 -0600 Subject: [PATCH] test(restart-chaos): arm a provider-fault Stop on the first live provider turn (#20512) 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 restart-chaos harness (`tests/restart-chaos`) injects provider message faults (PV1ā€“PV3) to test recovery > - A board Stop task (S1) with a PV `interrupt_ack` fault needs the Stop to reach a live provider turn > - The harness clicked Stop only after a seeded wall-clock window, so a fast agent finished first and nothing was injected > - That task then failed `provider_fault_applied`, which made a clean wave exit 1 with no product failure > - This pull request arms the Stop on the first live provider turn for PV tasks > - The benefit is that PV S1 tasks inject their fault every time, so a wave result means what it says ## Linked Issues or Issue Description Refs #20498 (the product fix whose live waves showed this harness gap). **What happened?** In waves `w-20261110T082702-s212` and `w-20261110T091057-s213` (Claude, `--workloads Q1,S1 --faults PV2 --provider-fault-message interrupt_ack`), task t03 (S1) failed only `provider_fault_applied` with `applied=0`. Its run finished before the seeded Stop window, so the Stop was missed and the fault never fired. Every product rule (R1ā€“R6, U1) passed. The wave still exited 1. **Expected behavior** A PV S1 task injects its fault on every run. A missed injection is a harness gap, not a product failure. **Steps to reproduce** Run `--adapters claude --workloads Q1,S1 --faults PV2 --provider-fault-message interrupt_ack --concurrency 1 --tasks 4`. The second S1 task often finishes before its Stop window. ## What Changed - `observer.ts`: the run-event cursor now tracks a live provider turn (`turn.started` with no `turn.completed/failed/cancelled/interrupted` yet). Run samples expose it as `providerTurnActive`. - New `stopArmed()`: a task with a provider fault arms its Stop on the first poll that shows a live provider turn. Other tasks keep the seeded wall-clock window, unchanged. - A runner replacement or stop clears the live-turn mark, as it already clears open tools. - A PV Stop still counts as missed when the run ends with no live turn seen and the task rests after the window. - The continue comment still waits for the seeded window and `STOP_CONTINUE_AFTER_MS`. - README note under the provider fault section. No product code changes. ## Verification - `pnpm exec vitest run --config tests/restart-chaos/vitest.config.ts`: 35 files, 438 tests pass. - New tests in `observer.test.ts`: - `S1 with a provider fault: stops on the first live provider turn, not the wall-clock window` - `S1 with a provider fault: does not stop after a turn terminal, and stops once when the next turn starts` - `S1 with a provider fault: records a missed Stop when the run ends before any live turn and the task rests after the window` - `noteLivenessEvent: a runner replacement or stop clears the live provider turn` - `stopArmed: a provider-fault Stop needs a live provider turn; others keep the window` - Red against master `observer.ts`: the first three new tests fail. Green with the change. - `node scripts/typecheck-test-projects.mjs tests/restart-chaos` passes. - No live wave was run (the wave queue was full); the coordinator asked for a test-only change. ## Risks - Low. This is test-harness code only. - A PV S1 Stop can now land earlier in the turn than before. That is the intended test point for `interrupt_ack`. - A turn shorter than the poll interval (`--poll-ms`, 2ā€“5 s) can still be missed. The README states this limit. - If a provider never records `turn.started`, the PV Stop waits until the task rests and is then recorded as missed, the same result as before. ## Model Used - Anthropic Claude, model ID `claude-opus-5-5`, used through Claude Code with tool use (shell, file edit, code execution). ## 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 - [x] All Paperclip CI gates are green - [x] 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 --- tests/restart-chaos/README.md | 8 +++ tests/restart-chaos/observer.test.ts | 104 ++++++++++++++++++++++++++- tests/restart-chaos/observer.ts | 31 ++++++-- tests/restart-chaos/types.ts | 2 + 4 files changed, 139 insertions(+), 6 deletions(-) diff --git a/tests/restart-chaos/README.md b/tests/restart-chaos/README.md index 93db4f57445..04bb9cd4d41 100644 --- a/tests/restart-chaos/README.md +++ b/tests/restart-chaos/README.md @@ -550,6 +550,14 @@ G1 grades the board decision after a restart, so G1 with a provider fault needs `--provider-fault-restart K1`. On a board Stop (S1) the runner ends Codex without waiting for its terminal: in wave w-20261110T050407-s206 Codex exited 1.5 s after `turn/interrupt` with no `turn/completed`, so a `terminal` rule never applies there and the task fails `provider_fault_applied`. Use `interrupt_ack` for S1. +An S1 task with a provider fault clicks Stop on the first poll that shows a live provider turn +(`turn.started` with no turn terminal yet), not after the seeded follow-up window. A fast agent used to +finish before that window, so the fault was never injected (waves w-20261110T082702-s212 and +w-20261110T091057-s213, t03: `applied=0`). The continue comment still waits for the window. If the +run ends before any live turn is seen, the Stop is recorded as missed once the task rests after the window. +A live turn is seen only when a poll (`--poll-ms`, 2ā€“5 s) lands inside it, so a turn shorter than the +poll interval can still be missed. A runner replacement or stop clears the live-turn mark, as it does for +an open tool. | Adapter | `terminal` | `interrupt_ack` | | --- | --- | --- | diff --git a/tests/restart-chaos/observer.test.ts b/tests/restart-chaos/observer.test.ts index c2dcb4fc046..41f7e609faa 100644 --- a/tests/restart-chaos/observer.test.ts +++ b/tests/restart-chaos/observer.test.ts @@ -4,7 +4,7 @@ import os from "node:os"; import path from "node:path"; import { afterEach, describe, expect, it } from "vitest"; import type { ChaosApi } from "./api.js"; -import { CHILD_WAKE_GRACE_MS, REST_CONFIRM_MS, STALL_GIVE_UP_MS, STOP_CONTINUE_AFTER_MS, TaskObserver, childSpeedTasksInTurn, childrenPending, listWorkspaceFiles, toRunSample } from "./observer.js"; +import { CHILD_WAKE_GRACE_MS, REST_CONFIRM_MS, STALL_GIVE_UP_MS, STOP_CONTINUE_AFTER_MS, TaskObserver, childSpeedTasksInTurn, childrenPending, listWorkspaceFiles, noteLivenessEvent, stopArmed, toRunSample } from "./observer.js"; import { gradeTask } from "./grader.js"; import { createFixtureRepository, type ChaosLab } from "./seed.js"; import { Timeline } from "./timeline.js"; @@ -189,6 +189,108 @@ describe("TaskObserver", () => { expect(posted.filter(route => route.endsWith("/cancel"))).toHaveLength(1); }); + it("S1 with a provider fault: stops on the first live provider turn, not the wall-clock window", async () => { + // Waves w-20261110T082702-s212 and w-20261110T091057-s213: the agent finished + // before the seeded window, so the PV2 interrupt_ack fault was never injected. + let events: unknown[] = []; + let runStatus = "running"; + const base = fakeApi({ + "/events": () => events, + "/runs": () => [{ id: "r1", status: runStatus, createdAt: new Date(0).toISOString(), finishedAt: null }], + }, "in_progress"); + const posted: string[] = []; + const api = { ...base.api, get: base.api.get.bind(base.api), async post(route: string) { + posted.push(route); + if (route === "/api/heartbeat-runs/r1/cancel") { runStatus = "cancelled"; return { id: "r1" }; } + return route.endsWith("/issues") ? { id: "i1", identifier: "CHA-1" } : { id: "comment-1" }; + } } as unknown as ChaosApi; + const pvPlan: TaskPlan = { ...plan, workload: "S1", adapter: "claude", followUpAfterMs: 60_000, + providerFault: { kind: "PV2", message: "interrupt_ack" } }; + const observer = new TaskObserver(pvPlan, api, lab, new Timeline(null), ready); + await observer.launch(); + const start = observer.record.createdAt!; + // Running, but no provider turn yet: the prompt has not reached the provider. + await observer.poll(start + 500); + expect(posted.filter(route => route.endsWith("/cancel"))).toEqual([]); + events = [{ seq: 1, eventType: "turn.started", createdAt: new Date(start + 600).toISOString(), payload: {} }]; + await observer.poll(start + 1_000); + expect(posted.filter(route => route.endsWith("/cancel"))).toEqual(["/api/heartbeat-runs/r1/cancel"]); + expect(observer.record.stop).toMatchObject({ runId: "r1", httpStatus: 200 }); + // The continue comment still waits for the seeded window. + events = []; + await observer.poll(start + 1_000 + STOP_CONTINUE_AFTER_MS + 1); + expect(observer.record.followUp).toBeNull(); + await observer.poll(start + 60_000 + 1); + expect(observer.record.followUp).toMatchObject({ commentId: "comment-1" }); + }); + + it("S1 with a provider fault: does not stop after a turn terminal, and stops once when the next turn starts", async () => { + const events = [ + { seq: 1, eventType: "turn.started", createdAt: new Date(1).toISOString(), payload: {} }, + { seq: 2, eventType: "turn.completed", createdAt: new Date(2).toISOString(), payload: {} }, + ]; + let nextTurn: unknown[] = []; + const base = fakeApi({ + "/events": route => route.includes("afterSeq=0") ? events + : route.includes("afterSeq=2") ? nextTurn : [], + "/runs": () => [{ id: "r1", status: "running", createdAt: new Date(0).toISOString(), finishedAt: null }], + }, "in_progress"); + const pvPlan: TaskPlan = { ...plan, workload: "S1", adapter: "claude", followUpAfterMs: 1_000, + providerFault: { kind: "PV2", message: "interrupt_ack" } }; + const observer = new TaskObserver(pvPlan, base.api, lab, new Timeline(null), ready); + await observer.launch(); + await observer.poll(observer.record.createdAt! + 5_000); + expect(base.posted.filter(route => route.endsWith("/cancel"))).toEqual([]); + expect(observer.record.stop ?? null).toBeNull(); + // The next turn re-arms the Stop, and it fires once. + nextTurn = [{ seq: 3, eventType: "turn.started", createdAt: new Date(3).toISOString(), payload: {} }]; + await observer.poll(observer.record.createdAt! + 6_000); + nextTurn = []; + await observer.poll(observer.record.createdAt! + 7_000); + expect(base.posted.filter(route => route.endsWith("/cancel"))).toEqual(["/api/heartbeat-runs/r1/cancel"]); + expect(observer.record.stop).toMatchObject({ runId: "r1" }); + }); + + it("S1 with a provider fault: records a missed Stop when the run ends before any live turn and the task rests after the window", async () => { + const base = fakeApi({ "/events": () => [], + "/runs": () => [{ id: "r1", status: "succeeded", createdAt: new Date(0).toISOString(), finishedAt: new Date(1).toISOString() }], + "/comments": () => [], "/documents/": () => null, "/workspace-operations": () => [] }, "done"); + const timeline = new Timeline(null); + const pvPlan: TaskPlan = { ...plan, workload: "S1", adapter: "claude", followUpAfterMs: 1_000, + providerFault: { kind: "PV2", message: "interrupt_ack" } }; + const observer = new TaskObserver(pvPlan, base.api, lab, timeline, ready); + await observer.launch(); + const start = observer.record.createdAt!; + await observer.poll(start + 500); + expect(observer.record.stop ?? null).toBeNull(); + await observer.poll(start + 2_000); + expect(observer.record.stop).toMatchObject({ runId: null, missed: true }); + expect(timeline.entries.some(entry => entry.kind === "task_stop_missed")).toBe(true); + expect(base.posted.filter(route => route.endsWith("/cancel"))).toEqual([]); + }); + + it("noteLivenessEvent: a runner replacement or stop clears the live provider turn", () => { + const replaced = { seq: 0, lastAt: null, openTools: 0, process: null } as Parameters[0]; + noteLivenessEvent(replaced, { eventType: "native.process_identity_recorded", payload: { targetKind: "local", processPid: 1, processStartedAt: "a" } }); + noteLivenessEvent(replaced, { eventType: "turn.started", payload: {} }); + expect(replaced.turnActive).toBe(true); + noteLivenessEvent(replaced, { eventType: "native.process_identity_recorded", payload: { targetKind: "local", processPid: 2, processStartedAt: "b" } }); + expect(replaced.turnActive).toBe(false); + noteLivenessEvent(replaced, { eventType: "turn.started", payload: {} }); + noteLivenessEvent(replaced, { eventType: "native.local_process_stopped", payload: { processPid: 2 } }); + expect(replaced.turnActive).toBe(false); + }); + + it("stopArmed: a provider-fault Stop needs a live provider turn; others keep the window", () => { + const live = { id: "r1", status: "running", providerTurnActive: true } as never; + const idle = { id: "r1", status: "running" } as never; + expect(stopArmed({ now: 0, windowAt: 1_000, providerFault: true, running: live })).toBe(true); + expect(stopArmed({ now: 5_000, windowAt: 1_000, providerFault: true, running: idle })).toBe(false); + expect(stopArmed({ now: 5_000, windowAt: 1_000, providerFault: true, running: undefined })).toBe(false); + expect(stopArmed({ now: 0, windowAt: 1_000, providerFault: false, running: live })).toBe(false); + expect(stopArmed({ now: 1_000, windowAt: 1_000, providerFault: false, running: undefined })).toBe(true); + }); + it("S1: holds the Stop while another task's fault has the server down or recovering", async () => { const base = fakeApi({ "/runs": () => [{ id: "r1", status: "running", createdAt: new Date(0).toISOString(), finishedAt: null }] }, "in_progress"); const posted: string[] = []; diff --git a/tests/restart-chaos/observer.ts b/tests/restart-chaos/observer.ts index e1042cf6ed6..15abf96dfd2 100644 --- a/tests/restart-chaos/observer.ts +++ b/tests/restart-chaos/observer.ts @@ -97,24 +97,29 @@ interface RunEventCursor { openTools: number; /** The run's latest recorded local runner process, until recovery reports it stopped. */ process: { pid: number; startedAt: string } | null; + /** A provider turn started and has no turn terminal yet. */ + turnActive?: boolean; } /** R5 liveness: a tool in flight, or a recorded local runner process. */ export function noteLivenessEvent(cursor: RunEventCursor, event: Json) { const payload = (event.payload ?? {}) as Json; switch (event.eventType) { + case "turn.started": cursor.turnActive = true; break; + case "turn.completed": case "turn.failed": case "turn.cancelled": case "turn.interrupted": + cursor.turnActive = false; break; case "tool.execution.started": cursor.openTools += 1; break; case "tool.execution.completed": cursor.openTools = Math.max(0, cursor.openTools - 1); break; case "native.process_identity_recorded": if (payload.targetKind === "local" && Number.isSafeInteger(payload.processPid) && typeof payload.processStartedAt === "string") { - // A replacement runner cannot finish a tool its predecessor started. - if (cursor.process && cursor.process.pid !== payload.processPid) cursor.openTools = 0; + // A replacement runner cannot finish a tool or turn its predecessor started. + if (cursor.process && cursor.process.pid !== payload.processPid) { cursor.openTools = 0; cursor.turnActive = false; } cursor.process = { pid: payload.processPid, startedAt: payload.processStartedAt }; } break; case "native.local_process_stopped": - // A stopped runner's in-flight tools can never send their completion. - if (cursor.process && payload.processPid === cursor.process.pid) { cursor.process = null; cursor.openTools = 0; } + // A stopped runner's in-flight tools and turn can never send their completion. + if (cursor.process && payload.processPid === cursor.process.pid) { cursor.process = null; cursor.openTools = 0; cursor.turnActive = false; } break; } } @@ -161,6 +166,17 @@ export function toInterruption(value: Json | null | undefined): InterruptionSamp } /** Rest = no live run and nothing the system itself is still doing. */ +/** + * When a board Stop (S1) fires. A provider message fault (PV) needs the Stop's + * interrupt to reach a live provider turn, so it fires on the first sample that + * shows one, not after the seeded wall-clock window: a fast agent can finish + * before that window and leave the fault uninjected. Other tasks keep the window. + */ +export function stopArmed(input: { now: number; windowAt: number; providerFault: boolean; running: RunSample | undefined }): boolean { + if (input.providerFault) return Boolean(input.running?.providerTurnActive); + return input.now >= input.windowAt; +} + export function isResting(sample: TaskSample): boolean { if (!sample.reachable || !sample.serverReady) return false; if ((sample.runs ?? []).some(run => ACTIVE_RUN_STATUSES.has(run.status))) return false; @@ -516,6 +532,7 @@ export class TaskObserver { this.runEventCursors.set(run.id, cursor); return { ...run, lastEvidenceAt: latestIso([run.lastEvidenceAt, cursor.lastAt]), ...(cursor.openTools > 0 ? { toolInFlight: true } : {}), + ...(cursor.turnActive ? { providerTurnActive: true } : {}), ...(cursor.process && this.processAlive(cursor.process.pid, cursor.process.startedAt) ? { processAlive: true } : {}) }; } @@ -539,8 +556,12 @@ export class TaskObserver { private async maybeStop(sample: TaskSample, now: number): Promise { if (!this.definition.stopBeforeFollowUp || this.record.stop || this.plan.followUpAfterMs === null || !sample.serverReady) return false; - if (now < this.record.createdAt! + this.plan.followUpAfterMs) return false; + const windowAt = this.record.createdAt! + this.plan.followUpAfterMs; const running = (sample.runs ?? []).find(run => run.status === "running"); + if (!stopArmed({ now, windowAt, providerFault: Boolean(this.plan.providerFault), running })) { + // A PV Stop still waits for a live turn; it counts as missed only once the task rests after the window. + if (!this.plan.providerFault || now < windowAt || running || !isResting(sample)) return false; + } if (!running) { if (!isResting(sample)) return false; this.record.stop = { at: now, runId: null, httpStatus: null, error: null, missed: true }; diff --git a/tests/restart-chaos/types.ts b/tests/restart-chaos/types.ts index b1d07b2563a..1cafd3b54aa 100644 --- a/tests/restart-chaos/types.ts +++ b/tests/restart-chaos/types.ts @@ -203,6 +203,8 @@ export interface RunSample { toolInFlight?: boolean; /** The run's recorded local runner process is still running with the same start time. */ processAlive?: boolean; + /** A provider turn started and has no turn terminal yet. */ + providerTurnActive?: boolean; } export interface InterruptionSample {