diff --git a/doc/plans/2026-11-11-staging-failures-vs-chaos-coverage.md b/doc/plans/2026-11-11-staging-failures-vs-chaos-coverage.md index 2550b6ff024..3164758a4b1 100644 --- a/doc/plans/2026-11-11-staging-failures-vs-chaos-coverage.md +++ b/doc/plans/2026-11-11-staging-failures-vs-chaos-coverage.md @@ -307,3 +307,40 @@ What this shows: - The next scenario to build is **K15 with `--upgrade-from` on Daytona**: start with the older checkout and its image, redeploy to the current checkout, and keep the older runner in the retained sandboxes. Today the Daytona image check refuses that mixed state on purpose. + +### Follow-up: long mid-tool outages and server stalls (PR #20711) + +Built after review by the class R and class L fix owners: + +- `--k15-hold-seconds` holds a K15 outage, because staging deploys were down 4–7 minutes. +- The T1 workload keeps a shell tool running across the fault, and `fault_crossed_tool` proves it. +- Sandbox-side Runner evidence is captured in `results//daytona-runner/`. +- TM1 stalls now run on Daytona, with `--tm1-hold-seconds`. + +Class L turned out not to be a deploy. The server process stalled for about 100 s at 08:19Z on Nov 10. + +| Wave | Revision | Scenario | Result | +| --- | --- | --- | --- | +| `w-20261111T015441-s9310` | 8f6ca25976 | K15 hold 267–408 s, T1, OpenCode | 4 of 4 pass. The Runner was alive through every outage. | +| `w-20261111T022637-s9311` | 8f6ca25976 | K15 hold 300 s, T1, OpenCode and Claude | 4 of 4 pass. The stop captures show the T1 loop running. | +| `w-20261111T025307-s9320` | a1ec05a1a4 | K15 hold 460–482 s, past the Runner's 420 s reconnect grace | 4 of 4 pass. The same `runnerd` PID was alive 491–549 s after the stop, every sandbox was `started`, and there was no `transport_reconnect_grace_exceeded`. | +| `w-20261111T034105-s9330` | a1ec05a1a4 | TM1 70–120 s at `--fault-after-seconds 10`, A1, all three adapters | **RED, 1 of 3 fail.** An OpenCode run was stalled at `native.process_start_requested`. Afterwards it waited forever on `native.recovery.transition` with `reason: controller_still_alive` and `restartKind: hard`. The controller it waited for was its own live, unrestarted process. No Retry was offered. | +| `w-20261111T040439-s9331` | a1ec05a1a4 | TM1 70–120 s mid-tool, T1, all three adapters | **RED, 3 of 3 fail.** After the stall, `native.session.execute` ended, but the run never got another event: no terminal and no recovery. It stayed `running` for more than 20 minutes with no Retry. Each task crossed three back-to-back stalls. | + +Conclusions: + +- Class R's Runner loss (`runner_remote_process_identity_unavailable`) does **not** reproduce on current + master with the e2e image, even past the reconnect grace. +- Staging differs from these waves in four ways: + - its sandboxes come from the managed fleet snapshot (`fleet-sbx-…`, last updated Nov 5), not the e2e image; + - it ran older runner builds; + - Railway drains the server before it stops; + - the cloud manages the sandbox lifecycle. +- The next step needs staging-side `runnerd.stderr.log` from a retained sandbox of a failed run. +- A control-plane stall **without** a restart is a new open product class. A native run whose lease + lapses while its own server is frozen is never taken back by that same server: + - **stall during preparation:** the run waits forever on `controller_still_alive`; + - **stall mid-turn:** the run is orphaned while still `running`. +- #20694 fixed the legacy `preparing` case only. +- Code pointer: `server/src/services/native-runtime/native-restart-recovery.ts` (the same-boot owner is not + recognized as the server itself). diff --git a/tests/restart-chaos/README.md b/tests/restart-chaos/README.md index 44bdfc95349..19886b6dc43 100644 --- a/tests/restart-chaos/README.md +++ b/tests/restart-chaos/README.md @@ -353,10 +353,16 @@ minutes. In staging class R, recovery then found the remote Runner gone next deploy generation starts. Without the option, a K15 restarts at once. The range is drawn only for K15 cells, so other seeds keep their plans. - **T1** (opt-in workload) has the agent run one shell command in the - foreground for about 100 s (50 ticks of 2 s). It then saves `brief`, whose - first line is `TICKS-=50`. Its fault window (35–80 s after launch) - lands while the tool runs in the sandbox. The window stays short of provider - shell-tool timeouts. + foreground for about 100 s (50 ticks of 2 s). The command prints the loop's + own clock window. The agent then saves `brief`, whose first line is + `TICKS-=50 start= end=`. Its fault window (35–80 s + after launch) aims to land while the tool runs in the sandbox, and stays short + of provider shell-tool timeouts. + + The `fault_crossed_tool` check fails the task unless one of its own faults + started inside the reported window, with 5 s of clock slack. A fault that hit + preparation, with the loop run afterwards, tested nothing mid-tool, as a + provider-fault task whose fault never applied. - **Runner evidence:** on a Daytona K15 wave, the harness captures every started sandbox of the wave three times: - right after the server stopped (`-stopped`); @@ -376,6 +382,11 @@ minutes. In staging class R, recovery then found the remote Runner gone that carry the wave's company and environment labels. Known secret values are redacted. A failed capture is recorded and does not fail the wave. + The whole capture (client, listing and every probe) has one 45 s deadline. + The capture runs while the server is down, so a slow Daytona API cannot + stretch the outage. A capture that hits the deadline is recorded as + `deadlineExceeded`, and the restart continues. + ## Absolute symlink in the workspace (F1) ```sh diff --git a/tests/restart-chaos/daytona-runner-logs.ts b/tests/restart-chaos/daytona-runner-logs.ts index 8d6a71575e1..5b9efa3e1ad 100644 --- a/tests/restart-chaos/daytona-runner-logs.ts +++ b/tests/restart-chaos/daytona-runner-logs.ts @@ -29,9 +29,14 @@ export const RUNNER_LOG_PROBE = [ + ' echo "== file $f $(stat -c "%s bytes, modified %y" "$f" 2>/dev/null)"; tail -c 24576 "$f"; echo; done', ].join("; "); +/** The whole capture (client, listing and every probe) gets this long; the outage it runs in must not grow. */ +export const RUNNER_LOG_CAPTURE_DEADLINE_MS = 45_000; + export interface RunnerLogCapture { label: string; observedAt: string; + /** True when the deadline ended the capture; sandboxes not reached are recorded with `error: "deadline"`. */ + deadlineExceeded?: boolean; sandboxes: Array<{ id: string; name: string | null; state: string | null; file: string | null; exitCode: number | null; error: string | null }>; error: string | null; } @@ -60,36 +65,56 @@ export function probeableSandbox(sandbox: DaytonaSandboxRow): boolean { */ export async function captureWaveRunnerLogs(input: { apiKey: string; companyId: string; environmentId: string; outDir: string; label: string; secrets: readonly string[]; - client?: ProbeClient; timeoutSeconds?: number; + client?: ProbeClient; timeoutSeconds?: number; deadlineMs?: number; }): Promise { const label = captureDirectoryName(input.label); const capture: RunnerLogCapture = { label, observedAt: new Date().toISOString(), sandboxes: [], error: null }; const directory = path.join(input.outDir, label); + const deadlineMs = input.deadlineMs ?? RUNNER_LOG_CAPTURE_DEADLINE_MS; + const deadlineAt = Date.now() + deadlineMs; + let timer: NodeJS.Timeout | undefined; + const deadline = new Promise<"deadline">(resolve => { timer = setTimeout(() => resolve("deadline"), deadlineMs); }); + // Each step races the shared deadline; a step that loses keeps running in the background but is no longer awaited. + const withinDeadline = (step: Promise) => Promise.race([step, deadline]); try { - await mkdir(directory, { recursive: true, mode: 0o700 }); - const client = input.client ?? await createRemoteFixtureClient(input.apiKey) as unknown as ProbeClient; - const wave = { companyId: input.companyId, environmentId: input.environmentId }; - const rows: DaytonaSandboxRow[] = []; - for await (const row of client.list({ labels: { "paperclip-company-id": wave.companyId, "paperclip-environment-id": wave.environmentId } })) rows.push(row); - for (const row of selectWaveSandboxes(rows, wave)) { - const entry: RunnerLogCapture["sandboxes"][number] = { id: row.id, name: row.name ?? null, state: row.state ?? null, file: null, exitCode: null, error: null }; - capture.sandboxes.push(entry); - if (!probeableSandbox(row)) continue; - try { - const sandbox = await client.get(row.id); - const response = await sandbox.process.executeCommand(`sh -c '${RUNNER_LOG_PROBE.replace(/'/g, `'\\''`)}'`, undefined, {}, input.timeoutSeconds ?? 20); - entry.exitCode = response.exitCode; - entry.file = `${row.id}.txt`; - await writeFile(path.join(directory, entry.file), redactKnownSecrets(String(response.result ?? ""), input.secrets), { mode: 0o600 }); - } catch (error) { - entry.error = error instanceof Error ? error.message : String(error); - } + const outcome = await withinDeadline(probeWave()); + if (outcome === "deadline") { + capture.deadlineExceeded = true; + capture.error = `capture deadline ${deadlineMs} ms exceeded`; } - } catch (error) { - capture.error = error instanceof Error ? error.message : String(error); + } finally { + clearTimeout(timer); } try { await writeFile(path.join(directory, "index.json"), `${JSON.stringify(capture, null, 2)}\n`, { mode: 0o600 }); } catch { /* the directory itself failed; the returned record still carries the error */ } return capture; + + async function probeWave(): Promise { + try { + await mkdir(directory, { recursive: true, mode: 0o700 }); + const client = input.client ?? await createRemoteFixtureClient(input.apiKey) as unknown as ProbeClient; + if (Date.now() >= deadlineAt) return; + const wave = { companyId: input.companyId, environmentId: input.environmentId }; + const rows: DaytonaSandboxRow[] = []; + for await (const row of client.list({ labels: { "paperclip-company-id": wave.companyId, "paperclip-environment-id": wave.environmentId } })) rows.push(row); + for (const row of selectWaveSandboxes(rows, wave)) { + const entry: RunnerLogCapture["sandboxes"][number] = { id: row.id, name: row.name ?? null, state: row.state ?? null, file: null, exitCode: null, error: null }; + capture.sandboxes.push(entry); + if (!probeableSandbox(row)) continue; + if (Date.now() >= deadlineAt) { entry.error = "deadline"; continue; } + try { + const sandbox = await client.get(row.id); + const response = await sandbox.process.executeCommand(`sh -c '${RUNNER_LOG_PROBE.replace(/'/g, `'\\''`)}'`, undefined, {}, input.timeoutSeconds ?? 20); + entry.exitCode = response.exitCode; + entry.file = `${row.id}.txt`; + await writeFile(path.join(directory, entry.file), redactKnownSecrets(String(response.result ?? ""), input.secrets), { mode: 0o600 }); + } catch (error) { + entry.error = error instanceof Error ? error.message : String(error); + } + } + } catch (error) { + capture.error = error instanceof Error ? error.message : String(error); + } + } } diff --git a/tests/restart-chaos/journey-matrix.ts b/tests/restart-chaos/journey-matrix.ts index 6acb49229ba..b8e7f6f6b71 100644 --- a/tests/restart-chaos/journey-matrix.ts +++ b/tests/restart-chaos/journey-matrix.ts @@ -10,6 +10,7 @@ * share the server with a fault cell (`matrixMayLaunch`). */ import path from "node:path"; +import { k15HoldMs } from "./redeploy.js"; import { WORKLOAD_TRIGGERS } from "./journeys.js"; import { withProviderFaultRules } from "./provider-faults.js"; import { createRng, k4HoldRange, TRIGGER_DELAY_RANGE_MS } from "./scheduler.js"; @@ -43,7 +44,7 @@ export function matrixMayLaunch(next: Pick, inFlight: Readonl return inFlight.every(task => (task.fault === "K0") === baseline); } -export function planMatrixTasks(options: Pick): TaskPlan[] { +export function planMatrixTasks(options: Pick): TaskPlan[] { const rng = createRng((options.seed ^ 0x6a6d7478) >>> 0); return matrixCells(options).map((cell, index) => { const definition = workloadDefinitions[cell.workload]; @@ -58,8 +59,10 @@ export function planMatrixTasks(options: Pick { expect(defaults.mode === "wave" && defaults.options.workloads).not.toContain("T1"); }); - it("passes only when the finished tool's count is reported and the task is done", () => { - expect(t1.grade(NONCE, done(`${t1Marker(NONCE)}=${T1_TICKS}\nmore`)).verdict).toBe("pass"); - expect(t1.grade(NONCE, done(`${t1Marker(NONCE)}=49`)).verdict).toBe("fail"); + const START = 1_794_370_000; + const line = (ticks: number, start = START, end = START + 100) => `${t1Marker(NONCE)}=${ticks} start=${start} end=${end}`; + + it("passes only when the finished tool's count and window are reported and the task is done", () => { + expect(t1.grade(NONCE, done(`${line(T1_TICKS)}\nmore`)).verdict).toBe("pass"); + expect(t1.grade(NONCE, done(line(49))).verdict).toBe("fail"); + expect(t1.grade(NONCE, done(`${t1Marker(NONCE)}=${T1_TICKS}`)).verdict).toBe("fail"); expect(t1.grade(NONCE, done("")).verdict).toBe("fail"); - expect(t1.grade(NONCE, { ...done(`${t1Marker(NONCE)}=${T1_TICKS}`), issueStatus: "blocked" }).verdict).toBe("fail"); + expect(t1.grade(NONCE, { ...done(line(T1_TICKS)), issueStatus: "blocked" }).verdict).toBe("fail"); + expect(parseT1Report(NONCE, line(T1_TICKS, START + 10, START))).toBeNull(); + }); + + it("counts a mid-tool test only when one of the task's own faults started inside the loop's window", () => { + const plan = { taskId: "t01", workload: "T1" as const, nonce: NONCE }; + const pass = t1.grade(NONCE, done(line(T1_TICKS))); + const fault = (taskId: string, atSeconds: number) => ({ faultId: "f01", requestedBy: taskId, startedAt: atSeconds * 1000 }); + expect(withT1CrossingCheck(pass, plan, line(T1_TICKS), [fault("t01", START + 40)]).verdict).toBe("pass"); + // Clock slack at the edges, but a fault during preparation (before the loop) tested nothing mid-tool. + expect(withT1CrossingCheck(pass, plan, line(T1_TICKS), [fault("t01", START - T1_CLOCK_SLACK_MS / 1000)]).verdict).toBe("pass"); + const missed = withT1CrossingCheck(pass, plan, line(T1_TICKS), [fault("t01", START - 30)]); + expect(missed.verdict).toBe("fail"); + expect(missed.checks.find(check => check.name === "fault_crossed_tool")?.ok).toBe(false); + // Another task's fault does not count, and other workloads are untouched. + expect(withT1CrossingCheck(pass, plan, line(T1_TICKS), [fault("t02", START + 40)]).verdict).toBe("fail"); + expect(withT1CrossingCheck(pass, { ...plan, workload: "A1" }, null, [])).toBe(pass); + }); + + it("prints the loop's own clock window", () => { + expect(t1Command(NONCE)).toContain("start=$s end=$(date +%s)"); + }); +}); + +describe("hold options in --matrix", () => { + it("plans the requested K15 and TM1 holds for matrix cells", () => { + const parsed = parseCommand(["--matrix", "--workloads", "T1", "--adapters", "codex", "--faults", "K15,TM1", + "--k15-hold-seconds", "300", "--tm1-hold-seconds", "100", "--seed", "5"]); + if (parsed.mode !== "wave") throw new Error("expected a wave"); + const cells = planMatrixTasks(parsed.options); + expect(cells.filter(cell => cell.fault === "K15").every(cell => cell.holdMs === 300_000)).toBe(true); + expect(cells.filter(cell => cell.fault === "TM1").every(cell => cell.holdMs === 100_000)).toBe(true); + expect(cells.some(cell => cell.fault === "K15") && cells.some(cell => cell.fault === "TM1")).toBe(true); }); }); @@ -114,4 +151,19 @@ describe("Daytona Runner log capture", () => { secrets: [], client: { async *list() { throw new Error("list failed"); }, get } }); expect(failed.error).toBe("list failed"); }); + + it("stops at one deadline for the whole capture, so the outage it runs in does not grow", async () => { + const outDir = await mkdtemp(path.join(os.tmpdir(), "runner-logs-")); + const labels = { "paperclip-company-id": COMPANY, "paperclip-environment-id": ENVIRONMENT }; + const hung = { async *list() { yield { id: "slow", state: "started", labels }; }, + get: () => new Promise(() => { /* a Daytona API that never answers */ }) }; + const started = Date.now(); + const capture = await captureWaveRunnerLogs({ apiKey: "unused", companyId: COMPANY, environmentId: ENVIRONMENT, outDir, + label: "f03-stopped", secrets: [], client: hung, deadlineMs: 200 }); + expect(Date.now() - started).toBeLessThan(2_000); + expect(capture.deadlineExceeded).toBe(true); + expect(capture.error).toMatch(/deadline 200 ms exceeded/); + expect(JSON.parse(await readFile(path.join(outDir, "f03-stopped", "index.json"), "utf8")).deadlineExceeded).toBe(true); + expect(RUNNER_LOG_CAPTURE_DEADLINE_MS).toBeLessThanOrEqual(60_000); + }); }); diff --git a/tests/restart-chaos/main.ts b/tests/restart-chaos/main.ts index e8992b3ea10..86dcb0f05ec 100644 --- a/tests/restart-chaos/main.ts +++ b/tests/restart-chaos/main.ts @@ -39,6 +39,7 @@ import { TaskObserver, childSpeedTasksInTurn } from "./observer.js"; import { closeJourneyApps } from "./journey-driver.js"; import { matrixMayLaunch, planMatrixWave } from "./journey-matrix.js"; import { redeployWave } from "./redeploy.js"; +import { withT1CrossingCheck } from "./workloads.js"; import { captureWaveRunnerLogs } from "./daytona-runner-logs.js"; import { StormRun, TASK_FAULT_LOG, observedFaultSchedule, planWave, replayOnCurrentBuild, replayRecordFor, replayWave, type TaskFaultLog } from "./scheduler.js"; import { chaosLifecycleOverrides, seedChaosLab } from "./seed.js"; @@ -677,7 +678,9 @@ async function main(): Promise { const restart = faults.find(receipt => receipt.requestedBy === observer.plan.taskId && receipt.trigger === "provider"); const oracle = withProviderFaultCheck(graded, observer.plan, artifacts?.providerFaultEvents ?? [], restart?.startedAt ?? null, restart?.stoppedAt ?? restart?.startedAt ?? null); - const grade = gradeTask(observer.record, faults, observer.definition.budgetMs, oracle, universalByIssue ? { + // T1: a mid-tool fault only counts when one of the task's faults started while its loop ran (workloads.ts). + const toolOracle = withT1CrossingCheck(oracle, observer.plan, artifacts?.documents.brief, faults); + const grade = gradeTask(observer.record, faults, observer.definition.budgetMs, toolOracle, universalByIssue ? { runMessages: allRunMessages, recoveryActions: universalByIssue.get(observer.record.issueId ?? "")?.recoveryActions ?? [] } : undefined); let evidence: string | null = null; if (!grade.pass) { diff --git a/tests/restart-chaos/workloads.ts b/tests/restart-chaos/workloads.ts index c6eb772bcd1..4f79a08f139 100644 --- a/tests/restart-chaos/workloads.ts +++ b/tests/restart-chaos/workloads.ts @@ -46,8 +46,42 @@ export const f1LinkName = (nonce: string) => `hosts-link-${nonce}`; /** T1: ticks of the long tool (2 s each) and the line the agent reports after it finished. */ export const T1_TICKS = 50; export const t1Marker = (nonce: string) => `TICKS-${nonce}`; +/** Prints ` start= end=`: the loop's own clock window, so the harness can check a fault crossed it. */ export const t1Command = (nonce: string) => - `i=0; while [ $i -lt ${T1_TICKS} ]; do i=$((i+1)); echo tick-$i; sleep 2; done > ticks-${nonce}.txt; wc -l < ticks-${nonce}.txt`; + `s=$(date +%s); i=0; while [ $i -lt ${T1_TICKS} ]; do i=$((i+1)); echo tick-$i; sleep 2; done > ticks-${nonce}.txt;` + + ` echo "$(wc -l < ticks-${nonce}.txt | tr -d ' ') start=$s end=$(date +%s)"`; + +/** The brief's first line, `TICKS-= start= end=`, parsed; null when it does not match. */ +export function parseT1Report(nonce: string, brief: string | null | undefined): { ticks: number; startMs: number; endMs: number } | null { + const first = (brief ?? "").split(/\r?\n/).map(line => line.trim()).find(Boolean) ?? ""; + const match = new RegExp(`^${t1Marker(nonce)}=([0-9]+) start=([0-9]{9,11}) end=([0-9]{9,11})$`).exec(first); + if (!match) return null; + const [ticks, start, end] = [Number(match[1]), Number(match[2]) * 1000, Number(match[3]) * 1000]; + return end >= start ? { ticks, startMs: start, endMs: end } : null; +} + +/** Sandbox and host clocks are not the same clock: a fault this close to the loop's edges still counts as crossing it. */ +export const T1_CLOCK_SLACK_MS = 5_000; + +/** + * T1 tested a mid-tool fault only if one of the task's own faults started while the loop ran. A fault that landed + * during preparation, with the loop run afterwards, tested nothing mid-tool: the task fails `fault_crossed_tool`, + * as a provider-fault task whose fault never applied does. + */ +export function withT1CrossingCheck(oracle: OracleResult, plan: { taskId: string; workload: WorkloadId; nonce: string }, + brief: string | null | undefined, faults: ReadonlyArray<{ requestedBy: string; startedAt: number; faultId: string }>): OracleResult { + if (plan.workload !== "T1") return oracle; + const report = parseT1Report(plan.nonce, brief); + const own = faults.filter(fault => fault.requestedBy === plan.taskId); + const crossing = report ? own.filter(fault => fault.startedAt >= report.startMs - T1_CLOCK_SLACK_MS + && fault.startedAt <= report.endMs + T1_CLOCK_SLACK_MS) : []; + const check = { name: "fault_crossed_tool", ok: crossing.length > 0, + detail: report ? `loop ${new Date(report.startMs).toISOString()}..${new Date(report.endMs).toISOString()}; ` + + `faults ${own.map(fault => `${fault.faultId}@${new Date(fault.startedAt).toISOString()}`).join(",") || "none"}` + : "no loop window reported" }; + const checks = [...oracle.checks, check]; + return { ...oracle, checks, verdict: checks.every(entry => entry.ok) ? "pass" : "fail" }; +} /** F1: an `ls -l` line for that link: a symlink (`l` mode) naming the link and its absolute target. */ export const f1LinkListing = (nonce: string) => new RegExp(`^l\\S*\\s.*\\s${f1LinkName(nonce)} -> /etc/hosts$`); const benchFile = (nonce: string) => `bench-result-${nonce}.txt`; @@ -372,15 +406,16 @@ export const workloadDefinitions: Record = { description: nonce => [ "Run this exact shell command in your working directory as one tool call, in the foreground, and wait for it to finish", `(about 100 seconds; do not run it in the background): \`${t1Command(nonce)}\``, - `Then save this issue's document with key \`brief\` (title "Brief"). Its first line is \`${t1Marker(nonce)}=\`.`, + `Then save this issue's document with key \`brief\` (title "Brief"). Its first line is \`${t1Marker(nonce)}=\`.`, "Do not create other files or tasks. When the document is saved, mark this task done.", ].join("\n"), collect: { documents: ["brief"], files: () => [], commands: [] }, grade(nonce, artifacts) { + const report = parseT1Report(nonce, artifacts.documents.brief); const first = (artifacts.documents.brief ?? "").split(/\r?\n/).map(line => line.trim()).find(Boolean) ?? ""; return result([ statusCheck(artifacts), - { name: "tool_finished", ok: first === `${t1Marker(nonce)}=${T1_TICKS}`, detail: JSON.stringify(first.slice(0, 120)) }, + { name: "tool_finished", ok: report?.ticks === T1_TICKS, detail: JSON.stringify(first.slice(0, 120)) }, ]); }, },