trevato/forge

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

More
Forks1g fMapg aRuns2g rEventsFlows

test/rehearsal-real.test.ts is admitted: ten green flake-hunt runs on the check host, or its red names what did not come up and that is fixed #11178

Merged masoncrew opened this

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

ConversationFiles
Merged

mason/forge:mason/11169-test-rehearsal-real-test-ts-is-admitted → main 1 commit fork

  • Merged. mason/11169-test-rehearsal-real-test-ts-is-admitted was merged into main as e89189b.

Review

Sign in to review this change.
3 files changed +179 −19
scripts/rehearsal.ts +38
@@ -292,3 +292,41 @@ export function report(v: Verdict): string {
292292 : []),
293293 ].join("\n");
294294 }
295
296 /** What a forge that did not come up, or went away, left to say why. */
297 export interface ForgeGone {
298 readonly name: "old" | "new";
299 readonly pid: number;
300 readonly port: number;
301 /** Its exit status; null while it still runs or when a signal ended it. */
302 readonly exitCode: number | null;
303 readonly signal: string | null;
304 /** From its start to when it was given up on. */
305 readonly waitedMs: number;
306 /** Fresh ports it was started on after another process took its port. */
307 readonly portsLost: number;
308 /** What it wrote (stderr, else stdout); only the last lines are quoted. */
309 readonly output: string;
310 readonly log: string;
311 }
312
313 /** How many of a gone forge's last lines its error quotes. */
314 export const OUTPUT_TAIL_LINES = 20;
315
316 /**
317 * The error a gone forge raises: which process on which port, how it
318 * ended and how long it was waited for, and the end of what it said. The
319 * log files go with the check's tmpdir, so the error carries their tail.
320 */
321 export function goneLine(g: ForgeGone): string {
322 const how =
323 g.exitCode !== null
324 ? `exited with code ${g.exitCode}`
325 : g.signal !== null
326 ? `was ended by ${g.signal}`
327 : "was still not ready";
328 const lost = g.portsLost === 0 ? "" : `, after losing ${g.portsLost} port${g.portsLost === 1 ? "" : "s"} to other processes`;
329 const tail = g.output.trimEnd().split("\n").slice(-OUTPUT_TAIL_LINES).join("\n");
330 const said = tail.trim() === "" ? `it wrote nothing; see ${g.log}` : `it wrote (${g.log}):\n${tail}`;
331 return `the ${g.name} forge (pid ${g.pid}, port ${g.port}) ${how} ${g.waitedMs} ms after it started${lost}; ${said}`;
332 }
scripts/rehearse-roll.ts +65 −19
@@ -22,9 +22,11 @@
2222 import { cpSync, mkdirSync, mkdtempSync, rmSync } from "node:fs";
2323 import { tmpdir } from "node:os";
2424 import { join, resolve } from "node:path";
25 import { freePort, lostPort, PORT_RETRIES } from "../src/kernel/port.ts";
2526 import {
2627 count,
2728 emptyTally,
29 goneLine,
2830 judge,
2931 parseArgs,
3032 report,
@@ -38,28 +40,30 @@ import {
3840
3941 interface Forge {
4042 readonly name: "old" | "new";
43 readonly port: number;
4144 readonly url: string;
4245 readonly proc: Bun.Subprocess;
4346 readonly log: string;
47 readonly startedAt: number;
48 /** Fresh ports this forge was started on after losing one (`kernel/port.ts`). */
49 readonly portsLost: number;
4450 }
4551
46 /** A loopback port nobody holds right now. */
47 function freePort(): number {
48 const probe = Bun.serve({ port: 0, hostname: "127.0.0.1", fetch: () => new Response() });
49 const port = probe.port ?? 0;
50 probe.stop(true);
51 return port;
52 }
53
54 function start(
52 /**
53 * A forge on a port free a moment ago. Between the probe that found it and
54 * the forge's bind, another process can take it — a gate shard's listener,
55 * or one of the thousands of outgoing connections a roll makes.
56 */
57 async function start(
5558 name: Forge["name"],
5659 checkout: string,
5760 dataDir: string,
5861 lingerS: number,
5962 logDir: string,
60 ): Forge {
61 const port = freePort();
62 const log = join(logDir, `${name}.log`);
63 portsLost = 0,
64 ): Promise<Forge> {
65 const port = await freePort();
66 const log = join(logDir, `${name}-${portsLost}.log`);
6367 const env: Record<string, string> = {
6468 PATH: process.env["PATH"] ?? "",
6569 HOME: process.env["HOME"] ?? "",
@@ -81,7 +85,39 @@ function start(
8185 stdout: Bun.file(log),
8286 stderr: Bun.file(`${log}.err`),
8387 });
84 return { name, url: `http://127.0.0.1:${port}`, proc, log };
88 return { name, port, url: `http://127.0.0.1:${port}`, proc, log, startedAt: Date.now(), portsLost };
89 }
90
91 const gone = (forge: Forge): boolean =>
92 forge.proc.exitCode !== null || forge.proc.signalCode !== null;
93
94 /** What the forge wrote: its stderr, or its log when stderr is empty. */
95 async function said(forge: Forge): Promise<string> {
96 const read = (path: string): Promise<string> => Bun.file(path).text().catch(() => "");
97 const err = await read(`${forge.log}.err`);
98 return err.trim() !== "" ? err : read(forge.log);
99 }
100
101 /** Whether a gone forge only lost its port, and has a retry left to take a fresh one. */
102 async function retriable(forge: Forge): Promise<boolean> {
103 return forge.portsLost < PORT_RETRIES && gone(forge) && lostPort(await said(forge));
104 }
105
106 /** The error a gone forge raises: process, port, wait and its last words. */
107 async function goneError(forge: Forge): Promise<Error> {
108 return new Error(
109 goneLine({
110 name: forge.name,
111 pid: forge.proc.pid,
112 port: forge.port,
113 exitCode: forge.proc.exitCode,
114 signal: forge.proc.signalCode,
115 waitedMs: Date.now() - forge.startedAt,
116 portsLost: forge.portsLost,
117 output: await said(forge),
118 log: forge.log,
119 }),
120 );
85121 }
86122
87123 /** One readiness probe: ready, not ready (a 503, or nothing listening), or silent past its timeout. */
@@ -139,13 +175,18 @@ export async function rehearse(
139175 const timeline: Timeline = { newInRotationMs: null, oldOutOfRotationMs: null, oldExitMs: null };
140176 const forges: Forge[] = [];
141177 try {
142 const old = start("old", resolve(args.old), dataDir, args.lingerS, logs);
178 let old = await start("old", resolve(args.old), dataDir, args.lingerS, logs);
143179 forges.push(old);
144180 say(`old forge starting at ${old.url}`);
145181 const bootBy = Date.now() + 60_000;
146182 while (!(await ready(old, 1000))) {
147 if (old.proc.exitCode !== null || Date.now() > bootBy)
148 throw new Error(`the old forge did not come up; see ${old.log}.err`);
183 if (await retriable(old)) {
184 say(`old forge lost port ${old.port} to another process; starting it on a fresh one`);
185 old = await start("old", resolve(args.old), dataDir, args.lingerS, logs, old.portsLost + 1);
186 forges[0] = old;
187 continue;
188 }
189 if (gone(old) || Date.now() > bootBy) throw await goneError(old);
149190 await Bun.sleep(100);
150191 }
151192 rotation.saw(old, true);
@@ -181,7 +222,7 @@ export async function rehearse(
181222 // one beside the old, and signal the old one once the new is ready.
182223 const roll = async (): Promise<void> => {
183224 await Bun.sleep(Math.min(2000, (args.seconds * 1000) / 4));
184 const next = start("new", resolve(args.next), dataDir, args.lingerS, logs);
225 let next = await start("new", resolve(args.next), dataDir, args.lingerS, logs);
185226 forges.push(next);
186227 say(`new forge starting at ${next.url}`);
187228 old.proc.exited.then(() => {
@@ -207,8 +248,13 @@ export async function rehearse(
207248 say("old forge out of rotation");
208249 }
209250 }
210 if (next.proc.exitCode !== null)
211 throw new Error(`the new forge exited; see ${next.log}.err`);
251 // A new forge that never joined lost only its port; one that did is the roll's failure.
252 if (termAt === null && !rotation.has(next) && (await retriable(next))) {
253 say(`new forge lost port ${next.port} to another process; starting it on a fresh one`);
254 const again = await start("new", resolve(args.next), dataDir, args.lingerS, logs, next.portsLost + 1);
255 forges[forges.indexOf(next)] = again;
256 next = again;
257 } else if (gone(next)) throw await goneError(next);
212258 await Bun.sleep(args.probeMs);
213259 }
214260 };
test/rehearsal.test.ts +76
@@ -4,10 +4,17 @@
44 */
55
66 import { describe, expect, test } from "bun:test";
7 import { mkdirSync, mkdtempSync, rmSync, writeFileSync } from "node:fs";
8 import { tmpdir } from "node:os";
9 import { join } from "node:path";
10 import { PORT_RETRIES } from "../src/kernel/port.ts";
11 import { rehearse } from "../scripts/rehearse-roll.ts";
712 import {
813 count,
914 DEFAULTS,
1015 emptyTally,
16 goneLine,
17 OUTPUT_TAIL_LINES,
1118 isRefusal,
1219 judge,
1320 missLine,
@@ -143,3 +150,72 @@ describe("the verdict", () => {
143150 expect(judge(emptyTally(), rolled).problem).toBe("no request was sent");
144151 });
145152 });
153
154 describe("a forge that does not come up says which, where and why", () => {
155 const base = {
156 name: "old" as const,
157 pid: 4242,
158 port: 39001,
159 exitCode: 1,
160 signal: null,
161 waitedMs: 112,
162 portsLost: 0,
163 output: "booting\nerror: database is locked\n",
164 log: "/tmp/r/old-0.log",
165 };
166
167 test("its process, port, exit and wait, then the end of what it wrote", () => {
168 expect(goneLine(base)).toBe(
169 "the old forge (pid 4242, port 39001) exited with code 1 112 ms after it started; " +
170 "it wrote (/tmp/r/old-0.log):\nbooting\nerror: database is locked",
171 );
172 });
173
174 test("a signal, a forge still not ready, lost ports and silence are each said", () => {
175 expect(goneLine({ ...base, exitCode: null, signal: "SIGKILL" })).toContain("was ended by SIGKILL");
176 const slow = goneLine({ ...base, exitCode: null, waitedMs: 60_004, portsLost: 1, output: "" });
177 expect(slow).toBe(
178 "the old forge (pid 4242, port 39001) was still not ready 60004 ms after it started, " +
179 "after losing 1 port to other processes; it wrote nothing; see /tmp/r/old-0.log",
180 );
181 });
182
183 test("only the last lines are quoted", () => {
184 const output = Array.from({ length: OUTPUT_TAIL_LINES + 5 }, (_, i) => `line ${i}`).join("\n");
185 const line = goneLine({ ...base, output });
186 expect(line).not.toContain("line 4\n");
187 expect(line).toContain("line 5\n");
188 expect(line.endsWith(`line ${OUTPUT_TAIL_LINES + 4}`)).toBe(true);
189 });
190 });
191
192 describe("rehearse: a forge that dies at boot", () => {
193 // A checkout whose src/main.ts is only `body`: no real forge is started.
194 const rehearseWith = async (body: string): Promise<string> => {
195 const checkout = mkdtempSync(join(tmpdir(), "forge-rehearsal-checkout-"));
196 mkdirSync(join(checkout, "src"));
197 writeFileSync(join(checkout, "src", "main.ts"), body);
198 try {
199 await rehearse({ ...parseArgs([], checkout), seconds: 2, probeMs: 100, lingerS: 0, concurrency: 1 });
200 return "it came up";
201 } catch (error) {
202 return (error as Error).message;
203 } finally {
204 rmSync(checkout, { recursive: true, force: true });
205 }
206 };
207
208 test("is named with its port, exit code and last words", async () => {
209 const message = await rehearseWith('console.error("cannot open FORGE_DATA"); process.exit(3);');
210 expect(message).toMatch(/^the old forge \(pid \d+, port \d+\) exited with code 3 \d+ ms after it started; it wrote/);
211 expect(message).toContain("cannot open FORGE_DATA");
212 }, 30_000);
213
214 test("one that lost its port to another process is started on a fresh one, a bounded number of times", async () => {
215 const message = await rehearseWith(
216 'console.error(`Failed to start server. Is port ${process.env.PORT} in use?`); process.exit(1);',
217 );
218 expect(message).toContain(`after losing ${PORT_RETRIES} ports to other processes`);
219 expect(message).toMatch(/Is port \d+ in use\?$/);
220 }, 30_000);
221 });

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs