From 9715b3d2102ff138f3b4ec1f5bf0e6ac57269eae Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Mon, 9 Nov 2026 05:32:59 -0600 Subject: [PATCH] test(restart-chaos): do not grade a recovery that a back-to-back fault interrupted (#20243) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Thinking Path - #20183 split restart recovery so the speed budget judges Paperclip's own share (`restart_recovery_control_plane`). - In Phase 3's local mixed wave (`w-20261109T104527-s9901`, master 3963d38560), Claude's control-plane recovery was p50 1.4 s but p95 24.2 s (n=19). That suggested an occasional 20 s wait on Paperclip's side. - The kept database shows otherwise. The slow samples all come from back-to-back faults on one run (`566c07b4`): - f07 was ready at 10:56:45.39; the run requested its runner at 45.70; f08 (K6) killed the server at 45.78. - f09 started 0.69 s after f08 was ready. - So each "sample" spans the next fault's outage plus a repeated recovery. Outage time is removed, but the repeated claim, prepare and launch work and the partial attempt are still charged. Paperclip has no wait to fix; the grader mismeasures overlapping faults. ## Linked Issues or Issue Description Refs #20183 **What happened?** A recovery sample that a later fault interrupted before its next provider event was graded as if it were one long recovery. That inflated the control-plane p95 (Claude, 24.2 s) in fault storms. **Steps to reproduce** 1. Run a chaos wave with back-to-back faults (for example the mixed wave seed 9901: f07 K4 → f08 K6 0.4 s after ready → f09 K6 0.7 s after ready). 2. Look at `restart_recovery_control_plane` for runs in flight across those faults. **Expected behavior** Only uninterrupted recoveries are graded. Interrupted ones are counted and reported. ## What Changed - `tests/restart-chaos/ttft-baseline-stats.ts`: - `BaselineFault` gains `startedAt`. - When a later fault starts inside a sample's window (after ready, before the next provider event), `recoverySamples` marks the sample `interruptedByFault` and nulls its latencies. The later fault's own sample measures that run. - `tests/restart-chaos/wave-speed.ts`: - `faultRuns` passes `startedAt`. - `WaveSpeed` reports `recoveryInterruptedByFault`, which no longer counts as "no provider event". - The speed summary prints it. - Tests: - A new back-to-back case: the interrupted sample is skipped and the later fault's 1.5 s recovery is graded. It's red without the change and green with it. - The `faultRuns` expectation includes `startedAt`. ## Verification - `npx vitest run --config tests/restart-chaos/vitest.config.ts tests/restart-chaos/wave-speed.test.ts tests/restart-chaos/ttft-baseline-stats.test.ts`: 32 passed. - Against the wave: the two samples behind the tail (f07 → f08, f08 → f09) are exactly the interrupted ones. The next slowest Claude sample (f10, 15.6 s) includes a 9.4 s `provider.session.load`, so its control-plane share is about 6 s. ## Risks - **Harness grading only; no product change.** Fault storms produce fewer graded samples, and the count is reported, so a wave that is mostly interrupted is visible. - **A real Paperclip wait** that happened to straddle a later fault would be hidden in that sample. It would show up in uninterrupted samples. ## Model Used Claude Opus 5.5 (`claude-opus-5-5`, Anthropic), 1M context window, tool use and code execution, via 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/ttft-baseline-stats.ts | 15 ++++++++++++++- tests/restart-chaos/wave-speed.test.ts | 15 ++++++++++++++- tests/restart-chaos/wave-speed.ts | 10 +++++++--- 3 files changed, 35 insertions(+), 5 deletions(-) diff --git a/tests/restart-chaos/ttft-baseline-stats.ts b/tests/restart-chaos/ttft-baseline-stats.ts index ce407120494..317a54927d5 100644 --- a/tests/restart-chaos/ttft-baseline-stats.ts +++ b/tests/restart-chaos/ttft-baseline-stats.ts @@ -24,6 +24,9 @@ export interface BaselineRun { export interface BaselineFault { kind: string; readyAt: number; + /** When the fault began. A recovery that a later fault interrupts before its + * next provider event is not a measurement of this fault's recovery. */ + startedAt?: number; /** Runs that were in flight when the fault started. */ runIds: string[]; } @@ -137,7 +140,11 @@ export interface RecoverySample { runId: string; adapter: string; kind: string; * latency when nothing reloads. The judged row. */ controlPlaneMs: number | null; /** The provider's share: session load start to the next provider event. Reported. */ - providerLoadMs: number | null } + providerLoadMs: number | null; + /** A later fault began before this recovery reached its next provider event + * (back-to-back faults). Its latencies are null: the later fault's own sample + * measures that run. */ + interruptedByFault?: true } /** Control plane ready → the recovered run's next provider event, keyed by runner disposition. */ /** The run's trace start: every span records its offset from it. A span event is @@ -180,6 +187,12 @@ export function recoverySamples(runs: readonly BaselineRun[], faults: readonly B && Date.parse(event.createdAt) >= fault.readyAt - 60_000); const next = run.events.find(event => PROVIDER_EVENT_TYPES.has(event.eventType) && Date.parse(event.createdAt) >= fault.readyAt); const nextAt = next ? Date.parse(next.createdAt) : null; + if (nextAt !== null && faults.some(other => other.startedAt !== undefined && other.startedAt > fault.readyAt && other.startedAt < nextAt)) { + samples.push({ runId, adapter: run.adapter, kind: fault.kind, readyAt: fault.readyAt, + disposition: String(transition?.payload?.runnerDisposition ?? "none"), + latencyMs: null, controlPlaneMs: null, providerLoadMs: null, interruptedByFault: true }); + continue; + } const stamped = stampProviderLoadStarts(run); const loadStarts = nextAt === null ? [] : stamped.events.flatMap(event => { if (event.eventType !== "run.performance.span" || event.payload?.span !== "provider.session.load") return []; diff --git a/tests/restart-chaos/wave-speed.test.ts b/tests/restart-chaos/wave-speed.test.ts index c376cd83ee2..2a78be4110e 100644 --- a/tests/restart-chaos/wave-speed.test.ts +++ b/tests/restart-chaos/wave-speed.test.ts @@ -64,6 +64,19 @@ describe("wave speed grade", () => { expect(speed.breaches).toBe(0); }); + it("does not grade a recovery that a back-to-back fault interrupted before its next provider event", () => { + // f1 is ready at 10 s; f2 hits 0.4 s later and is ready at 30 s; the run resumes 1.5 s after f2. + const recovered: BaselineRun = { runId: "r", adapter: "claude", environment: "local", phase: "cold", + events: [{ eventType: "session.resumed", createdAt: new Date(31_500).toISOString() }] }; + const faults = [{ kind: "K4", startedAt: 1_000, readyAt: 10_000, runIds: ["r"] }, + { kind: "K6", startedAt: 10_400, readyAt: 30_000, runIds: ["r"] }]; + const windows = outageWindows(faults.map(fault => ({ startedAt: fault.startedAt, readyAt: fault.readyAt }) as FaultReceipt)); + const speed = gradeWaveSpeed("local", [recovered], faults, 0, [], { adjusted: 0, removedMs: 0, windows }); + expect(speed.rows.find(row => row.metric === "restart_recovery_control_plane")).toMatchObject({ measured: { n: 1, p50: 1_500 }, breaches: [] }); + expect(speed.recoveryInterruptedByFault).toBe(1); + expect(speed.recoveryWithoutProviderEvent).toBe(0); + }); + it("removes a later outage from restart recovery", () => { const recovered: BaselineRun = { runId: "r", adapter: "claude", environment: "local", phase: "cold", events: [{ eventType: "turn.started", createdAt: new Date(10_000 + 302_000).toISOString() }] }; @@ -183,6 +196,6 @@ describe("wave speed grade", () => { const fault = { kind: "K2", startedAt: 1_000, readyAt: 2_000 } as FaultReceipt; expect(faultRuns([fault], [{ id: "before", createdAt: 0, finishedAt: 500 }, { id: "live", createdAt: 0, finishedAt: null }, { id: "during", createdAt: 1_500, finishedAt: null }, { id: "after", createdAt: 2_500, finishedAt: null }])) - .toEqual([{ kind: "K2", readyAt: 2_000, runIds: ["live", "during"] }]); + .toEqual([{ kind: "K2", readyAt: 2_000, startedAt: 1_000, runIds: ["live", "during"] }]); }); }); diff --git a/tests/restart-chaos/wave-speed.ts b/tests/restart-chaos/wave-speed.ts index c57973fa00b..065fd1d24ce 100644 --- a/tests/restart-chaos/wave-speed.ts +++ b/tests/restart-chaos/wave-speed.ts @@ -22,6 +22,8 @@ export interface WaveSpeed { outageAdjustedSpans: number; outageRemovedMs: number; recoveryWithoutProviderEvent: number; + /** Recovery samples a later fault interrupted before their next provider event (not graded). */ + recoveryInterruptedByFault: number; runBudgetExceeded: number; singleRunBreaches: number; breaches: number; @@ -53,7 +55,7 @@ export function breachesOf(measured: Distribution, budget: SpeedBudget | 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!, + 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) })); } @@ -211,7 +213,9 @@ export function gradeWaveSpeed(environment: EnvironmentKind, runs: readonly Base || (boot !== null && bootBudget !== null && boot > bootBudget.p95Ms); }).length; const breaches = rows.reduce((total, row) => total + row.breaches.length, 0) + singleRunBreaches; - return { environment, rows, recoveryWithoutProviderEvent: samples.filter(sample => sample.latencyMs === null).length, + return { environment, rows, + recoveryWithoutProviderEvent: samples.filter(sample => sample.latencyMs === null && !sample.interruptedByFault).length, + recoveryInterruptedByFault: samples.filter(sample => sample.interruptedByFault).length, runBudgetExceeded, singleRunBreaches, breaches, errors, outageAdjustedSpans: outage.adjusted, outageRemovedMs: outage.removedMs }; } @@ -282,7 +286,7 @@ export function speedMarkdown(speed: WaveSpeed): string { const s = (value: number | null) => value === null ? "—" : `${(value / 1000).toFixed(1)} s`; const lines = [`## Speed (${speed.environment})`, "", `Breaches: ${speed.breaches} (aggregate p50/p95 rows plus ${speed.singleRunBreaches} runs over the p95 budget after outage removal; the server logged ${speed.runBudgetExceeded} budget_exceeded events before removal).`, - `Restart samples with no provider event after ready: ${speed.recoveryWithoutProviderEvent}.`, + `Restart samples with no provider event after ready: ${speed.recoveryWithoutProviderEvent}. Interrupted by a later fault (not graded): ${speed.recoveryInterruptedByFault}.`, `Outage time removed from ${speed.outageAdjustedSpans} spans: ${s(speed.outageRemovedMs)} (fault start to server ready; budgets judge the rest).`, "", "| Adapter | Metric | Start | n | p50 | p95 | Budget p50 / p95 | Breach |", "|---|---|---|---|---|---|---|---|"]; for (const row of speed.rows) {