From 88835e624a2ae7159bfe0c2332c2c1fca23453fc Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Sun, 8 Nov 2026 14:20:57 -0600 Subject: [PATCH] test(chaos): fail M1 fast on a blocked subtask and grade interrupted waves (#20094) 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 proves that real agent tasks survive control-plane restarts > - In a K4/K6 wave with the M1 multi-agent scenario, one subtask failed. Its parent waited on it, and the harness kept watching for over 50 minutes > - When the operator stopped the wave, the harness wrote no grade files, so the 17 finished tasks had no grade > - Separately, master's harness test for time to first activity failed after #20077 changed how time is measured from run creation > - This pull request makes M1 fail fast on a blocked subtask, grades the finished tasks of an interrupted wave, and aligns the speed grade with #20077 > - The benefit is shorter waves with a grade for every task, and a green harness suite on master ## Linked Issues or Issue Description Refs #20071, #20077, #20088 **What happened?** Wave `w-20261108T181313-s9701` (local, codex and claude, A1/C1/M1, K4 and K6) ran 71 minutes against a planned 30. Task t05 (M1) delegated CHA-8 and CHA-9. The CHA-8 run failed after a K4 restart (the defect that #20088 fixes), and CHA-8 went to `blocked`. The observer kept waiting for CHA-8 to finish. After SIGINT, the harness threw before grading, so no task had a grade file. Also, `wave-speed.test.ts` fails on master: #20077 changed `runMetrics` to measure from the start of `heartbeat.queue`. **Steps to reproduce** 1. Run an M1 task whose subtask run fails and leaves the subtask `blocked`. 2. See the observer wait until the parent deadline. 3. Send SIGINT to the harness and see that no grade files are written. **Expected behavior** A blocked subtask ends the wait, and the parent is graded as a failure with a `task_child_blocked` timeline entry. An interrupted wave grades every finished task and fails the wave. ## What Changed - `observer.ts`: `childrenPending` treats a `blocked` subtask as settled, so the parent rests and is graded. The timeline records `task_child_blocked` with the subtask ids. - `observer.ts`: `markUnfinished` closes an open task at interrupt as unfinished (`timedOut`, last seen status) and records `task_unfinished_at_interrupt`. - `main.ts`: an interrupt now sets the harness error and grades the wave, instead of throwing before the grade. The wave still fails. - `wave-speed.ts`: `firstActivityMs` uses `runMetrics().firstActivityAfterRunCreatedMs` from #20077, so there is one definition of time from run creation. - `wave-speed.test.ts`: the fixture starts `heartbeat.queue` when the comment wait ends, as in real runs. ## Verification - `npx vitest run` in `tests/restart-chaos`: 172 passed. Before this change, the wave-speed test failed on master. - `node scripts/typecheck-test-projects.mjs tests/restart-chaos`: clean. ## Risks - A subtask that is `blocked` only for a short time and then resumes would end the parent's watch after the 60-second grace. The grade then shows a failure that a longer wait could avoid. M1 subtasks have no blockers, so `blocked` means a stuck subtask. - An interrupted wave grades tasks while its server is still up. If the server is already down, artifact collection fails, and those tasks are graded as failures. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, with tool use and code execution in Claude Code. ## 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 Opus 5.5 --- tests/restart-chaos/main.ts | 5 ++- tests/restart-chaos/observer.test.ts | 49 +++++++++++++++++++++++++- tests/restart-chaos/observer.ts | 19 +++++++++- tests/restart-chaos/wave-speed.test.ts | 9 ++--- tests/restart-chaos/wave-speed.ts | 4 +-- 5 files changed, 76 insertions(+), 10 deletions(-) diff --git a/tests/restart-chaos/main.ts b/tests/restart-chaos/main.ts index dc02edc393a..a3e77987747 100644 --- a/tests/restart-chaos/main.ts +++ b/tests/restart-chaos/main.ts @@ -425,7 +425,10 @@ async function main(): Promise { // An injected fault that did not complete invalidates the wave, even when // bounded recovery brought the server back and the tasks passed. if (faultFailures) harnessError ??= new Error(`${faultFailures} injected fault(s) failed; see fault_error in the timeline`); - if (interrupted) throw new Error("Harness interrupted before the wave finished"); + if (interrupted) { + harnessError ??= new Error("Harness interrupted before the wave finished"); + for (const observer of launched) observer.markUnfinished(); + } // R6: let finalizers settle, then sweep for anything still pending. const quietFor = Date.now() - lastDoneAt; diff --git a/tests/restart-chaos/observer.test.ts b/tests/restart-chaos/observer.test.ts index 3094909e8a9..51ad4916034 100644 --- a/tests/restart-chaos/observer.test.ts +++ b/tests/restart-chaos/observer.test.ts @@ -4,7 +4,8 @@ import os from "node:os"; import path from "node:path"; import { afterEach, describe, expect, it } from "vitest"; import type { ChaosApi } from "./api.js"; -import { REST_CONFIRM_MS, STALL_GIVE_UP_MS, TaskObserver, listWorkspaceFiles } from "./observer.js"; +import { CHILD_WAKE_GRACE_MS, REST_CONFIRM_MS, STALL_GIVE_UP_MS, TaskObserver, childrenPending, listWorkspaceFiles } from "./observer.js"; +import { gradeTask } from "./grader.js"; import { createFixtureRepository, type ChaosLab } from "./seed.js"; import { Timeline } from "./timeline.js"; import type { TaskPlan } from "./types.js"; @@ -85,6 +86,43 @@ describe("TaskObserver", () => { expect(observer.record.preFaultSnapshotError).toMatch(/ENOENT/); }); + it("keeps an M1 parent watched while a subtask runs, then rests it once a subtask is blocked", async () => { + let childStatus = "in_progress"; + const { api } = fakeApi({ "parentIds=": () => [{ id: "c1", parentId: "i1", status: "done" }, { id: "c2", parentId: "i1", status: childStatus }], + "/documents/": () => null }, "blocked"); + const timeline = new Timeline(null); + const observer = new TaskObserver({ ...plan, workload: "M1", followUpAfterMs: null }, api, lab, timeline, ready); + await observer.launch(); + let now = observer.record.createdAt! + 1_000; + const restWindow = async () => { await observer.poll(now); now += REST_CONFIRM_MS + 1; await observer.poll(now); now += 1_000; }; + await restWindow(); + await restWindow(); + expect(observer.done).toBe(false); + childStatus = "blocked"; + await restWindow(); + expect(observer.done).toBe(false); + expect(timeline.entries.filter(entry => entry.kind === "task_child_blocked")).toHaveLength(1); + now += CHILD_WAKE_GRACE_MS; + await restWindow(); + expect(observer.done).toBe(true); + expect(observer.record.finalStatus).toBe("blocked"); + }); + + it("closes an open task as unfinished at interrupt, so the wave grades it as a failure", async () => { + const { api } = fakeApi({}, "in_progress"); + const timeline = new Timeline(null); + const observer = new TaskObserver({ ...plan, workload: "A1", followUpAfterMs: null }, api, lab, timeline, ready); + await observer.launch(); + await observer.poll(observer.record.createdAt! + 1_000); + observer.markUnfinished(); + expect(observer.done).toBe(true); + expect(observer.record).toMatchObject({ timedOut: true, finalStatus: "in_progress" }); + expect(timeline.entries.some(entry => entry.kind === "task_unfinished_at_interrupt")).toBe(true); + const grade = gradeTask(observer.record, [], observer.definition.budgetMs, { verdict: "pass", checks: [] }); + expect(grade.pass).toBe(false); + expect(grade.rules.R1.detail).toMatch(/no_rest_within_budget/); + }); + it("fires the planned fault once, after its offset", async () => { const { api } = fakeApi(); const observer = new TaskObserver({ ...plan, fireAfterMs: 5_000 }, api, lab, new Timeline(null), ready); @@ -116,3 +154,12 @@ describe("fixture repository", () => { expect(record?.result).toBe(BENCH_EXPECTED); }, 60_000); }); + +describe("childrenPending", () => { + it("waits on running subtasks and stops waiting once each is done, cancelled or blocked", () => { + expect(childrenPending(null)).toBe(true); + expect(childrenPending([{ status: "done" }, { status: "in_progress" }])).toBe(true); + expect(childrenPending([{ status: "done" }, { status: "cancelled" }])).toBe(false); + expect(childrenPending([{ status: "done" }, { status: "blocked" }])).toBe(false); + }); +}); diff --git a/tests/restart-chaos/observer.ts b/tests/restart-chaos/observer.ts index 919d4fdead5..b67ddcd300a 100644 --- a/tests/restart-chaos/observer.ts +++ b/tests/restart-chaos/observer.ts @@ -49,6 +49,10 @@ const RESULT_TRIGGER_EVENTS = new Set(["run.result.proposed", "run.result.accept /** Rest must hold for this long before the observer acts on it. */ export const REST_CONFIRM_MS = 12_000; export const CHILD_WAKE_GRACE_MS = 60_000; + +export function childrenPending(children: ReadonlyArray<{ status: string | null }> | null): boolean { + return !children || children.some(child => !["done", "cancelled", "blocked"].includes(child.status ?? "")); +} /** Extra time granted after a Retry click before R3 is graded as timed out. */ export const RETRY_BUDGET_MS = 15 * 60_000; /** H1: how long the pause must hold with the server ready before the board resumes. */ @@ -386,6 +390,15 @@ export class TaskObserver { if (startedAt !== undefined) this.record.lastFaultAt = Math.max(this.record.lastFaultAt ?? 0, startedAt); } + markUnfinished() { + if (this.done) return; + const last = this.record.samples.at(-1); + this.record.timedOut = true; + this.record.finalStatus = last?.issueStatus ?? this.record.finalStatus; + this.done = true; + this.timeline.add("task_unfinished_at_interrupt", { taskId: this.plan.taskId, status: this.record.finalStatus }); + } + /** Outages extend the deadline: R1 allows budget plus outage time. */ extendDeadline(ms: number) { if (this.record.deadlineAt !== null) this.record.deadlineAt += ms; } @@ -501,7 +514,11 @@ export class TaskObserver { const faultSinceRetry = this.record.retry !== null && (this.record.lastFaultAt ?? 0) > this.record.retry.at; if (status !== "done" && this.definition.collect.childDocuments && this.record.issueId) { const children = await this.collectChildren(this.record.issueId).catch(() => null); - const pending = !children || children.some(child => !["done", "cancelled"].includes(child.status ?? "")); + const pending = childrenPending(children); + const blocked = (children ?? []).filter(child => child.status === "blocked").map(child => child.id); + if (!pending && blocked.length && this.childrenSettledAt === null) { + this.timeline.add("task_child_blocked", { taskId: this.plan.taskId, childIssueIds: blocked }); + } this.childrenSettledAt = pending ? null : (this.childrenSettledAt ?? now); if (pending || now - this.childrenSettledAt! < CHILD_WAKE_GRACE_MS) { this.restCandidateSince = null; diff --git a/tests/restart-chaos/wave-speed.test.ts b/tests/restart-chaos/wave-speed.test.ts index b283fc11f68..9e2ef2f232a 100644 --- a/tests/restart-chaos/wave-speed.test.ts +++ b/tests/restart-chaos/wave-speed.test.ts @@ -4,8 +4,8 @@ import type { FaultReceipt } from "./types.js"; import { breachesOf, budgetFor, faultRuns, firstActivityMs, gradeWaveSpeed, outageWindows, speedMarkdown, traceStartMs, withoutOutage } from "./wave-speed.js"; import { runMetrics } from "./ttft-baseline-stats.js"; -const span = (name: string, startOffsetMs: number, durationMs: number) => - ({ eventType: "run.performance.span", createdAt: "2026-11-08T00:00:00.000Z", payload: { span: name, startOffsetMs, durationMs } }); +const span = (name: string, startOffsetMs: number, durationMs: number, extra: Record = {}) => + ({ eventType: "run.performance.span", createdAt: "2026-11-08T00:00:00.000Z", payload: { span: name, startOffsetMs, durationMs, ...extra } }); const run = (runId: string, adapter: string, ttftMs: number, extra: BaselineRun["events"] = []): BaselineRun => ({ runId, adapter, environment: "local", phase: "cold", @@ -30,8 +30,9 @@ describe("wave speed grade", () => { }); it("judges time to first agent activity when the run logs it, net of the wait behind a live turn", () => { - const withActivity = run("a", "codex", 40_000, [span("task.time_to_first_agent_activity", 0, 9_000), - span("comment.to_run_created", 0, 4_000)]); + const withActivity: BaselineRun = { runId: "a", adapter: "codex", environment: "local", phase: "cold", + events: [span("comment.to_run_created", 0, 4_000), span("heartbeat.queue", 4_000, 100), span("runner.turn.submit", 4_100, 900), + span("task.time_to_first_agent_activity", 0, 9_000, { anchor: "comment" }), span("task.time_to_first_token", 0, 40_000, { anchor: "comment" })] }; expect(firstActivityMs(withActivity)).toBe(5_000); expect(firstActivityMs(run("b", "codex", 7_000))).toBe(7_000); const speed = gradeWaveSpeed("local", [withActivity], [], 0); diff --git a/tests/restart-chaos/wave-speed.ts b/tests/restart-chaos/wave-speed.ts index 61afe2e1001..bfa77ce0d03 100644 --- a/tests/restart-chaos/wave-speed.ts +++ b/tests/restart-chaos/wave-speed.ts @@ -102,9 +102,7 @@ export function withoutOutage(run: BaselineRun, windows: readonly OutageWindow[] export function firstActivityMs(run: BaselineRun): number | null { const metrics = runMetrics(run); - const span = runSpans(run).find(candidate => candidate.name === "task.time_to_first_agent_activity"); - if (!span) return metrics.ttftAfterRunCreatedMs; - return Math.max(0, span.durationMs - (metrics.inputWaitMs ?? 0)); + return metrics.firstActivityAfterRunCreatedMs ?? metrics.ttftAfterRunCreatedMs; } function firstActivityByGroup(runs: readonly BaselineRun[]): Map {