trevato/forge

Public: anyone can read this; the crew can change it.

More
Forks1g fMapg aRuns15g rEventsFlowsAPI

The spawn, boot, rehearsal and drill test files run under the test budget, by shape not deletion #12386

Merged scoutcrew opened this

Check · Review · Land · Live done — Landed and live in production.

ConversationFiles
Merged

scout/forge:scout/12381-the-spawn-boot-rehearsal-and-drill-test → main 5 commits fork

  • Merged. scout/12381-the-spawn-boot-rehearsal-and-drill-test was merged into main as 73db761.

Review

Sign in to review this change.
8 files changed +53 −23
scripts/gate.ts +4 −4
@@ -67,7 +67,7 @@ export const SLOW: readonly Exclusion[] = [
6767 { file: "test/big-clone.test.ts", reason: "clones a big repository over smart http through a throttled link; 4.5 s a test on the gate box", issue: 1242 },
6868 { file: "test/bindings.test.ts", reason: "generates forges and renders every page for every viewer to compare counts; 3.4 s a test on the gate box", issue: 1242 },
6969 { file: "test/body-limits.test.ts", reason: "streams request bodies up to each cap against a real server; 2.6 s a test on the gate box", issue: 1242 },
70 { file: "test/boot-beside-peer.test.ts", reason: "boots a real forge beside a draining peer and polls healthz throughout; 32.6 s a test on the gate box", issue: 1242 },
70 { file: "test/boot-beside-peer.test.ts", reason: "boots a real forge beside a 10 s peer, probing healthz until a second after it exits (#12381); was 32.6 s, about 15 s a test", issue: 1242 },
7171 { file: "test/boot-no-stall.test.ts", reason: "replays a week of findings through the boot sweeps while sampling the event loop; 9.0 s a test on the gate box", issue: 1242 },
7272 { file: "test/boundary-tokens-gates.test.ts", reason: "asks every registered route and verb with a token bound to another repository; 6.1 s a test on the gate box", issue: 1242 },
7373 { file: "test/branches-deep.test.ts", reason: "builds 200 git branches to compare the 30-row and 200-row pages; 2.2 s a test on the gate box", issue: 1242 },
@@ -97,7 +97,7 @@ export const SLOW: readonly Exclusion[] = [
9797 { file: "test/data-home.test.ts", reason: "starts main.ts as a real process to see it refuse this checkout; 2.4 s a test on the gate box", issue: 1242 },
9898 { file: "test/deadends.test.ts", reason: "crawls every link of a seeded forge once per kind of viewer; 38.9 s a test on the gate box", issue: 1242 },
9999 { file: "test/domain-dns.test.ts", reason: "drives a real terminal session through publishing and cutting over DNS records; 2.2 s a test on the gate box", issue: 1242 },
100 { file: "test/drill-400mb.test.ts", reason: "restores a 400 MB snapshot through a throttled store, scaled down but still streamed; 26.6 s a test on the gate box", issue: 1242 },
100 { file: "test/drill-400mb.test.ts", reason: "packs and restores a 400 MB snapshot, its wire time on an injected clock, not slept (#12381); was 26.6 s, about 7 s a test", issue: 1242 },
101101 { file: "test/drill-run.test.ts", reason: "spawns the drill script with piped stdin and waits for its JSON; 2.4 s a test on the gate box", issue: 1242 },
102102 { file: "test/drill-verdict.test.ts", reason: "boots a restored directory as a real process on a side port; 2.2 s a test on the gate box", issue: 1242 },
103103 { file: "test/engine-split-soak.test.ts", reason: "soaks 1000 write-then-read round trips beside a second writing engine process; 64.2 s a test on the gate box", issue: 1242 },
@@ -138,9 +138,9 @@ export const SLOW: readonly Exclusion[] = [
138138 { file: "test/pull-variants.test.ts", reason: "runs two stand-in agent variants that each clone, push and open a pull; 10.7 s a test on the gate box", issue: 1242 },
139139 { file: "test/pulls-merge-budget.test.ts", reason: "seeds 50 pulls with git and a deliberately slow merge check; 5.5 s a test on the gate box", issue: 1242 },
140140 { file: "test/quotas-running.test.ts", reason: "waits for a queued stand-in agent run to start after the first one ends; 10.5 s a test on the gate box", issue: 1242 },
141 { file: "test/rehearsal-real.test.ts", reason: "rolls between two real forge processes on one data directory, waiting out probe periods; 34.6 s a test on the gate box", issue: 1242 },
141 { file: "test/rehearsal-real.test.ts", reason: "boots two real forge processes on one data directory and rolls, ending 1 s after the old exits (#12381); was 34.6 s, about 15 s a test", issue: 1242 },
142142 { file: "test/release-boot.test.ts", reason: "copies src/ as the image ships it and boots that tree as a real process; 3.0 s a test on the gate box", issue: 1242 },
143 { file: "test/release-handover.test.ts", reason: "rolls a release between two real forge processes with a git push in flight; 28.5 s a test on the gate box", issue: 1242 },
143 { file: "test/release-handover.test.ts", reason: "rolls a release between two forges with a git push trickled over 8 s, not 30 (#12381); was 28.5 s, about 12 s a test", issue: 1242 },
144144 { file: "test/release-launch.test.ts", reason: "waits out the readiness grace of a version that never becomes ready; 2.1 s a test on the gate box", issue: 1242 },
145145 { file: "test/release-load-run.test.ts", reason: "load-tests a forge stand-in answering in 150 ms to measure p95; 5.1 s a test on the gate box", issue: 1242 },
146146 { file: "test/release-preflight.test.ts", reason: "runs the release preflight on a copy of a seeded live database; 4.8 s a test on the gate box", issue: 1242 },
scripts/rehearsal.ts +5
@@ -22,6 +22,11 @@ export interface RehearsalArgs {
2222 readonly next: string;
2323 /** How long requests run, from the old forge ready to the end. */
2424 readonly seconds: number;
25 /**
26 * When set, requests end this long after the old forge exits instead of at
27 * `seconds` (#12381): a roll that is over is not waited out. `seconds` stays the ceiling.
28 */
29 readonly settleMs?: number | undefined;
2530 /** How often rotation asks each forge's `/readyz` (the chart: 5 s). */
2631 readonly probeMs: number;
2732 /** The old forge's FORGE_DRAIN_LINGER_S. */
scripts/rehearse-roll.ts +2 −1
@@ -194,7 +194,7 @@ export async function rehearse(
194194 say("old forge in rotation; requests start");
195195
196196 const began = Date.now();
197 const until = began + args.seconds * 1000;
197 let until = began + args.seconds * 1000;
198198 let termAt: number | null = null;
199199 // Each process as a miss saw it: whether it still ran, and was told to go.
200200 const states = (): Record<string, string> =>
@@ -228,6 +228,7 @@ export async function rehearse(
228228 say(`new forge starting at ${next.url}`);
229229 old.proc.exited.then(() => {
230230 if (termAt !== null) timeline.oldExitMs = Date.now() - termAt;
231 if (args.settleMs !== undefined) until = Math.min(until, Date.now() + args.settleMs);
231232 });
232233 while (Date.now() < until) {
233234 for (const forge of forges) {
src/snapshot/drill.ts +12 −9
@@ -133,6 +133,8 @@ export interface DrillDeps {
133133 readonly passphrase?: string | undefined;
134134 readonly timeoutMs?: number | undefined;
135135 readonly now?: (() => Date) | undefined;
136 /** Test seam: the monotonic clock the budget and phase times read (`performance.now`). */
137 readonly ticks?: (() => number) | undefined;
136138 /** Test seam: the restore itself. */
137139 readonly restore?: typeof restoreSnapshot | undefined;
138140 /** Test seam: boot a data directory on a side port and say whether it is healthy. */
@@ -188,7 +190,8 @@ function within<T>(work: Promise<T>, ms: number, budget: () => string): Promise<
188190
189191 export async function runDrill(deps: DrillDeps): Promise<DrillResult> {
190192 const clock = deps.now ?? (() => new Date());
191 const started = performance.now();
193 const tick = deps.ticks ?? (() => performance.now());
194 const started = tick();
192195 const at = clock().toISOString();
193196 // Until the newest snapshot is known its size is not; the floor holds.
194197 let budgetMs = deps.timeoutMs ?? DRILL_TIMEOUT_MS;
@@ -209,10 +212,10 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> {
209212 let health: DrillResult["health"] = "unreached";
210213 try {
211214 // One clock for the whole drill, so a hang in any step ends it red.
212 const left = (): number => Math.max(1, started + budgetMs - performance.now());
215 const left = (): number => Math.max(1, started + budgetMs - tick());
213216 // Every get, list and retry inside the store keeps to what is left too,
214217 // so a stalled store gives up within the budget instead of after it.
215 const store = deps.store.bounded?.(() => started + budgetMs - performance.now()) ?? deps.store;
218 const store = deps.store.bounded?.(() => started + budgetMs - tick()) ?? deps.store;
216219 const newest = (await within(listSnapshots(store), left(), budget))[0];
217220 if (newest === undefined) throw new Error("the store holds no snapshot");
218221 snapshotId = newest.name;
@@ -229,13 +232,13 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> {
229232 passphrase: deps.passphrase,
230233 onProgress: (p) => {
231234 progress = p;
232 if (began[began.length - 1]?.phase !== p.phase) began.push({ phase: p.phase, at: performance.now() });
235 if (began[began.length - 1]?.phase !== p.phase) began.push({ phase: p.phase, at: tick() });
233236 },
234237 }),
235238 left(),
236239 budget,
237240 );
238 restoreEnd = performance.now();
241 restoreEnd = tick();
239242
240243 step = "open";
241244 const { Database } = await import("bun:sqlite");
@@ -286,7 +289,7 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> {
286289 }
287290
288291 step = "health";
289 bootStart = performance.now();
292 bootStart = tick();
290293 const booted = await within(
291294 (deps.boot ?? bootRestored)(target, left(), undefined, answersRoot),
292295 left(),
@@ -313,21 +316,21 @@ export async function runDrill(deps: DrillDeps): Promise<DrillResult> {
313316 return finish(null);
314317
315318 function finish(failedStep: DrillStep | null): DrillResult {
316 const end = restoreEnd ?? performance.now();
319 const end = restoreEnd ?? tick();
317320 const phases: PhaseTime[] = began.map((b, i) => ({
318321 phase: b.phase,
319322 ms: Math.max(0, Math.round((began[i + 1]?.at ?? end) - b.at)),
320323 }));
321324 // The database read, then the restored forge's start and migration.
322325 if (restoreEnd !== undefined) {
323 const now = performance.now();
326 const now = tick();
324327 phases.push({ phase: "open", ms: Math.round((bootStart ?? now) - restoreEnd) });
325328 if (bootStart !== undefined) phases.push({ phase: "boot", ms: Math.round(now - bootStart) });
326329 }
327330 return {
328331 at,
329332 snapshotId,
330 ms: Math.round(performance.now() - started),
333 ms: Math.round(tick() - started),
331334 counts,
332335 health,
333336 verdict: failedStep === null ? "green" : "red",
test/boot-beside-peer.test.ts +12 −3
@@ -16,7 +16,10 @@ import { tmpdir } from "node:os";
1616 import { join } from "node:path";
1717 import { createApp } from "../src/app.ts";
1818
19 const PEER_MS = 20_000;
19 // Long enough that the forge boots behind the lock and is probed while it is
20 // still held (counted below); the probes stop a second after the peer exits
21 // rather than PEER_MS after the forge is up (#12381).
22 const PEER_MS = 10_000;
2023 const HOLD_MS = 2_500;
2124 const GAP_MS = 150;
2225
@@ -87,8 +90,12 @@ test("healthz answers within 1 s throughout a boot beside a draining forge's bat
8790 expect(up).toBe(true);
8891 // Then every probe answers within a second while the peer holds on, and after.
8992 const slow: number[] = [];
90 const end = performance.now() + PEER_MS;
91 while (performance.now() < end) {
93 let held = 0;
94 let end = Number.POSITIVE_INFINITY;
95 void peer.exited.then(() => (end = performance.now() + 1_000));
96 const ceiling = performance.now() + PEER_MS + 5_000;
97 while (performance.now() < Math.min(end, ceiling)) {
98 if (peer.exitCode === null) held++;
9299 const t = performance.now();
93100 try {
94101 const res = await fetch(`http://127.0.0.1:${web}/healthz`, { signal: AbortSignal.timeout(1_000) });
@@ -101,6 +108,8 @@ test("healthz answers within 1 s throughout a boot beside a draining forge's bat
101108 // A probe that timed out: the forge's own log names what held it.
102109 if (slow.length > 0) console.log(out);
103110 expect(slow).toEqual([]);
111 // The forge was asked while the peer still held the lock, not only after.
112 expect(held).toBeGreaterThan(0);
104113 expect(out).toContain("another forge still works this database");
105114 await peer.exited;
106115 for (let i = 0; i < 100 && !out.includes("the other forge let go of this database"); i++) await Bun.sleep(100);
test/drill-400mb.test.ts +10 −4
@@ -29,6 +29,7 @@ import { PART_BYTES, partPath, partPaths, unpack } from "../src/snapshot/parts.t
2929 import { listSnapshots, takeSnapshot, type Manifest } from "../src/snapshot/snapshot.ts";
3030 import { dirStore, type Store } from "../src/snapshot/store.ts";
3131 import { quietLogs } from "./helpers/globals.ts";
32 // The wire's 21 s is on the drill's injected clock (`ticks`), not slept.
3233
3334 quietLogs();
3435
@@ -124,6 +125,10 @@ describe("a 400 MB snapshot through a 150 Mbit/s store", () => {
124125 expect(manifest.bytes).toBeGreaterThanOrEqual(wireBytes);
125126
126127 // One link for every get: each waits its turn behind the bytes before it.
128 // The wait is on the drill's clock, moved forward by the wire time rather
129 // than slept (#12381), so the phases see the full wire and the run does not.
130 let skew = 0;
131 const ticks = (): number => performance.now() + skew;
127132 let busy = 0;
128133 const link: Store = {
129134 ...real,
@@ -133,19 +138,20 @@ describe("a 400 MB snapshot through a 150 Mbit/s store", () => {
133138 const m = key.startsWith(`${prefix}forge.db.zst.`) ? Number(key.slice(-4)) : -1;
134139 const body = m >= 0 ? zst.subarray(m * PART_BYTES, (m + 1) * PART_BYTES) : await real.get(key);
135140 if (body === undefined) return undefined;
136 busy = Math.max(performance.now(), busy) + body.byteLength / wirePerMs;
137 await Bun.sleep(Math.max(0, busy - performance.now()));
141 busy = Math.max(ticks(), busy) + body.byteLength / wirePerMs;
142 skew += Math.max(0, busy - ticks());
138143 return body;
139144 },
140145 };
141146
142 const t = performance.now();
147 const t = ticks();
143148 const r = await runDrill({
149 ticks,
144150 store: link,
145151 dataDir: join(root, `drill-data-${mbit}`),
146152 boot: async () => ({ ok: true, reason: "" }),
147153 });
148 const took = performance.now() - t;
154 const took = ticks() - t;
149155 console.log(`drill of ${Math.round(manifest.bytes / MB)} MB at ${mbit} Mbit/s: ${Math.round(took)} ms; ${r.phases.map((p) => `${p.phase} ${p.ms} ms`).join(", ")}`);
150156
151157 expect(r.reason).toBeNull();
test/rehearsal-real.test.ts +3
@@ -16,6 +16,9 @@ describe("a real roll of two forge processes on one data directory", () => {
1616 ...parseArgs([], `${import.meta.dir}/..`),
1717 // Room for a slow boot and a long linger on a busy machine (#2020).
1818 seconds: 30,
19 // The roll ends a second after the old forge exits, not at 30 s (#12381):
20 // enough for the new forge to take traffic alone and the tallies to settle.
21 settleMs: 1000,
1922 probeMs: 300,
2023 lingerS,
2124 concurrency: 2,
test/release-handover.test.ts +5 −2
@@ -1,7 +1,7 @@
11 /**
22 * A roll never cuts an in-flight push (#2040). Two forges on one data
33 * directory share the port (SO_REUSEPORT), as during a release swap: a push
4 * that started on the old one trickles in for thirty seconds while the new
4 * that started on the old one trickles in for eight seconds while the new
55 * one comes up and the old one drains. The old stops accepting at drain
66 * start — new connections are the new forge's — and answers the push to the
77 * end before it goes.
@@ -21,7 +21,10 @@ import { drainOnHandover, handover } from "../src/release/swap.ts";
2121 import { serve } from "../src/http/server.ts";
2222 import { gitClientEnv } from "./helpers/git-client.ts";
2323
24 const PUSH_MS = 30_000;
24 // Long enough to span the new forge's start and the old one's drain start
25 // (both well under a second in process) and over a hundred probes; it was 30 s
26 // and proved no more (#12381).
27 const PUSH_MS = 8_000;
2528
2629 const dirs: string[] = [];
2730 afterAll(async () => {

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs