Public: anyone can read this; the crew can change it.
A rehearsal that rolled nothing names the forge, its port and how long it waited #11192
Check · Review · Land · Live done — Landed and live in production.
scout/forge:scout/11186-a-rehearsal-that-rolled-nothing-names-th → main 1 commit fork
4 files
changed +100
−7
scripts/rehearsal.ts +45 −4
| @@ -229,17 +229,58 @@ export interface Verdict { | ||
| 229 | 229 | readonly problem: string | null; |
| 230 | 230 | } |
| 231 | 231 | |
| 232 | /** What the rehearsal saw of one forge when it judged: where it ran and what it said. */ | |
| 233 | export interface ForgeSeen { | |
| 234 | readonly port: number; | |
| 235 | /** Fresh ports it was started on after losing one (`kernel/port.ts`). */ | |
| 236 | readonly portsLost: number; | |
| 237 | /** How long it was waited for: the new one from its start, the old one from its SIGTERM. */ | |
| 238 | readonly waitedMs: number; | |
| 239 | /** What it wrote (stderr, else stdout); only the end is quoted. */ | |
| 240 | readonly output: string; | |
| 241 | } | |
| 242 | ||
| 243 | /** How many of a forge's last lines a verdict quotes, and how long that quote may be. */ | |
| 244 | export const PROBLEM_TAIL_LINES = 5; | |
| 245 | export const PROBLEM_TAIL_CHARS = 400; | |
| 246 | ||
| 247 | /** | |
| 248 | * One forge, as a verdict names it: its port, the ports it lost, the wait | |
| 249 | * and the end of its stderr, on one line so `report` keeps its shape. | |
| 250 | */ | |
| 251 | export function seenLine(name: "old" | "new", s: ForgeSeen): string { | |
| 252 | const lines = s.output | |
| 253 | .split("\n") | |
| 254 | .map((l) => l.trim()) | |
| 255 | .filter((l) => l !== "") | |
| 256 | .slice(-PROBLEM_TAIL_LINES); | |
| 257 | let tail = lines.join(" | "); | |
| 258 | if (tail.length > PROBLEM_TAIL_CHARS) tail = `…${tail.slice(-(PROBLEM_TAIL_CHARS - 1))}`; | |
| 259 | const said = tail === "" ? "it wrote nothing" : `it last wrote: ${tail}`; | |
| 260 | return `the ${name} forge on port ${s.port}, ${s.portsLost} port${s.portsLost === 1 ? "" : "s"} lost, waited ${s.waitedMs} ms; ${said}`; | |
| 261 | } | |
| 262 | ||
| 232 | 263 | /** |
| 233 | 264 | * Zero refusals over a roll that happened. A rehearsal in which the new |
| 234 | * forge never joined, or the old one never left, rolled nothing and says so. | |
| 265 | * forge never joined, or the old one never left, rolled nothing and says | |
| 266 | * so, naming that forge's port, lost ports, wait and last words when the | |
| 267 | * rehearsal saw them. | |
| 235 | 268 | */ |
| 236 | export function judge(tally: Tally, timeline: Timeline): Verdict { | |
| 269 | export function judge( | |
| 270 | tally: Tally, | |
| 271 | timeline: Timeline, | |
| 272 | seen: Partial<Readonly<Record<"old" | "new", ForgeSeen>>> = {}, | |
| 273 | ): Verdict { | |
| 237 | 274 | const refused = refusals(tally); |
| 275 | const naming = (sentence: string, name: "old" | "new"): string => { | |
| 276 | const s = seen[name]; | |
| 277 | return s === undefined ? sentence : `${sentence}: ${seenLine(name, s)}`; | |
| 278 | }; | |
| 238 | 279 | const problem = |
| 239 | 280 | timeline.newInRotationMs === null |
| 240 | ? "the new forge never became ready" | |
| 281 | ? naming("the new forge never became ready", "new") | |
| 241 | 282 | : timeline.oldExitMs === null |
| 242 | ? "the old forge did not exit" | |
| 283 | ? naming("the old forge did not exit", "old") | |
| 243 | 284 | : tally.requests === 0 |
| 244 | 285 | ? "no request was sent" |
| 245 | 286 | : null; |
scripts/rehearse-roll.ts +12 −1
| @@ -26,6 +26,7 @@ import { freePort, lostPort, PORT_RETRIES } from "../src/kernel/port.ts"; | ||
| 26 | 26 | import { |
| 27 | 27 | count, |
| 28 | 28 | emptyTally, |
| 29 | type ForgeSeen, | |
| 29 | 30 | goneLine, |
| 30 | 31 | judge, |
| 31 | 32 | parseArgs, |
| @@ -268,7 +269,17 @@ export async function rehearse( | ||
| 268 | 269 | await Promise.race([old.proc.exited, Bun.sleep(args.lingerS * 1000 + 30_000)]); |
| 269 | 270 | if (old.proc.exitCode !== null) timeline.oldExitMs = Date.now() - termAt; |
| 270 | 271 | } |
| 271 | return { ...judge(tally, timeline), logs }; | |
| 272 | // What each forge left, so a roll that rolled nothing names where and why. | |
| 273 | const seenOf = async (f: Forge | undefined, since: number | null): Promise<ForgeSeen | undefined> => | |
| 274 | f === undefined | |
| 275 | ? undefined | |
| 276 | : { port: f.port, portsLost: f.portsLost, waitedMs: Date.now() - (since ?? f.startedAt), output: await said(f) }; | |
| 277 | const seen: Partial<Record<Forge["name"], ForgeSeen>> = {}; | |
| 278 | const oldSeen = await seenOf(forges.find((f) => f.name === "old"), termAt); | |
| 279 | const newSeen = await seenOf(forges.find((f) => f.name === "new"), null); | |
| 280 | if (oldSeen !== undefined) seen.old = oldSeen; | |
| 281 | if (newSeen !== undefined) seen.new = newSeen; | |
| 282 | return { ...judge(tally, timeline, seen), logs }; | |
| 272 | 283 | } finally { |
| 273 | 284 | for (const f of forges) if (f.proc.exitCode === null) f.proc.kill("SIGKILL"); |
| 274 | 285 | await Promise.all(forges.map((f) => f.proc.exited)); |
test/rehearsal-real.test.ts +2 −2
| @@ -23,14 +23,14 @@ describe("a real roll of two forge processes on one data directory", () => { | ||
| 23 | 23 | |
| 24 | 24 | test("an old forge that exits on SIGTERM refuses what routers still send it", async () => { |
| 25 | 25 | const v = await rehearse(short(0)); |
| 26 | expect(v.problem).toBeNull(); | |
| 26 | expect(v.problem, v.problem ?? "").toBeNull(); | |
| 27 | 27 | expect(v.refused).toBeGreaterThan(0); |
| 28 | 28 | expect(v.tally.byOutcome["refused"]).toBeGreaterThan(0); |
| 29 | 29 | }, 60_000); |
| 30 | 30 | |
| 31 | 31 | test("an old forge that lingers past a probe period refuses nobody", async () => { |
| 32 | 32 | const v = await rehearse(short(5)); |
| 33 | expect(v.problem).toBeNull(); | |
| 33 | expect(v.problem, v.problem ?? "").toBeNull(); | |
| 34 | 34 | // Each refusal says when, whom, what came back and where both processes were. |
| 35 | 35 | expect(v.tally.misses.filter((m) => isRefusal(m.outcome)).map(missLine)).toEqual([]); |
| 36 | 36 | expect(v.refused).toBe(0); |
test/rehearsal.test.ts +41
| @@ -15,6 +15,8 @@ import { | ||
| 15 | 15 | emptyTally, |
| 16 | 16 | goneLine, |
| 17 | 17 | OUTPUT_TAIL_LINES, |
| 18 | PROBLEM_TAIL_CHARS, | |
| 19 | PROBLEM_TAIL_LINES, | |
| 18 | 20 | isRefusal, |
| 19 | 21 | judge, |
| 20 | 22 | missLine, |
| @@ -151,6 +153,45 @@ describe("the verdict", () => { | ||
| 151 | 153 | }); |
| 152 | 154 | }); |
| 153 | 155 | |
| 156 | describe("a rehearsal that rolled nothing names the forge, its port and the wait", () => { | |
| 157 | const rolled = { newInRotationMs: 2100, oldOutOfRotationMs: 300, oldExitMs: 5200 }; | |
| 158 | const t = emptyTally(); | |
| 159 | count(t, "old", 200); | |
| 160 | const stderr = Array.from({ length: 30 }, (_, i) => `line ${i}`).join("\n") + "\n"; | |
| 161 | const seen = { | |
| 162 | old: { port: 39001, portsLost: 0, waitedMs: 30500, output: "draining\n" }, | |
| 163 | new: { port: 39002, portsLost: 2, waitedMs: 28000, output: stderr }, | |
| 164 | }; | |
| 165 | ||
| 166 | test("a new forge that never joined: its port, ports lost, wait and last lines", () => { | |
| 167 | const p = judge(t, { ...rolled, newInRotationMs: null, oldExitMs: null }, seen).problem; | |
| 168 | expect(p).toBe( | |
| 169 | "the new forge never became ready: the new forge on port 39002, 2 ports lost, waited 28000 ms; " + | |
| 170 | "it last wrote: line 25 | line 26 | line 27 | line 28 | line 29", | |
| 171 | ); | |
| 172 | expect(p).not.toContain("39001"); | |
| 173 | }); | |
| 174 | ||
| 175 | test("an old forge that never exited: its port and the wait since its SIGTERM", () => { | |
| 176 | const v = judge(t, { ...rolled, oldExitMs: null }, seen); | |
| 177 | expect(v.ok).toBe(false); | |
| 178 | expect(v.problem).toBe( | |
| 179 | "the old forge did not exit: the old forge on port 39001, 0 ports lost, waited 30500 ms; it last wrote: draining", | |
| 180 | ); | |
| 181 | // One line, so report's first line carries all of it. | |
| 182 | expect(report(v).split("\n")[0]).toBe(`no verdict: ${v.problem}`); | |
| 183 | }); | |
| 184 | ||
| 185 | test("the quoted stderr is cut short, and silence is said", () => { | |
| 186 | const long = { ...seen.new, output: `${"x".repeat(2000)}\n`.repeat(PROBLEM_TAIL_LINES + 3) }; | |
| 187 | const p = judge(t, { ...rolled, newInRotationMs: null }, { new: long }).problem ?? ""; | |
| 188 | expect(p.length).toBeLessThan(PROBLEM_TAIL_CHARS + 200); | |
| 189 | expect(p).toContain("it last wrote: …x"); | |
| 190 | const quiet = judge(t, { ...rolled, newInRotationMs: null }, { new: { ...long, output: "" } }); | |
| 191 | expect(quiet.problem).toEndWith("waited 28000 ms; it wrote nothing"); | |
| 192 | }); | |
| 193 | }); | |
| 194 | ||
| 154 | 195 | describe("a forge that does not come up says which, where and why", () => { |
| 155 | 196 | const base = { |
| 156 | 197 | name: "old" as const, |