From c874cfa4dacc6e8dc0a13135d4e5f84f4928729d Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Tue, 10 Nov 2026 07:03:15 -0600 Subject: [PATCH] test(restart-chaos): anchor two-server speed samples on the primary's restart (#20535) 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 grades each wave's speed, including how fast runs recover after a server restart > - Two-server faults (MS1–MS3, #20518) record their `readyAt` after the second server stops > - The speed grade used that time as a restart-recovery anchor, also for faults that never restart the primary > - Wave `w-20261110T115048-s302` passed every task but exited 1 on four such samples > - This pull request anchors two-server samples on the primary's own restart > - The benefit is that a two-server wave fails speed only for a real recovery delay ## Linked Issues or Issue Description Refs #20518 (the two-server faults). **What happened?** In wave `w-20261110T115048-s302` (Codex, B5, MS2/MS3, 4 tasks) every task passed, but the speed grade counted 4 single-run breaches on `restart_recovery_control_plane` (p50 10.9 s, p95 12.8 s, budget p95 4.0 s), one per fault. - MS2 never restarts the primary (it freezes and thaws it), yet it produced a restart-recovery sample. - MS3's sample started at the fault's `readyAt`, after the second server's 33–43 s tail. The primary's replacement had been ready since 1794311949160 (f02) and 1794312728179 (f04), 43.4 s and 33.6 s earlier. - So each sample measured the B5 run's next provider event after the second server stopped, while `bench.sh` ran quietly. **Expected behavior** MS1 and MS2 produce no restart-recovery sample. MS3's sample starts when the primary's replacement is ready. ## What Changed - `wave-speed.ts`: - New `primaryRestartReadyAt(fault)`: a non-MS fault keeps its `readyAt`; MS1 gives none; MS2 gives none, unless the primary exited after the thaw and was replaced (then the replacement's `healthyAt`); MS3 gives `multiServer.primaryRestart.readyAt`. - `faultRuns` (recovery samples and the retry "restart" phase) uses that anchor and skips faults without one. - `outageWindows` removes only the time the primary could not serve: none for MS1, the freeze for MS2, and for MS3 from the second server's readiness (when the primary is told to stop) to the replacement's readiness. Before, the second server's whole window was removed from run timings. - `collectWaveSpeed` sets a run's restart phase only from faults that restarted the primary. A freeze still subtracts its downtime, but a run it hit before its first activity stays in its cold or warm budget (review finding). - `wave-speed.test.ts`: six tests built from s302's saved receipts, including two `collectWaveSpeed` cases (a run frozen before its first activity; a retry after an MS2 freeze). - README: one note on how the speed grade treats MS faults. Test-only. No longer freeze and no lease change, as agreed. ## Verification - Red against master `wave-speed.ts`: all 6 new tests fail. Green with the change. - `pnpm exec vitest run --config tests/restart-chaos/vitest.config.ts`: 38 files, 480 tests pass. - `node scripts/typecheck-test-projects.mjs tests/restart-chaos` passes. - Offline re-grade of s302 with the fix, from its saved `faults.json` and run timings (`t0*.grade.json`): - Restart-recovery samples go from 4 to 2. The MS2 samples (f01, f03) are gone. - The two MS3 samples are anchored at 1794311949160 (f02) and 1794312728179 (f04), 43.4 s and 33.6 s earlier than before. - Outage removed from run timings: 110.0 s and 113.3 s for the MS2 freezes, 5.6 s and 6.5 s for the MS3 restarts. - No s302 run was hit before its first activity (each freeze came about 68 s into its run), so no run changes phase. - The MS3 latency itself needs the run's event list, which a wave does not save for passing tasks. The observer's saved samples show the run's first recorded activity 0.5 s (f02) and 1.6 s (f04) after the replacement was ready. The next provider event comes at or after that, so this is a lower bound, not the graded value. - `restart_recovery_control_plane` has n = 2 < 5, so its row reports "insufficient sample". The wave's speed verdict now depends only on whether each MS3 sample is under 4.0 s, which this offline data cannot confirm. - No new wave (as agreed). ## Risks - Low. Test-harness code only. - After MS1/MS2 a retry of a failed run is graded as an ordinary warm run, since the primary never restarted. - MS1 overlap and the MS2 thaw tail no longer count as outage, so run timings in those windows are graded in full. The primary served during them. - A primary replaced after an MS2 thaw is graded like any restart. ## 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 | 5 +- tests/restart-chaos/wave-speed.test.ts | 83 ++++++++++++++++++++++++++ tests/restart-chaos/wave-speed.ts | 48 +++++++++++++-- 3 files changed, 130 insertions(+), 6 deletions(-) diff --git a/tests/restart-chaos/README.md b/tests/restart-chaos/README.md index 46b11781627..ed117ef867e 100644 --- a/tests/restart-chaos/README.md +++ b/tests/restart-chaos/README.md @@ -930,7 +930,10 @@ server's pid, start, exit and freezes). A violation fails the wave. (`native.process_identity_recorded`) before the first was shown stopped (`native.local_process_stopped`). - Ownership failures whose owner is not a wave server (or is unknown) are listed as `unattributed`. -The usual R1–R6, U1–U4 and T checks grade every task as before. +The usual R1–R6, U1–U4 and T checks grade every task as before. In the speed grade, MS1 and MS2 take no +restart-recovery sample (the primary never restarts; MS2 does when the primary exited after the thaw and was +replaced), MS3 is timed from the primary replacement's readiness, and only the time the primary could not serve +counts as outage. ## Fault timing (`--triggers`) diff --git a/tests/restart-chaos/wave-speed.test.ts b/tests/restart-chaos/wave-speed.test.ts index cd7d4ff7aeb..f4bf929f40f 100644 --- a/tests/restart-chaos/wave-speed.test.ts +++ b/tests/restart-chaos/wave-speed.test.ts @@ -260,3 +260,86 @@ describe("wave speed grade", () => { .toEqual([{ kind: "K2", readyAt: 2_000, startedAt: 1_000, runIds: ["live", "during"] }]); }); }); + +// Receipts from wave w-20261110T115048-s302 (faults.json), trimmed to what the speed grade reads. +const msReceipt = (kind: "MS1" | "MS2" | "MS3", times: { startedAt: number; readyAt: number; healthyAt?: number }, + multi: Partial>): FaultReceipt => ({ + faultId: "f", kind, requestedBy: "t", signal: "none", holdMs: 0, requestedAt: times.startedAt, startedAt: times.startedAt, + stoppedAt: null, restartedAt: null, healthyAt: times.healthyAt ?? null, readyAt: times.readyAt, phases: [], + serverLogOffsetAtStart: 0, serverLogOffsetAtReady: null, error: null, + multiServer: { kind, secondary: null, steps: [], ...multi }, +}); +const S302_MS2 = msReceipt("MS2", { startedAt: 1794311530823, readyAt: 1794311678390, healthyAt: 1794311647900 }, + { primaryFreeze: { kind: "TM2", frozenAt: 1794311537833, thawedAt: 1794311647835 } }); +const S302_MS3 = msReceipt("MS3", { startedAt: 1794311934901, readyAt: 1794311992580 }, + { secondary: { pid: 79488, port: 54688, spawnedAt: 1794311934902, readyAt: 1794311943511, stoppedAt: 1794311992577 }, primaryRestart: { stoppedAt: 1794311943796, restartedAt: 1794311943796, readyAt: 1794311949160, replacementPid: 80430 } }); +const MS1 = msReceipt("MS1", { startedAt: 1_000, readyAt: 120_000 }, {}); + +describe("two-server faults in the speed grade", () => { + const live = [{ id: "r", createdAt: 0, finishedAt: null }]; + + it("takes no restart-recovery sample from MS1 or MS2: the primary never restarted", () => { + expect(faultRuns([MS1, S302_MS2], live)).toEqual([]); + // An MS2 primary that exited after the thaw and was replaced did restart: its replacement's health anchors it. + const replaced = { ...S302_MS2, multiServer: { ...S302_MS2.multiServer!, primaryFreeze: { kind: "TM2" as const, + frozenAt: 1794311537833, thawedAt: 1794311647835, serverExitedAfterThaw: { code: 1, signal: null } } } }; + expect(faultRuns([replaced], live)).toEqual([{ kind: "MS2", readyAt: 1794311647900, startedAt: 1794311530823, runIds: ["r"] }]); + }); + + it("anchors an MS3 sample when the primary's replacement is ready, not when the second server stops", () => { + expect(faultRuns([S302_MS3], live)).toEqual([{ kind: "MS3", readyAt: 1794311949160, startedAt: 1794311934901, runIds: ["r"] }]); + }); + + it("removes only the time the primary could not serve", () => { + expect(outageWindows([MS1, S302_MS2, S302_MS3])).toEqual([ + { startedAt: 1794311537833, readyAt: 1794311647835 }, + // From the second server's readiness, when the primary was told to stop; it served until then. + { startedAt: 1794311943511, readyAt: 1794311949160 }, + ]); + }); + + const traced = (runId: string, trace: number, spans: Array<[string, number, number]>, extra: Record = {}) => ({ + events: spans.map(([name, offset, duration], seq) => ({ seq, eventType: "run.performance.span", + createdAt: new Date(trace + offset + duration).toISOString(), payload: { span: name, startOffsetMs: offset, durationMs: duration } })), + sample: { id: runId, status: "succeeded", createdAt: new Date(trace).toISOString(), finishedAt: new Date(trace + 200_000).toISOString(), ...extra }, + }); + const collect = (runs: Array>, faults: FaultReceipt[]) => { + const byId = new Map(runs.map(entry => [entry.sample.id, entry.events])); + const api = { get: async (route: string) => route.includes("workspace-operations") ? [] + : byId.get(route.split("/")[3]!.split("?")[0]!) ?? [] } as unknown as ChaosApi; + return collectWaveSpeed(api, "local", [{ issueId: "i", adapter: "codex", samples: [{ runs: runs.map(entry => entry.sample) }] as never }], faults); + }; + + it("keeps a run an MS2 freeze hit before its first activity in its cold budget, with the freeze removed", async () => { + // Created 1 s before the freeze; first activity 115 s later, 110.002 s of it frozen: 4.998 s of real start. + const hit = traced("r1", 1794311536833, [["heartbeat.queue", 0, 100], ["task.time_to_first_agent_activity", 0, 115_000]]); + const speed = await collect([hit], [S302_MS2]); + expect(speed.rows.find(row => row.metric === "time_to_first_activity" && row.start === "cold")).toMatchObject({ measured: { n: 1, p50: 4_998 } }); + expect(speed.rows.filter(row => row.start === "restart").every(row => row.measured.n === 0)).toBe(true); + expect(speed.singleRunBreaches).toBe(0); + }); + + it("grades a retry of a run that failed after an MS2 freeze as an ordinary warm run", async () => { + // The primary never restarted, so the retry starts on a serving server and keeps its warm budget. + const failed = traced("r1", 1794311500000, [["heartbeat.queue", 0, 100], ["task.time_to_first_agent_activity", 0, 4_000]], + { status: "failed" }); + const retry = traced("r2", 1794311700000, [["heartbeat.queue", 0, 100], ["task.time_to_first_agent_activity", 0, 30_000]], + { retryOfRunId: "r1" }); + const speed = await collect([failed, retry], [S302_MS2]); + expect(speed.rows.find(row => row.metric === "time_to_first_activity" && row.start === "warm")).toMatchObject({ measured: { n: 1, p50: 30_000 } }); + }); + + it("grades s302's MS3 shape as a fast recovery, and MS2 not at all", () => { + // The run resumes 1.5 s after the replacement is ready; its next provider event after the second server + // stopped (s302: about 11 s later, while bench.sh ran quietly) is not a recovery. + const resumedAt = 1794311949160 + 1_500; + const recovered: BaselineRun = { runId: "r", adapter: "codex", environment: "local", phase: "cold", events: [ + { eventType: "session.resumed", createdAt: new Date(resumedAt).toISOString() }, + { eventType: "tool.execution.progressed", createdAt: new Date(1794311992580 + 11_000).toISOString() }] }; + const faults = [S302_MS2, S302_MS3]; + const speed = gradeWaveSpeed("local", [recovered], faultRuns(faults, live), 0, [], + { adjusted: 0, removedMs: 0, windows: outageWindows(faults) }); + expect(speed.rows.find(row => row.metric === "restart_recovery_control_plane")).toMatchObject({ measured: { n: 1, p50: 1_500 }, breaches: [] }); + expect(speed).toMatchObject({ singleRunBreaches: 0, breaches: 0 }); + }); +}); diff --git a/tests/restart-chaos/wave-speed.ts b/tests/restart-chaos/wave-speed.ts index ce5f5fb76a6..dc0cd2e8f3f 100644 --- a/tests/restart-chaos/wave-speed.ts +++ b/tests/restart-chaos/wave-speed.ts @@ -70,16 +70,51 @@ export function breachesOf(measured: Distribution, budget: SpeedBudget | null): return out; } +/** + * When the primary server served again after a restart, the anchor of a restart-recovery sample; null when + * the fault did not restart it. A two-server fault's own `readyAt` comes after the second server stopped + * (multi-server.ts), which is not a restart of the primary: + * MS1 leaves the primary serving: no restart. + * MS2 freezes and thaws it: no restart, unless it exited after the thaw and was replaced (its `healthyAt`). + * MS3 restarts it (K2): its replacement's `readyAt`, before the second server's tail. + */ +export function primaryRestartReadyAt(fault: FaultReceipt): number | null { + const multi = fault.multiServer; + if (!multi) return fault.readyAt; + if (multi.kind === "MS3") return multi.primaryRestart?.readyAt ?? null; + if (multi.kind === "MS2" && multi.primaryFreeze?.serverExitedAfterThaw) return fault.healthyAt; + return null; +} + export function faultRuns(faults: readonly FaultReceipt[], runs: ReadonlyArray<{ id: string; createdAt: number; finishedAt: number | null }>): BaselineFault[] { - return faults.filter(fault => fault.readyAt !== null).map(fault => ({ kind: fault.kind, readyAt: fault.readyAt!, startedAt: fault.startedAt, - runIds: runs.filter(run => run.createdAt <= fault.readyAt! && (run.finishedAt === null || run.finishedAt >= fault.startedAt)) - .map(run => run.id) })); + return faults.flatMap(fault => { + const readyAt = primaryRestartReadyAt(fault); + return readyAt === null ? [] : [{ kind: fault.kind, readyAt, startedAt: fault.startedAt, + runIds: runs.filter(run => run.createdAt <= readyAt && (run.finishedAt === null || run.finishedAt >= fault.startedAt)) + .map(run => run.id) }]; + }); } export interface OutageWindow { startedAt: number; readyAt: number } +/** + * Time the primary could not serve, removed from run timings. MS1 has none. MS2's is the freeze (to the + * replacement's health when it exited after the thaw). MS3's ends when the replacement is ready. + */ export function outageWindows(faults: readonly FaultReceipt[]): OutageWindow[] { - return faults.filter(fault => fault.readyAt !== null).map(fault => ({ startedAt: fault.startedAt, readyAt: fault.readyAt! })); + return faults.flatMap((fault): OutageWindow[] => { + const multi = fault.multiServer; + if (!multi) return fault.readyAt === null ? [] : [{ startedAt: fault.startedAt, readyAt: fault.readyAt }]; + if (multi.kind === "MS2") { + const freeze = multi.primaryFreeze; + const end = freeze?.serverExitedAfterThaw ? fault.healthyAt : freeze?.thawedAt ?? null; + return freeze?.frozenAt !== undefined && end !== null && end > freeze.frozenAt ? [{ startedAt: freeze.frozenAt, readyAt: end }] : []; + } + // MS3 stops the primary only once the second server is ready; the primary served until then. + const ready = primaryRestartReadyAt(fault); + const stopping = multi.secondary?.readyAt ?? fault.startedAt; + return ready === null || ready <= stopping ? [] : [{ startedAt: stopping, readyAt: ready }]; + }); } export function storageFaultWindows(receipts: readonly StorageFaultReceipt[], now: number): OutageWindow[] { @@ -317,6 +352,9 @@ export async function collectWaveSpeed(api: ChaosApi, environment: EnvironmentKi const timing: Array<{ id: string; createdAt: number; finishedAt: number | null }> = []; const errors: string[] = []; const windows = outageWindows(faults); + // A freeze is downtime to remove, but only a restart makes a run a restart-phase run: a frozen-then-thawed + // primary (MS2) keeps its runs in their cold or warm budgets, with the freeze removed. + const restartWindows = outageWindows(faults.filter(fault => !fault.multiServer || primaryRestartReadyAt(fault) !== null)); const storageWindows = storageFaultWindows(storageReceipts, now); const outage = { adjusted: 0, removedMs: 0, windows, storageWindows, storageRemovedMs: 0 }; const perTask = tasks.map(task => { @@ -337,7 +375,7 @@ export async function collectWaveSpeed(api: ChaosApi, environment: EnvironmentKi errors.push(`${run.id}: ${error instanceof Error ? error.message : String(error)}`); } if (run.retryOfRunId && faultHit.has(run.retryOfRunId)) raw.phase = "restart"; - if (faultBeforeFirstActivity(raw, windows, Date.parse(run.createdAt!))) raw.phase = "restart"; + if (faultBeforeFirstActivity(raw, restartWindows, Date.parse(run.createdAt!))) raw.phase = "restart"; // Stamp provider load starts from raw offsets before outage removal rewrites them. const stamped = stampProviderLoadStarts(raw); const restartOnly = withoutOutage(stamped, windows);