mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-10 12:37:55 +01:00
test(chaos): fail M1 fast on a blocked subtask and grade interrupted waves (#20094)
## 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 <noreply@anthropic.com>
This commit is contained in:
1 parent
c02fd8d427
commit
88835e624a
5 files changed
+76
-10
No files matched your search
@@ -425,7 +425,10 @@ async function main(): Promise<number> {
|
||||
// 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;
|
||||
|
||||
@@ -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);
|
||||
});
|
||||
});
|
||||
@@ -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;
|
||||
|
||||
@@ -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<string, unknown> = {}) =>
|
||||
({ 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);
|
||||
|
||||
@@ -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<string, number[]> {
|
||||
|
||||
Reference in new issue
Block a user