diff --git a/.github/scripts/pr-proof-budgets.test.mjs b/.github/scripts/pr-proof-budgets.test.mjs new file mode 100644 index 0000000000..7af3c43282 --- /dev/null +++ b/.github/scripts/pr-proof-budgets.test.mjs @@ -0,0 +1,53 @@ +import assert from "node:assert/strict"; +import { readFileSync } from "node:fs"; +import { test } from "node:test"; +import { BUILD_TIMING, PREPARE_BUDGET_ENV } from "../../packages/daytona-evidence/src/build-budget.ts"; + +// A job is cancelled at its timeout with no output. Every job that prepares an +// evidence world must give that preparation a budget that ends before its step +// does, and the step plus the steps after it must end before the job does, so +// a slow or stuck shared build fails with a diagnosis instead. +const workflow = readFileSync(new URL("../workflows/pr-proof.yml", import.meta.url), "utf8"); +/** Minutes allowed for checkout, installs and uploads around the timed steps. */ +const UNTIMED_STEPS_MINUTES = 2; + +function jobs() { + const body = workflow.split("\njobs:\n")[1] ?? ""; + return body.split(/\n(?= [a-z][a-z0-9-]*:\n)/).map((block) => ({ name: block.match(/^ {2}([a-z][a-z0-9-]*):/)?.[1] ?? "", block })); +} + +function steps(block) { + return block.split(/\n(?= {6}- )/).slice(1); +} + +function minutes(text, indent) { + const value = text.match(new RegExp(`\\n {${indent}}timeout-minutes: (\\d+)\\n`))?.[1]; + return value === undefined ? undefined : Number(value); +} + +const preparing = jobs().filter(({ block }) => block.includes("node scripts/prepare-evidence-web.ts")); + +test("every job that prepares an evidence world is checked", () => { + assert.ok(preparing.length >= 2, `expected the core and checkpoint jobs, found ${preparing.map((job) => job.name).join(", ")}`); +}); + +for (const { name, block } of preparing) { + test(`${name}: the preparation budget < its step < the job`, () => { + const jobMinutes = minutes(block, 4); + assert.ok(jobMinutes, `${name} needs a numeric timeout-minutes`); + const all = steps(block); + const prepare = all.find((step) => step.includes("node scripts/prepare-evidence-web.ts")); + assert.ok(prepare); + const stepMinutes = minutes(`\n${prepare}`, 8); + assert.ok(stepMinutes, `${name}: the preparation step needs timeout-minutes`); + const budget = Number(prepare.match(new RegExp(`\\n {10}${PREPARE_BUDGET_ENV}: '?(\\d+)'?\\n`))?.[1]); + assert.ok(Number.isFinite(budget) && budget > 0, `${name}: the preparation step must set ${PREPARE_BUDGET_ENV}`); + // Waits stop BUILD_TIMING.reserveMs before the budget; the budget itself + // ends a minute before the step so a diagnosis and cleanup still print. + assert.ok(budget * 60_000 > BUILD_TIMING.reserveMs, `${name}: the budget must exceed the diagnosis reserve`); + assert.ok(budget + 1 <= stepMinutes, `${name}: budget ${budget} min must end at least a minute before the step's ${stepMinutes} min`); + const timed = all.reduce((sum, step) => sum + (minutes(`\n${step}`, 8) ?? 0), 0); + assert.ok(timed + UNTIMED_STEPS_MINUTES <= jobMinutes, + `${name}: timed steps (${timed} min) plus ${UNTIMED_STEPS_MINUTES} min of setup must fit the job's ${jobMinutes} min`); + }); +} diff --git a/.github/workflows/ci-tests.yml b/.github/workflows/ci-tests.yml index 31e98600f5..0b6cf48e7f 100644 --- a/.github/workflows/ci-tests.yml +++ b/.github/workflows/ci-tests.yml @@ -127,7 +127,7 @@ jobs: - name: Test fork authorization and free screening policy run: node --test .github/scripts/contributor-pr.test.mjs .github/scripts/contributor-screen.test.mjs .github/scripts/warden-check.test.mjs .github/scripts/warden-report.test.mjs .github/scripts/warden-fast.test.mjs .github/scripts/setup-browser.test.mjs - name: Test on-demand PR proof review builds - run: node --test .github/scripts/pr-proof-review-build.test.mjs .github/scripts/pr-proof-artifacts.test.mjs evals/scripts/engine-parity-binaries.test.mjs evals/scripts/run-parity-proof.test.mjs + run: node --test .github/scripts/pr-proof-review-build.test.mjs .github/scripts/pr-proof-artifacts.test.mjs .github/scripts/pr-proof-budgets.test.mjs evals/scripts/engine-parity-binaries.test.mjs evals/scripts/run-parity-proof.test.mjs - name: Test desktop and cloud computer access and interruption run: | pnpm --filter @openwork/computer-use build diff --git a/.github/workflows/pr-proof.yml b/.github/workflows/pr-proof.yml index 61576a2e14..adb1606dcf 100644 --- a/.github/workflows/pr-proof.yml +++ b/.github/workflows/pr-proof.yml @@ -97,13 +97,17 @@ jobs: run: | pnpm --filter @openwork/freestyle... --filter @openwork/daytona-evidence... --filter @openwork/review... --filter @openwork/world... --filter @openwork/types... --filter @openwork/sdk... install --frozen-lockfile --ignore-scripts --prefer-offline pnpm --dir evals install --frozen-lockfile --ignore-scripts --prefer-offline + # Budgets nest: the preparation's own budget < this step < the job, so + # a slow shared image build fails with what it waited on instead of the + # job being cancelled silently (.github/scripts/pr-proof-budgets.test.mjs). - name: Prepare this commit's evidence world - timeout-minutes: 35 + timeout-minutes: 13 env: FREESTYLE_API_KEY: ${{ secrets.FREESTYLE_API_KEY }} DAYTONA_API_KEY: ${{ secrets.DAYTONA_API_KEY }} OPENWORK_EVIDENCE_SOURCE_SHA: ${{ github.event.pull_request.head.sha }} OPENWORK_PREVIEW_GITHUB_TOKEN: ${{ github.token }} + OPENWORK_EVIDENCE_PREPARE_BUDGET_MINUTES: '11' run: node scripts/prepare-evidence-web.ts - name: Run the core journey and save its end state as the preview timeout-minutes: 15 @@ -401,12 +405,13 @@ jobs: - name: Build this branch's review app run: pnpm --filter @openwork/review-app build - name: Prepare this branch's isolated web world - timeout-minutes: 35 + timeout-minutes: 30 env: FREESTYLE_API_KEY: ${{ secrets.FREESTYLE_API_KEY }} DAYTONA_API_KEY: ${{ secrets.DAYTONA_API_KEY }} OPENWORK_EVIDENCE_SOURCE_SHA: ${{ github.event.pull_request.head.sha }} OPENWORK_PREVIEW_GITHUB_TOKEN: ${{ github.token }} + OPENWORK_EVIDENCE_PREPARE_BUDGET_MINUTES: '28' run: node scripts/prepare-evidence-web.ts # Specs tagged "checkpoints" run here because the Freestyle credential is # protected. Their records join this PR's normal evidence report; the shared diff --git a/.opencode/skills/diagnose-a-red-run/SKILL.md b/.opencode/skills/diagnose-a-red-run/SKILL.md index a3264cdc73..ec162a9ea9 100644 --- a/.opencode/skills/diagnose-a-red-run/SKILL.md +++ b/.opencode/skills/diagnose-a-red-run/SKILL.md @@ -50,6 +50,10 @@ git worktree remove /tmp/openwork-dev-control - World preparation failed: read the "builder log" group in the job log; it is the VM's own build or boot output. A fast path that fails falls back to a full build by itself, so a red here is a real build or boot failure. +- "was not ready within this job's N min preparation budget": another run (often + the dev warm-up after a dependency change) holds that shared Daytona layer. + The `waiting` lines and the message name its builder, state, commit and when + its controller gives up. Not caused by the PR: rerun once that build finishes. - Journey failed: the timeout prints the on-screen state. Reproduce with the `run-tests` core journey command on the same pushed commit. diff --git a/packages/daytona-evidence/src/api.ts b/packages/daytona-evidence/src/api.ts index 93cb3b671d..86fd4001c5 100644 --- a/packages/daytona-evidence/src/api.ts +++ b/packages/daytona-evidence/src/api.ts @@ -229,14 +229,16 @@ export class DaytonaApi { catch (error) { if (error instanceof DaytonaApiError && error.status === 404) return null; throw error; } } - async waitForSnapshot(name: string, timeoutMs = 20 * 60_000): Promise { + /** `onPending` sees each poll that is not done yet, for progress output. */ + async waitForSnapshot(name: string, timeoutMs = 20 * 60_000, onPending?: (snapshot: Snapshot | null) => void): Promise { const deadline = Date.now() + timeoutMs; for (;;) { const snapshot = await this.getSnapshot(name); if (snapshot?.state === "active") return snapshot; if (snapshot && /error|fail/.test(snapshot.state)) throw new Error(`Daytona snapshot ${name} is ${snapshot.state}: ${snapshot.errorReason ?? "no reason given"}`); - if (Date.now() > deadline) throw new Error(`Daytona snapshot ${name} is still ${snapshot?.state ?? "missing"}`); - await delay(3_000); + if (Date.now() > deadline) throw new Error(`Daytona snapshot ${name} is still ${snapshot?.state ?? "missing"} after ${Math.round(timeoutMs / 1000)}s`); + onPending?.(snapshot); + await delay(Math.max(0, Math.min(3_000, deadline - Date.now()))); } } diff --git a/packages/daytona-evidence/src/build-budget.test.ts b/packages/daytona-evidence/src/build-budget.test.ts new file mode 100644 index 0000000000..dcb26a4483 --- /dev/null +++ b/packages/daytona-evidence/src/build-budget.test.ts @@ -0,0 +1,171 @@ +import assert from "node:assert/strict"; +import { test } from "node:test"; +import { DaytonaApi, type Sandbox } from "./api.ts"; +import { BUILD_TIMING, buildBudget, builderIsStale, deadlineFromEnv, describeBuilder, progressReporter, type BuildClock, type BuildProgress } from "./build-budget.ts"; +import { ensureLayer, runScript } from "./builder.ts"; + +const MINUTE = 60_000; +const START = Date.parse("2026-10-24T01:21:33Z"); + +/** A clock that only moves when the code under test sleeps or a provider call takes time. */ +function fakeClock(start = START): BuildClock & { advance(ms: number): void; slept: number[] } { + let now = start; + const slept: number[] = []; + return { + now: () => now, + sleep: async (ms) => { slept.push(ms); now += ms; }, + advance: (ms) => { now += ms; }, + slept, + }; +} + +function fakeApi(overrides: Partial = {}) { + return Object.assign(new DaytonaApi({ apiKey: "k", apiUrl: "https://x.test/api", region: "r" }, async () => { + throw new Error("unexpected provider call"); + }), overrides); +} + +function builder(overrides: Partial = {}, labels: Record = {}): Sandbox { + return { id: "builder-id", name: "ow-dy-build-abc", state: "started", createdAt: new Date(START - 2 * MINUTE).toISOString(), + labels: { kind: "openwork-daytona-builder-v1", layer: "abc", devSha: "b".repeat(40), ...labels }, ...overrides }; +} + +function layer(options: Parameters[1]["options"], events: string[] = []) { + return { name: "ow-dy-evidence-image-v1-test", stage: "daytona-image", withMemory: false, options, + parent: async () => { events.push("parent"); return "base"; }, + prepare: async () => { events.push("prepare"); }, + observe: (event: { stage: string }) => { events.push(event.stage); } }; +} + +test("the budget ends waits a reserve before its deadline and caps every limit inside it", () => { + const clock = fakeClock(); + const budget = buildBudget({ deadline: START + 11 * MINUTE, clock }); + assert.equal(budget.waitUntil, START + 11 * MINUTE - BUILD_TIMING.reserveMs); + assert.equal(budget.cap(25 * MINUTE), 9 * MINUTE); + assert.equal(budget.cap(MINUTE), MINUTE); + clock.advance(10 * MINUTE); + assert.equal(budget.remaining(), 0); + assert.equal(budget.cap(5 * MINUTE), 0); + // No caller budget: the old per-layer limit. + assert.equal(buildBudget({ clock }).deadline, clock.now() + BUILD_TIMING.defaultBudgetMs); +}); + +test("a CI step's budget comes from the environment and must leave room for a diagnosis", () => { + assert.equal(deadlineFromEnv({}, START), undefined); + assert.equal(deadlineFromEnv({ OPENWORK_EVIDENCE_PREPARE_BUDGET_MINUTES: "11" }, START), START + 11 * MINUTE); + assert.throws(() => deadlineFromEnv({ OPENWORK_EVIDENCE_PREPARE_BUDGET_MINUTES: "soon" }, START), /positive number/); + assert.throws(() => deadlineFromEnv({ OPENWORK_EVIDENCE_PREPARE_BUDGET_MINUTES: "1" }, START), /diagnosis/); +}); + +test("a builder is stale once its controller is past the deadline it recorded, or after an hour without one", () => { + const now = START; + assert.equal(builderIsStale(builder({}, { deadline: String(now + MINUTE) }), now), false); + assert.equal(builderIsStale(builder({}, { deadline: String(now - BUILD_TIMING.staleGraceMs + 1) }), now), false); + assert.equal(builderIsStale(builder({}, { deadline: String(now - BUILD_TIMING.staleGraceMs - 1) }), now), true); + assert.equal(builderIsStale(builder({ createdAt: new Date(now - 59 * MINUTE).toISOString() }), now), false); + assert.equal(builderIsStale(builder({ createdAt: new Date(now - 61 * MINUTE).toISOString() }), now), true); + for (const state of ["error", "build_failed", "stopped", "archived"]) assert.equal(builderIsStale(builder({ state }), now), true); + assert.deepEqual(describeBuilder(builder({}, { deadline: String(now + 3 * MINUTE), sourceSha: "c".repeat(40), secret: "x" }), now), { + name: "ow-dy-build-abc", state: "started", ageMs: 2 * MINUTE, ownerDeadlineInMs: 3 * MINUTE, + labels: { layer: "abc", devSha: "b".repeat(40), sourceSha: "c".repeat(40) }, + }); +}); + +test("progress is reported at most once per interval for each kind of wait", () => { + const clock = fakeClock(); + const events: BuildProgress[] = []; + const report = progressReporter(buildBudget({ deadline: START + 11 * MINUTE, clock }), (event) => events.push(event)); + report({ stage: "daytona-image", waiting: "builder" }); + report({ stage: "daytona-image", waiting: "builder" }); + report({ stage: "daytona-image", waiting: "snapshot" }); + clock.advance(BUILD_TIMING.progressEveryMs); + report({ stage: "daytona-image", waiting: "builder" }); + assert.deepEqual(events.map((event) => [event.waiting, event.elapsedMs, event.remainingMs]), [ + ["builder", 0, 11 * MINUTE], ["snapshot", 0, 11 * MINUTE], ["builder", 30_000, 11 * MINUTE - 30_000], + ]); +}); + +test("waiting on another controller's builder reports progress and fails with a diagnosis before the step limit", async () => { + // The incident: a dependency change on dev, one job holding the image builder + // for its whole run, everyone else waiting on it with no output. + const clock = fakeClock(); + const owner = builder({}, { deadline: String(START + 28 * MINUTE) }); + const progress: BuildProgress[] = []; + const diagnostics: Array<[string, string]> = []; + const api = fakeApi({ + getSnapshot: async () => null, + getSandbox: async (name) => { assert.match(name, /^ow-dy-build-/); clock.advance(1_000); return owner; }, + exec: async (_vm, command) => ({ exitCode: 0, output: command.startsWith("tail") ? "ERR_PNPM_FETCH_404 while installing" : "" }), + deleteSandbox: async () => { assert.fail("a live builder within its own deadline is never taken over"); }, + }); + const deadline = START + 11 * MINUTE; + await assert.rejects(ensureLayer(api, layer({ deadline, clock, progress: (event) => progress.push(event), + diagnostic: async (stage, log) => { diagnostics.push([stage, log]); } })), + (error: Error) => { + assert.match(error.message, /daytona-image was not ready within this job's 11 min preparation budget/); + assert.match(error.message, /builder ow-dy-build-abc \(state started, created 11 min ago, building bbbbbbbbb, its controller gives up in 19 min\)/); + return true; + }); + // Stopped waiting at the reserve, not at the deadline or after it. + assert.ok(clock.now() <= deadline - BUILD_TIMING.reserveMs + 6_000, `stopped at ${clock.now() - START} ms`); + // A line at least every 30 s while waiting, each naming the builder. + assert.ok(progress.length >= (9 * MINUTE) / BUILD_TIMING.progressEveryMs - 1, `${progress.length} progress lines`); + assert.ok(progress.every((event) => event.waiting === "builder" && event.builder?.name === "ow-dy-build-abc")); + // The wait summary and the builder's classified private log tail. + assert.deepEqual(diagnostics.map(([stage]) => stage), ["daytona-image-wait", "daytona-image"]); + assert.equal(JSON.parse(diagnostics[0]?.[1] ?? "{}").builder.state, "started"); + assert.deepEqual(JSON.parse(diagnostics[1]?.[1] ?? "{}").events, ["dependency"]); +}); + +test("a builder abandoned by a cancelled job is taken over once its recorded deadline has passed", async () => { + const clock = fakeClock(); + const events: string[] = []; + let owner: Sandbox | null = builder({}, { deadline: String(START - BUILD_TIMING.staleGraceMs - 1) }); + const created: Array> = []; + let snapshot: { id: string; name: string; state: string } | null = null; + const api = fakeApi({ + getSnapshot: async () => snapshot, + getSandbox: async () => owner, + deleteSandbox: async (id) => { events.push(`delete ${id}`); if (id === "builder-id") owner = null; }, + createSandbox: async (input) => { created.push(input.labels); return builder({ id: "mine" }); }, + waitForSandbox: async (_id, states, timeoutMs) => { assert.ok((timeoutMs ?? 0) <= 9 * MINUTE); return builder({ id: "mine", state: states[0] ?? "started" }); }, + execChecked: async () => "", + stopSandbox: async () => undefined, + snapshotSandbox: async (_id, _name, _memory, retry) => { assert.ok((retry?.timeoutMs ?? Infinity) <= 9 * MINUTE); }, + waitForSnapshot: async (name, timeoutMs) => { assert.ok((timeoutMs ?? Infinity) <= 9 * MINUTE); snapshot = { id: name, name, state: "active" }; return snapshot; }, + }); + assert.equal(await ensureLayer(api, layer({ deadline: START + 11 * MINUTE, clock }, events)), "ow-dy-evidence-image-v1-test"); + assert.deepEqual(events.slice(0, 3), ["delete builder-id", "parent", "prepare"]); + // This controller records when it will have given up, for the next waiter. + assert.equal(created[0]?.deadline, String(START + 11 * MINUTE)); + assert.equal(events.at(-1), "delete mine"); +}); + +test("a build script stops at the preparation budget and says so, with the classified log", async () => { + const clock = fakeClock(); + const sandbox = builder({ id: "mine" }); + const reported: string[] = []; + const api = fakeApi({ + execChecked: async () => "", + writeFile: async () => undefined, + exec: async (_vm, command, timeout) => { + if (command.startsWith("if test")) { assert.ok((timeout ?? 120) <= 20); clock.advance(500); return { exitCode: 0, output: "building" }; } + return { exitCode: 0, output: "" }; + }, + }); + await assert.rejects(runScript(api, sandbox, "daytona-image", "true", { deadline: START + 11 * MINUTE, clock, + diagnostic: async (stage) => { reported.push(stage); } }), + /daytona-image was still building when this job's preparation budget ran out \(9 min of its 25 min limit\)/); + assert.ok(clock.now() <= START + 9 * MINUTE + 5_000); + assert.deepEqual(reported, ["daytona-image"]); +}); + +test("without a caller budget a build script keeps its own limit", async () => { + const clock = fakeClock(); + const api = fakeApi({ + execChecked: async () => "", writeFile: async () => undefined, + exec: async () => { clock.advance(1_000); return { exitCode: 0, output: "building" }; }, + }); + await assert.rejects(runScript(api, builder({ id: "mine" }), "daytona-base", "true", { clock }, 2 * MINUTE), /daytona-base exceeded 2 minutes/); + assert.ok(clock.now() >= START + 2 * MINUTE); +}); diff --git a/packages/daytona-evidence/src/build-budget.ts b/packages/daytona-evidence/src/build-budget.ts new file mode 100644 index 0000000000..f5630af117 --- /dev/null +++ b/packages/daytona-evidence/src/build-budget.ts @@ -0,0 +1,131 @@ +import { setTimeout as delay } from "node:timers/promises"; +import type { Sandbox } from "./api.ts"; + +/** Wall clock for build waits; tests pass a fake one. */ +export interface BuildClock { + now(): number; + sleep(ms: number): Promise; +} + +export const SYSTEM_CLOCK: BuildClock = { now: () => Date.now(), sleep: (ms) => delay(ms) }; + +/** + * Evidence world timing, in one place. A CI step that prepares a world passes + * its budget (OPENWORK_EVIDENCE_PREPARE_BUDGET_MINUTES) below its own + * `timeout-minutes`, and every wait inside stops `reserveMs` before that + * budget so the step fails with a diagnosis instead of being cancelled + * silently. `.github/scripts/pr-proof-budgets.test.mjs` checks the workflow + * numbers nest. + */ +export const BUILD_TIMING = Object.freeze({ + /** A preparation's limit when the caller sets no budget (the dev warm-up, previews). */ + defaultBudgetMs: 45 * 60_000, + /** Left before the deadline for one slow provider call, a bounded diagnostic and releasing the builder. */ + reserveMs: 2 * 60_000, + /** At most one "still waiting" line per wait this often. */ + progressEveryMs: 30_000, + /** A builder whose controller is this far past the deadline it recorded has been abandoned. */ + staleGraceMs: 2 * 60_000, + /** Builders from controllers that did not record a deadline. */ + legacyStaleBuilderMs: 60 * 60_000, +}); + +export const PREPARE_BUDGET_ENV = "OPENWORK_EVIDENCE_PREPARE_BUDGET_MINUTES"; + +export interface BuildBudget { + readonly clock: BuildClock; + /** When the caller's preparation must be over. */ + readonly deadline: number; + /** When waits stop, leaving the reserve for a diagnosis and cleanup. */ + readonly waitUntil: number; + readonly started: number; + /** Milliseconds a wait may still take; never negative. */ + remaining(): number; + /** `limitMs`, shortened so it ends by `waitUntil`. */ + cap(limitMs: number): number; +} + +export function buildBudget(input: { deadline?: number; clock?: BuildClock } = {}): BuildBudget { + const clock = input.clock ?? SYSTEM_CLOCK; + const started = clock.now(); + const deadline = input.deadline ?? started + BUILD_TIMING.defaultBudgetMs; + const waitUntil = deadline - BUILD_TIMING.reserveMs; + const remaining = () => Math.max(0, waitUntil - clock.now()); + return { clock, deadline, waitUntil, started, remaining, cap: (limitMs) => Math.min(limitMs, remaining()) }; +} + +/** The deadline for a preparation that starts at `now`, from the CI step's budget; undefined when none is set. */ +export function deadlineFromEnv(env: Readonly>, now: number): number | undefined { + const raw = env[PREPARE_BUDGET_ENV]?.trim(); + if (!raw) return undefined; + const minutes = Number(raw); + if (!Number.isFinite(minutes) || minutes <= 0) throw new Error(`${PREPARE_BUDGET_ENV} must be a positive number of minutes`); + if (minutes * 60_000 <= BUILD_TIMING.reserveMs) throw new Error(`${PREPARE_BUDGET_ENV} must leave more than ${BUILD_TIMING.reserveMs / 60_000} minutes for diagnosis`); + return now + minutes * 60_000; +} + +export type BuildWait = "builder" | "snapshot" | "script" | "sandbox"; + +export interface BuilderView { + name: string; + state: string; + ageMs: number | null; + /** How long until the builder's controller gives up, by the deadline it recorded; negative when past. */ + ownerDeadlineInMs: number | null; + /** Public commit labels only (what the builder is building). */ + labels: Record; +} + +export interface BuildProgress { + stage: string; + waiting: BuildWait; + elapsedMs: number; + remainingMs: number; + builder?: BuilderView; + snapshot?: { name: string; state: string }; +} + +const PUBLIC_BUILDER_LABELS = ["layer", "devSha", "sourceSha"]; + +export function describeBuilder(owner: Sandbox, now: number): BuilderView { + const created = owner.createdAt ? Date.parse(owner.createdAt) : Number.NaN; + const ownerDeadline = Number(owner.labels.deadline); + return { + name: owner.name, + state: owner.state, + ageMs: Number.isFinite(created) ? now - created : null, + ownerDeadlineInMs: Number.isFinite(ownerDeadline) && ownerDeadline > 0 ? ownerDeadline - now : null, + labels: Object.fromEntries(PUBLIC_BUILDER_LABELS.flatMap((key) => owner.labels[key] ? [[key, owner.labels[key]]] : [])), + }; +} + +/** + * Whether another controller's builder holds the layer lock without making + * progress: it failed or stopped, its controller is past the deadline it + * recorded (the controller deletes its builder before then), or, for builders + * from controllers that recorded none, it is older than an hour. + */ +export function builderIsStale(owner: Sandbox, now: number): boolean { + if (["error", "build_failed", "stopped", "archived"].includes(owner.state)) return true; + const view = describeBuilder(owner, now); + if (view.ownerDeadlineInMs !== null) return view.ownerDeadlineInMs < -BUILD_TIMING.staleGraceMs; + return (view.ageMs ?? 0) > BUILD_TIMING.legacyStaleBuilderMs; +} + +/** Reports each kind of wait at most once per interval, so long waits say what they wait on without flooding the log. */ +export function progressReporter(budget: BuildBudget, sink: ((event: BuildProgress) => void) | undefined, everyMs = BUILD_TIMING.progressEveryMs) { + const last = new Map(); + return (event: Omit) => { + if (!sink) return; + const now = budget.clock.now(); + const key = `${event.stage}:${event.waiting}`; + const previous = last.get(key); + if (previous !== undefined && now - previous < everyMs) return; + last.set(key, now); + sink({ ...event, elapsedMs: now - budget.started, remainingMs: Math.max(0, budget.deadline - now) }); + }; +} + +export function minutes(ms: number): string { + return `${Math.max(0, Math.round(ms / 6_000) / 10)} min`; +} diff --git a/packages/daytona-evidence/src/builder.ts b/packages/daytona-evidence/src/builder.ts index 5261cbfa4e..fae1316ce1 100644 --- a/packages/daytona-evidence/src/builder.ts +++ b/packages/daytona-evidence/src/builder.ts @@ -1,5 +1,4 @@ import { randomUUID } from "node:crypto"; -import { setTimeout as delay } from "node:timers/promises"; import { EVIDENCE_KIND } from "./kinds.ts"; import { readAsset } from "@openwork/freestyle/assets"; import { checkoutRecipe } from "@openwork/freestyle/build-recipes"; @@ -11,6 +10,7 @@ import { import { DaytonaApi, DaytonaApiError, type Sandbox } from "./api.ts"; import { LOCALHOST_RECIPE } from "./localhost.ts"; import { boundedDiagnostic, inspectGuest, requireLocalEvidenceReady } from "./health.ts"; +import { buildBudget, builderIsStale, describeBuilder, minutes, progressReporter, type BuildBudget, type BuildClock, type BuildProgress } from "./build-budget.ts"; /** * Daytona builds the same evidence world as Freestyle, with the same steps inside @@ -59,6 +59,16 @@ export interface DaytonaBuildOptions { diagnostic?: (stage: string, log: string) => Promise; /** The dev commit whose warm image to start from; defaults to the dev head. */ imageSha?: string; + /** + * When this whole preparation must be over (clock ms), usually just inside + * the CI step's limit. Every wait stops early enough to print why and fail, + * instead of being cancelled with no output. Unset: each layer gets + * `BUILD_TIMING.defaultBudgetMs`. + */ + deadline?: number; + clock?: BuildClock; + /** "Still waiting" lines: which layer, on what (builder, snapshot, script), and how long is left. */ + progress?: (event: BuildProgress) => void; } export interface DaytonaEvidenceTemplate { name: string; runtimeFingerprint: string } @@ -66,6 +76,9 @@ export interface DaytonaEvidenceTemplate { name: string; runtimeFingerprint: str /** Runs a build script as a transient systemd unit and polls its marker files; exec calls are short. */ export async function runScript(api: DaytonaApi, sandbox: Sandbox, stage: string, script: string, options: DaytonaBuildOptions, deadlineMs = 25 * 60_000) { if (!/^[a-z-]+$/.test(stage)) throw new Error("Invalid build stage"); + const budget = buildBudget(options); + const limitMs = budget.cap(deadlineMs); + const progress = progressReporter(budget, options.progress); const root = `${ROOT}/${stage}`; await api.execChecked(sandbox, `mkdir -p ${ROOT}`); await api.writeFile(sandbox, `${root}.sh`, `#!/bin/bash @@ -79,18 +92,22 @@ ${script} touch ${root}.ready `); await api.execChecked(sandbox, `systemd-run --collect --unit=openwork-${stage} /bin/bash ${root}.sh`); - const deadline = Date.now() + deadlineMs; - while (Date.now() < deadline) { - const state = (await api.exec(sandbox, `if test -f ${root}.failed; then echo failed; elif test -f ${root}.ready; then echo ready; else echo building; fi`)).output.trim(); + const deadline = budget.clock.now() + limitMs; + while (budget.clock.now() < deadline) { + // A short exec timeout keeps one stalled poll from running past the deadline. + const state = (await api.exec(sandbox, `if test -f ${root}.failed; then echo failed; elif test -f ${root}.ready; then echo ready; else echo building; fi`, 20)).output.trim(); if (state === "ready") return; if (state === "failed") { await reportBuildFailure(api, sandbox, stage, options); throw new Error(`Daytona ${stage} failed. Private builder log: ${root}.log`); } - await delay(3_000); + progress({ stage, waiting: "script" }); + await budget.clock.sleep(3_000); } await reportBuildFailure(api, sandbox, stage, options); - throw new Error(`Daytona ${stage} exceeded ${Math.round(deadlineMs / 60_000)} minutes`); + throw new Error(limitMs < deadlineMs + ? `Daytona ${stage} was still building when this job's preparation budget ran out (${minutes(limitMs)} of its ${minutes(deadlineMs)} limit)` + : `Daytona ${stage} exceeded ${Math.round(deadlineMs / 60_000)} minutes`); } async function reportBuildFailure(api: DaytonaApi, sandbox: Sandbox, stage: string, options: DaytonaBuildOptions) { @@ -117,43 +134,63 @@ interface LayerInput { /** Save memory too (running processes). Otherwise files only, from a stopped VM. */ withMemory: boolean; observe: ObserveBuild; labels?: Record; + /** Deadline, clock, progress and diagnostic sink shared by the whole preparation. */ + options?: DaytonaBuildOptions; + /** The build script's stage, whose private log a diagnosis classifies; defaults to `stage`. */ + logStage?: string; } export async function ensureLayer(api: DaytonaApi, input: LayerInput): Promise { + const options = input.options ?? {}; + const budget = buildBudget(options); + const { clock } = budget; + const progress = progressReporter(budget, options.progress); const start = performance.now(); const builderName = `ow-dy-build-${digest(input.name).slice(0, 24)}`; - const deadline = Date.now() + 45 * 60_000; - while (Date.now() < deadline) { + let waitingOn: { builder?: Sandbox; snapshot?: { name: string; state: string } } = {}; + while (clock.now() < budget.waitUntil) { const existing = await api.getSnapshot(input.name); if (existing?.state === "active") { input.observe({ stage: input.stage, durationMs: Math.round(performance.now() - start), cacheHit: true }); return existing.name; } - if (existing && !/error|fail/.test(existing.state)) { await api.waitForSnapshot(input.name); continue; } + if (existing && !/error|fail/.test(existing.state)) { + waitingOn = { snapshot: { name: existing.name, state: existing.state } }; + progress({ stage: input.stage, waiting: "snapshot", snapshot: waitingOn.snapshot }); + await clock.sleep(Math.min(3_000, budget.remaining())); + continue; + } if (existing) await api.deleteSnapshot(existing.id); const owner = await api.getSandbox(builderName); if (owner) { // Another build of this layer is running; wait for it. A stuck or dead builder is replaced. - const age = owner.createdAt ? Date.now() - Date.parse(owner.createdAt) : 0; if (owner.labels.kind !== BUILDER_KIND) throw new Error(`Refusing to reuse unrelated sandbox ${builderName}`); - if (["error", "build_failed", "stopped", "archived"].includes(owner.state) || age > 60 * 60_000) await api.deleteSandbox(owner.id); - else await delay(5_000); + if (builderIsStale(owner, clock.now())) await api.deleteSandbox(owner.id); + else { + waitingOn = { builder: owner }; + progress({ stage: input.stage, waiting: "builder", builder: describeBuilder(owner, clock.now()) }); + await clock.sleep(Math.min(5_000, budget.remaining())); + } continue; } + waitingOn = {}; const parent = await input.parent(); + if (clock.now() >= budget.waitUntil) break; let created: Sandbox; try { - created = await api.createSandbox({ name: builderName, snapshot: parent, labels: { ...input.labels, kind: BUILDER_KIND, layer: digest(input.name).slice(0, 24) }, + created = await api.createSandbox({ name: builderName, snapshot: parent, + // The deadline tells other controllers when this one will have given up and deleted the builder. + labels: { ...input.labels, kind: BUILDER_KIND, layer: digest(input.name).slice(0, 24), deadline: String(budget.deadline) }, // Polling keeps a live build active; a dead controller's builder stops, then is deleted. autoStopMinutes: 30, autoDeleteMinutes: 60 }); } catch (error) { // Lost the race for the builder name; loop to wait for the winner. - if (error instanceof DaytonaApiError && (error.status === 409 || /already exists/i.test(error.message))) { await delay(2_000); continue; } + if (error instanceof DaytonaApiError && (error.status === 409 || /already exists/i.test(error.message))) { await clock.sleep(2_000); continue; } throw error; } let diagnosticSandbox = created; try { - const sandbox = await api.waitForSandbox(created.id, ["started"]); + const sandbox = await api.waitForSandbox(created.id, ["started"], budget.cap(5 * 60_000)); diagnosticSandbox = sandbox; const prepareStart = performance.now(); await input.prepare(sandbox); @@ -162,10 +199,11 @@ export async function ensureLayer(api: DaytonaApi, input: LayerInput): Promise clock.now(), sleep: (ms) => clock.sleep(ms) }); + await waitForSnapshot(api, input.name, budget, input.stage, progress); input.observe({ stage: `${input.stage}-snapshot`, durationMs: Math.round(performance.now() - snapshotStart) }); input.observe({ stage: input.stage, durationMs: Math.round(performance.now() - start), cacheHit: false }); return input.name; @@ -177,18 +215,53 @@ export async function ensureLayer(api: DaytonaApi, input: LayerInput): Promise undefined); } } - throw new Error(`Daytona ${input.stage} build timed out`); + // Out of budget while another controller held this layer: say on what, before the step is cancelled. + const message = await describeLayerTimeout(api, input, budget, waitingOn); + throw new Error(message); +} + +/** Waits for a snapshot within the budget, reporting its state while it is saved. */ +async function waitForSnapshot(api: DaytonaApi, name: string, budget: BuildBudget, stage: string, + progress: ReturnType): Promise { + await api.waitForSnapshot(name, budget.cap(20 * 60_000), + (snapshot) => progress({ stage, waiting: "snapshot", snapshot: { name, state: snapshot?.state ?? "missing" } })); +} + +/** + * A bounded account of what this layer waited on when the budget ran out: the + * builder holding the lock (state, age, its controller's deadline, the commit + * it builds) and the classified tail of its private log, or the snapshot state. + */ +async function describeLayerTimeout(api: DaytonaApi, input: LayerInput, budget: BuildBudget, + waitingOn: { builder?: Sandbox; snapshot?: { name: string; state: string } }): Promise { + const now = budget.clock.now(); + const builder = waitingOn.builder ? describeBuilder(waitingOn.builder, now) : undefined; + const summary = { stage: input.stage, waitedMs: now - budget.started, budgetMs: budget.deadline - budget.started, + ...(builder ? { builder } : {}), ...(waitingOn.snapshot ? { snapshot: waitingOn.snapshot } : {}) }; + const diagnostic = input.options?.diagnostic; + if (diagnostic) { + await boundedDiagnostic(async () => { + await diagnostic(`${input.stage}-wait`, JSON.stringify(summary)); + if (waitingOn.builder) await reportBuildFailure(api, waitingOn.builder, input.logStage ?? input.stage, input.options ?? {}); + }); + } + const on = builder + ? `builder ${builder.name} (state ${builder.state}, ${builder.ageMs === null ? "age unknown" : `created ${minutes(builder.ageMs)} ago`}${builder.labels.devSha ?? builder.labels.sourceSha ? `, building ${(builder.labels.devSha ?? builder.labels.sourceSha ?? "").slice(0, 9)}` : ""}${builder.ownerDeadlineInMs === null ? "" : `, its controller gives up in ${minutes(builder.ownerDeadlineInMs)}`})` + : waitingOn.snapshot ? `snapshot ${waitingOn.snapshot.name} (${waitingOn.snapshot.state})` : "the provider"; + return `Daytona ${input.stage} was not ready within this job's ${minutes(budget.deadline - budget.started)} preparation budget; still waiting on ${on}. The other build continues; rerun once it finishes.`; } /** Plain Ubuntu at our largest VM size, with Node 24. Built once. */ export async function ensureBase(api: DaytonaApi, options: DaytonaBuildOptions = {}): Promise { const observe = options.observe ?? (() => {}); const plain = `${DAYTONA_BASE_SNAPSHOT}-plain`; - return ensureLayer(api, { name: DAYTONA_BASE_SNAPSHOT, stage: "daytona-base", observe, withMemory: false, + return ensureLayer(api, { name: DAYTONA_BASE_SNAPSHOT, stage: "daytona-base", observe, withMemory: false, options, parent: async () => { const existing = await api.getSnapshot(plain); - if (!existing) await api.createImageSnapshot({ name: plain, image: "ubuntu:24.04", ...VM_SIZE }); - await api.waitForSnapshot(plain); + const budget = buildBudget(options); + if (!existing) await api.createImageSnapshot({ name: plain, image: "ubuntu:24.04", ...VM_SIZE }, + { timeoutMs: budget.cap(16 * 60_000), now: () => budget.clock.now(), sleep: (ms) => budget.clock.sleep(ms) }); + await waitForSnapshot(api, plain, budget, "daytona-base", progressReporter(budget, options.progress)); return plain; }, prepare: (sandbox) => runScript(api, sandbox, "daytona-base", `${BASE_RECIPE}\n${SLIM_RECIPE}`, options), @@ -201,7 +274,7 @@ export async function ensureImage(api: DaytonaApi, devSha: string, options: Dayt const entries = devEntries ?? await sourceTree(devSha, options.sourceFetch); return ensureLayer(api, { name: `${DAYTONA_IMAGE_PREFIX}${digest(BASE_RECIPE + EVIDENCE_TOOLS_RECIPE + EVIDENCE_DEPENDENCIES_RECIPE + LOCALHOST_RECIPE + dependencyFingerprint(entries))}`, - stage: "daytona-image", observe: options.observe ?? (() => {}), withMemory: false, labels: { devSha }, + stage: "daytona-image", observe: options.observe ?? (() => {}), withMemory: false, labels: { devSha }, options, parent: () => ensureBase(api, options), prepare: (sandbox) => runScript(api, sandbox, "daytona-image", `${EVIDENCE_TOOLS_RECIPE}\n${checkoutRecipe(devSha)}\n${EVIDENCE_DEPENDENCIES_RECIPE}\n${SLIM_RECIPE}\n${LOCALHOST_RECIPE}\ndf -h /`, options), }); @@ -249,6 +322,7 @@ async function buildEvidenceWorld(sha: string, api: DaytonaApi, options: const state: { mode: "fast" | "full"; restart: string[] } = { mode: "full", restart: [] }; let allowFast = true; const build = () => buildLayer({ name: templateName(runtimeFingerprint), stage: "daytona-world", observe, withMemory: true, labels: { sourceSha: sha }, + options, get logStage() { return state.mode === "fast" ? "evidence-world-fast" : "evidence-world"; }, parent: async () => { const devSha = await devShaPromise; const devEntries = (await devEntriesPromise) ?? entries; @@ -349,7 +423,7 @@ export async function prepareWorldLayer(api: DaytonaApi, input: LayerInput, sour labels: { kind: EVIDENCE_KIND, sourceSha }, autoStopMinutes: 30, autoDeleteMinutes: 0 }); let diagnosticSandbox = created; try { - const sandbox = await api.waitForSandbox(created.id, ["started"]); + const sandbox = await api.waitForSandbox(created.id, ["started"], buildBudget(input.options ?? {}).cap(5 * 60_000)); diagnosticSandbox = sandbox; const prepareStart = performance.now(); await input.prepare(sandbox); diff --git a/scripts/prepare-evidence-web.ts b/scripts/prepare-evidence-web.ts index 8bc15abb0c..b3c809ab83 100644 --- a/scripts/prepare-evidence-web.ts +++ b/scripts/prepare-evidence-web.ts @@ -1,4 +1,5 @@ import { evidenceProviderFromEnv, EVIDENCE_PROVIDER_LABELS } from "../packages/evidence-provider/src/provider.ts"; +import { deadlineFromEnv } from "../packages/daytona-evidence/src/build-budget.ts"; // Builds (or finds) this commit's e2e/preview world on the provider chosen by // OPENWORK_EVIDENCE_PROVIDER (unset means Freestyle). @@ -12,8 +13,13 @@ const imageSha = process.env.OPENWORK_EVIDENCE_IMAGE_SHA || undefined; if (!sha || !process.env[credential]?.trim()) throw new Error(`OPENWORK_EVIDENCE_SOURCE_SHA and ${credential} are required`); const started = performance.now(); const stages: { stage: string; durationMs: number; cacheHit?: boolean; reason?: string }[] = []; +// The CI step's budget, inside its timeout-minutes: Daytona waits stop in time +// to print what they waited on instead of being cancelled with no output. +const deadline = deadlineFromEnv(process.env, Date.now()); const options = { imageSha, + deadline, + progress: (event: unknown) => { console.log(JSON.stringify(event)); }, observe: (event: { stage: string; durationMs: number; cacheHit?: boolean; reason?: string }) => { stages.push(event); console.log(JSON.stringify(event)); }, // The builder VM is credential-free and built from this public commit; its // log tail is the fastest way to see why the shared e2e/preview world failed.