mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-13 15:55:46 +01:00
test(restart-chaos): T1 proves the fault crossed the tool, capture deadline, matrix holds; record K15 and TM1 waves
Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
1 parent
f4f3b4e0f3
commit
3540bfe700
7 files changed
+204
-38
No files matched your search
@@ -307,3 +307,40 @@ What this shows:
|
|||||||
- The next scenario to build is **K15 with `--upgrade-from` on Daytona**: start with the older
|
- 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
|
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.
|
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/<wave>/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).
|
||||||
@@ -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.
|
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.
|
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
|
- **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
|
foreground for about 100 s (50 ticks of 2 s). The command prints the loop's
|
||||||
first line is `TICKS-<nonce>=50`. Its fault window (35–80 s after launch)
|
own clock window. The agent then saves `brief`, whose first line is
|
||||||
lands while the tool runs in the sandbox. The window stays short of provider
|
`TICKS-<nonce>=50 start=<epoch s> end=<epoch s>`. Its fault window (35–80 s
|
||||||
shell-tool timeouts.
|
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
|
- **Runner evidence:** on a Daytona K15 wave, the harness captures every
|
||||||
started sandbox of the wave three times:
|
started sandbox of the wave three times:
|
||||||
- right after the server stopped (`<fault>-stopped`);
|
- right after the server stopped (`<fault>-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
|
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.
|
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)
|
## Absolute symlink in the workspace (F1)
|
||||||
|
|
||||||
```sh
|
```sh
|
||||||
|
|||||||
@@ -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',
|
+ ' echo "== file $f $(stat -c "%s bytes, modified %y" "$f" 2>/dev/null)"; tail -c 24576 "$f"; echo; done',
|
||||||
].join("; ");
|
].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 {
|
export interface RunnerLogCapture {
|
||||||
label: string;
|
label: string;
|
||||||
observedAt: 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 }>;
|
sandboxes: Array<{ id: string; name: string | null; state: string | null; file: string | null; exitCode: number | null; error: string | null }>;
|
||||||
error: string | null;
|
error: string | null;
|
||||||
}
|
}
|
||||||
@@ -60,36 +65,56 @@ export function probeableSandbox(sandbox: DaytonaSandboxRow): boolean {
|
|||||||
*/
|
*/
|
||||||
export async function captureWaveRunnerLogs(input: {
|
export async function captureWaveRunnerLogs(input: {
|
||||||
apiKey: string; companyId: string; environmentId: string; outDir: string; label: string; secrets: readonly string[];
|
apiKey: string; companyId: string; environmentId: string; outDir: string; label: string; secrets: readonly string[];
|
||||||
client?: ProbeClient; timeoutSeconds?: number;
|
client?: ProbeClient; timeoutSeconds?: number; deadlineMs?: number;
|
||||||
}): Promise<RunnerLogCapture> {
|
}): Promise<RunnerLogCapture> {
|
||||||
const label = captureDirectoryName(input.label);
|
const label = captureDirectoryName(input.label);
|
||||||
const capture: RunnerLogCapture = { label, observedAt: new Date().toISOString(), sandboxes: [], error: null };
|
const capture: RunnerLogCapture = { label, observedAt: new Date().toISOString(), sandboxes: [], error: null };
|
||||||
const directory = path.join(input.outDir, label);
|
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 = <T>(step: Promise<T>) => Promise.race([step, deadline]);
|
||||||
try {
|
try {
|
||||||
await mkdir(directory, { recursive: true, mode: 0o700 });
|
const outcome = await withinDeadline(probeWave());
|
||||||
const client = input.client ?? await createRemoteFixtureClient(input.apiKey) as unknown as ProbeClient;
|
if (outcome === "deadline") {
|
||||||
const wave = { companyId: input.companyId, environmentId: input.environmentId };
|
capture.deadlineExceeded = true;
|
||||||
const rows: DaytonaSandboxRow[] = [];
|
capture.error = `capture deadline ${deadlineMs} ms exceeded`;
|
||||||
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);
|
|
||||||
}
|
|
||||||
}
|
}
|
||||||
} catch (error) {
|
} finally {
|
||||||
capture.error = error instanceof Error ? error.message : String(error);
|
clearTimeout(timer);
|
||||||
}
|
}
|
||||||
try {
|
try {
|
||||||
await writeFile(path.join(directory, "index.json"), `${JSON.stringify(capture, null, 2)}\n`, { mode: 0o600 });
|
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 */ }
|
} catch { /* the directory itself failed; the returned record still carries the error */ }
|
||||||
return capture;
|
return capture;
|
||||||
|
|
||||||
|
async function probeWave(): Promise<void> {
|
||||||
|
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);
|
||||||
|
}
|
||||||
|
}
|
||||||
}
|
}
|
||||||
@@ -10,6 +10,7 @@
|
|||||||
* share the server with a fault cell (`matrixMayLaunch`).
|
* share the server with a fault cell (`matrixMayLaunch`).
|
||||||
*/
|
*/
|
||||||
import path from "node:path";
|
import path from "node:path";
|
||||||
|
import { k15HoldMs } from "./redeploy.js";
|
||||||
import { WORKLOAD_TRIGGERS } from "./journeys.js";
|
import { WORKLOAD_TRIGGERS } from "./journeys.js";
|
||||||
import { withProviderFaultRules } from "./provider-faults.js";
|
import { withProviderFaultRules } from "./provider-faults.js";
|
||||||
import { createRng, k4HoldRange, TRIGGER_DELAY_RANGE_MS } from "./scheduler.js";
|
import { createRng, k4HoldRange, TRIGGER_DELAY_RANGE_MS } from "./scheduler.js";
|
||||||
@@ -43,7 +44,7 @@ export function matrixMayLaunch(next: Pick<TaskPlan, "fault">, inFlight: Readonl
|
|||||||
return inFlight.every(task => (task.fault === "K0") === baseline);
|
return inFlight.every(task => (task.fault === "K0") === baseline);
|
||||||
}
|
}
|
||||||
|
|
||||||
export function planMatrixTasks(options: Pick<WaveOptions, "seed" | "workloads" | "adapters" | "faults" | "providerFaults" | "k4HoldMaxMs" | "faultAfterMs" | "rrGapMs">): TaskPlan[] {
|
export function planMatrixTasks(options: Pick<WaveOptions, "seed" | "workloads" | "adapters" | "faults" | "providerFaults" | "k4HoldMaxMs" | "k15HoldMs" | "tm1HoldMs" | "faultAfterMs" | "rrGapMs">): TaskPlan[] {
|
||||||
const rng = createRng((options.seed ^ 0x6a6d7478) >>> 0);
|
const rng = createRng((options.seed ^ 0x6a6d7478) >>> 0);
|
||||||
return matrixCells(options).map((cell, index) => {
|
return matrixCells(options).map((cell, index) => {
|
||||||
const definition = workloadDefinitions[cell.workload];
|
const definition = workloadDefinitions[cell.workload];
|
||||||
@@ -58,8 +59,10 @@ export function planMatrixTasks(options: Pick<WaveOptions, "seed" | "workloads"
|
|||||||
...(cell.trigger === "time" ? {} : { trigger: cell.trigger, triggerDelayMs: rng.int(...TRIGGER_DELAY_RANGE_MS[cell.trigger]) }),
|
...(cell.trigger === "time" ? {} : { trigger: cell.trigger, triggerDelayMs: rng.int(...TRIGGER_DELAY_RANGE_MS[cell.trigger]) }),
|
||||||
// `--fault-after-seconds` pins time-fired restarts, as it does outside the matrix.
|
// `--fault-after-seconds` pins time-fired restarts, as it does outside the matrix.
|
||||||
fireAfterMs: cell.fault === "K0" || cell.fault.startsWith("PV") ? 0 : cell.trigger === "time" ? options.faultAfterMs ?? drawn : drawn,
|
fireAfterMs: cell.fault === "K0" || cell.fault.startsWith("PV") ? 0 : cell.trigger === "time" ? options.faultAfterMs ?? drawn : drawn,
|
||||||
holdMs: cell.fault === "K4" ? rng.int(...k4HoldRange(options.k4HoldMaxMs)) : isTimeFault(cell.fault) ? timeFaultHoldMs(cell.fault, rng.int)
|
holdMs: cell.fault === "K4" ? rng.int(...k4HoldRange(options.k4HoldMaxMs))
|
||||||
: isMultiServerFault(cell.fault) ? multiServerHoldMs(cell.fault, rng.int) : 0,
|
: isTimeFault(cell.fault) ? timeFaultHoldMs(cell.fault, rng.int, options.tm1HoldMs)
|
||||||
|
: isMultiServerFault(cell.fault) ? multiServerHoldMs(cell.fault, rng.int)
|
||||||
|
: cell.fault === "K15" ? k15HoldMs(options.k15HoldMs, rng.int) : 0,
|
||||||
...(isRepeatedRestartFault(cell.fault) ? { restartSteps: planRestartSteps(cell.fault, rng.int, options.rrGapMs) } : {}),
|
...(isRepeatedRestartFault(cell.fault) ? { restartSteps: planRestartSteps(cell.fault, rng.int, options.rrGapMs) } : {}),
|
||||||
followUpAfterMs: definition.followUpWindowMs ? rng.int(definition.followUpWindowMs[0], definition.followUpWindowMs[1]) : null,
|
followUpAfterMs: definition.followUpWindowMs ? rng.int(definition.followUpWindowMs[0], definition.followUpWindowMs[1]) : null,
|
||||||
nonce: rng.hex(8),
|
nonce: rng.hex(8),
|
||||||
|
|||||||
@@ -3,12 +3,13 @@ import os from "node:os";
|
|||||||
import path from "node:path";
|
import path from "node:path";
|
||||||
import { describe, expect, it, vi } from "vitest";
|
import { describe, expect, it, vi } from "vitest";
|
||||||
import { parseCommand } from "./config.js";
|
import { parseCommand } from "./config.js";
|
||||||
import { RUNNER_LOG_PROBE, captureDirectoryName, captureWaveRunnerLogs, probeableSandbox } from "./daytona-runner-logs.js";
|
import { RUNNER_LOG_CAPTURE_DEADLINE_MS, RUNNER_LOG_PROBE, captureDirectoryName, captureWaveRunnerLogs, probeableSandbox } from "./daytona-runner-logs.js";
|
||||||
import { WORKLOAD_TRIGGERS } from "./journeys.js";
|
import { WORKLOAD_TRIGGERS } from "./journeys.js";
|
||||||
import { K15_MAX_HOLD_SECONDS } from "./redeploy.js";
|
import { K15_MAX_HOLD_SECONDS } from "./redeploy.js";
|
||||||
import { planStorm, planTasks } from "./scheduler.js";
|
import { planStorm, planTasks } from "./scheduler.js";
|
||||||
import type { OracleArtifacts } from "./types.js";
|
import type { OracleArtifacts } from "./types.js";
|
||||||
import { T1_TICKS, t1Command, t1Marker, workloadDefinitions } from "./workloads.js";
|
import { T1_CLOCK_SLACK_MS, T1_TICKS, parseT1Report, t1Command, t1Marker, withT1CrossingCheck, workloadDefinitions } from "./workloads.js";
|
||||||
|
import { planMatrixTasks } from "./journey-matrix.js";
|
||||||
|
|
||||||
const IMAGE = `ghcr.io/paperclipai/paperclip-daytona-runner@sha256:${"c".repeat(64)}`;
|
const IMAGE = `ghcr.io/paperclipai/paperclip-daytona-runner@sha256:${"c".repeat(64)}`;
|
||||||
const COMPANY = "11111111-1111-4111-8111-111111111111";
|
const COMPANY = "11111111-1111-4111-8111-111111111111";
|
||||||
@@ -60,11 +61,47 @@ describe("T1: long shell tool in the agent's workspace", () => {
|
|||||||
expect(defaults.mode === "wave" && defaults.options.workloads).not.toContain("T1");
|
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", () => {
|
const START = 1_794_370_000;
|
||||||
expect(t1.grade(NONCE, done(`${t1Marker(NONCE)}=${T1_TICKS}\nmore`)).verdict).toBe("pass");
|
const line = (ticks: number, start = START, end = START + 100) => `${t1Marker(NONCE)}=${ticks} start=${start} end=${end}`;
|
||||||
expect(t1.grade(NONCE, done(`${t1Marker(NONCE)}=49`)).verdict).toBe("fail");
|
|
||||||
|
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("")).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 } });
|
secrets: [], client: { async *list() { throw new Error("list failed"); }, get } });
|
||||||
expect(failed.error).toBe("list failed");
|
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<never>(() => { /* 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);
|
||||||
|
});
|
||||||
});
|
});
|
||||||
@@ -39,6 +39,7 @@ import { TaskObserver, childSpeedTasksInTurn } from "./observer.js";
|
|||||||
import { closeJourneyApps } from "./journey-driver.js";
|
import { closeJourneyApps } from "./journey-driver.js";
|
||||||
import { matrixMayLaunch, planMatrixWave } from "./journey-matrix.js";
|
import { matrixMayLaunch, planMatrixWave } from "./journey-matrix.js";
|
||||||
import { redeployWave } from "./redeploy.js";
|
import { redeployWave } from "./redeploy.js";
|
||||||
|
import { withT1CrossingCheck } from "./workloads.js";
|
||||||
import { captureWaveRunnerLogs } from "./daytona-runner-logs.js";
|
import { captureWaveRunnerLogs } from "./daytona-runner-logs.js";
|
||||||
import { StormRun, TASK_FAULT_LOG, observedFaultSchedule, planWave, replayOnCurrentBuild, replayRecordFor, replayWave, type TaskFaultLog } from "./scheduler.js";
|
import { StormRun, TASK_FAULT_LOG, observedFaultSchedule, planWave, replayOnCurrentBuild, replayRecordFor, replayWave, type TaskFaultLog } from "./scheduler.js";
|
||||||
import { chaosLifecycleOverrides, seedChaosLab } from "./seed.js";
|
import { chaosLifecycleOverrides, seedChaosLab } from "./seed.js";
|
||||||
@@ -677,7 +678,9 @@ async function main(): Promise<number> {
|
|||||||
const restart = faults.find(receipt => receipt.requestedBy === observer.plan.taskId && receipt.trigger === "provider");
|
const restart = faults.find(receipt => receipt.requestedBy === observer.plan.taskId && receipt.trigger === "provider");
|
||||||
const oracle = withProviderFaultCheck(graded, observer.plan, artifacts?.providerFaultEvents ?? [], restart?.startedAt ?? null,
|
const oracle = withProviderFaultCheck(graded, observer.plan, artifacts?.providerFaultEvents ?? [], restart?.startedAt ?? null,
|
||||||
restart?.stoppedAt ?? 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);
|
runMessages: allRunMessages, recoveryActions: universalByIssue.get(observer.record.issueId ?? "")?.recoveryActions ?? [] } : undefined);
|
||||||
let evidence: string | null = null;
|
let evidence: string | null = null;
|
||||||
if (!grade.pass) {
|
if (!grade.pass) {
|
||||||
|
|||||||
@@ -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. */
|
/** 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 T1_TICKS = 50;
|
||||||
export const t1Marker = (nonce: string) => `TICKS-${nonce}`;
|
export const t1Marker = (nonce: string) => `TICKS-${nonce}`;
|
||||||
|
/** Prints `<ticks> start=<epoch s> end=<epoch s>`: the loop's own clock window, so the harness can check a fault crossed it. */
|
||||||
export const t1Command = (nonce: string) =>
|
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-<nonce>=<ticks> start=<s> end=<s>`, 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. */
|
/** 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$`);
|
export const f1LinkListing = (nonce: string) => new RegExp(`^l\\S*\\s.*\\s${f1LinkName(nonce)} -> /etc/hosts$`);
|
||||||
const benchFile = (nonce: string) => `bench-result-${nonce}.txt`;
|
const benchFile = (nonce: string) => `bench-result-${nonce}.txt`;
|
||||||
@@ -372,15 +406,16 @@ export const workloadDefinitions: Record<WorkloadId, WorkloadDefinition> = {
|
|||||||
description: nonce => [
|
description: nonce => [
|
||||||
"Run this exact shell command in your working directory as one tool call, in the foreground, and wait for it to finish",
|
"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)}\``,
|
`(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)}=<the number the command printed>\`.`,
|
`Then save this issue's document with key \`brief\` (title "Brief"). Its first line is \`${t1Marker(nonce)}=<the exact line the command printed>\`.`,
|
||||||
"Do not create other files or tasks. When the document is saved, mark this task done.",
|
"Do not create other files or tasks. When the document is saved, mark this task done.",
|
||||||
].join("\n"),
|
].join("\n"),
|
||||||
collect: { documents: ["brief"], files: () => [], commands: [] },
|
collect: { documents: ["brief"], files: () => [], commands: [] },
|
||||||
grade(nonce, artifacts) {
|
grade(nonce, artifacts) {
|
||||||
|
const report = parseT1Report(nonce, artifacts.documents.brief);
|
||||||
const first = (artifacts.documents.brief ?? "").split(/\r?\n/).map(line => line.trim()).find(Boolean) ?? "";
|
const first = (artifacts.documents.brief ?? "").split(/\r?\n/).map(line => line.trim()).find(Boolean) ?? "";
|
||||||
return result([
|
return result([
|
||||||
statusCheck(artifacts),
|
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)) },
|
||||||
]);
|
]);
|
||||||
},
|
},
|
||||||
},
|
},
|
||||||
|
|||||||
Reference in new issue
Block a user