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

The test runner stops killing healthy shards, and each test file is isolated #7817

Merged opened this

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

Merged

torque/forge:torque/7788-the-test-runner-stops-killing-healthy-sh → main 5 commits fork 2 threads · 2 unresolved

  • Merged. torque/7788-the-test-runner-stops-killing-healthy-sh was merged into main as 5b0f109.

Review

Sign in to review this change.
7 files changed +202 −53
scripts/gate-summary.ts +2 −4
@@ -75,7 +75,7 @@ export type GateSummary = {
7575 memory: CgroupMemory;
7676 /** Spawn of the first file to exit of the last, in seconds. */
7777 wallSeconds: number;
78 /** Every file that ran, alone in its own `bun test`, and how long it took; fewer than `files` when fail-fast skipped some. */
78 /** Every file that ran, alone in its own `bun test`, and how long it took. */
7979 times: readonly { file: string; seconds: number }[];
8080 };
8181
@@ -106,14 +106,12 @@ export function summaryLines(s: GateSummary): string[] {
106106 ? `${gib(s.memory.peak.bytes)}${s.memory.limit ? ` of ${gib(s.memory.limit.bytes)}` : ""} (${s.memory.peak.from})`
107107 : "unknown here";
108108 const top = slowest.slice(0, SLOWEST);
109 // Fail-fast leaves files unstarted: the list is of the files that ran.
110 const skipped = s.files - s.times.length;
111109 return [
112110 GATE_SUMMARY_HEADING,
113111 `test-shards: shards: ${why(s)}`,
114112 `test-shards: wall: ${s.wallSeconds.toFixed(1)}s`,
115113 `test-shards: peak memory: ${peak}`,
116 `test-shards: slowest ${top.length} of ${s.times.length} files${skipped > 0 ? ` (${skipped} of ${s.files} skipped after a red file)` : ""}:`,
114 `test-shards: slowest ${top.length} of ${s.times.length} files:`,
117115 ...top.map((t) => ` ${t.seconds.toFixed(1).padStart(6)}s ${t.file}`),
118116 ...slowest
119117 .filter((t) => t.seconds > SLOW_SECONDS)
scripts/shards.ts +29 −4
@@ -394,11 +394,36 @@ export interface ShardResult {
394394 }
395395
396396 /**
397 * Whether a finished shard stops the shards not yet done (fail-fast): any
398 * red does. A wall-clock budget cannot be one in a check (#7789).
397 * The most shards one run re-runs after a crash outside any test (#7788).
398 * One crash is a leaked timer or socket from a file before; more than
399 * this is a change that breaks loading, and re-running it only doubles
400 * the wall.
399401 */
400 export function stopsTheRest(result: Pick<ShardResult, "code" | "output">): boolean {
401 return result.code !== 0;
402 export const CRASH_RERUNS = 3;
403
404 /**
405 * Whether a finished shard crashed outside any test: it went red and its
406 * report is not only failed tests ({@link onlyTestFailures}) — an
407 * unhandled error between tests ("Cannot use a closed database" from a
408 * timer the file before left), a file that would not load, a process that
409 * died before its summary. Such a shard is re-run once, whole.
410 */
411 export function crashedOutside(result: Pick<ShardResult, "code" | "output">): boolean {
412 return result.code !== 0 && !onlyTestFailures(result.output);
413 }
414
415 /**
416 * The crashed run's output, kept in the log for whoever reads it, each line
417 * behind ` │ ` so nothing that reads the log (the tally, the failing-test
418 * list, the budget re-run) counts its reds beside the re-run's.
419 */
420 export function quoteCrash(where: string, code: number, output: string): string {
421 const lines = output.replace(/\n$/, "").split("\n");
422 return [
423 `test-shards: shard ${where} crashed outside any test (exit ${code}); re-running it once. The crashed run:`,
424 ...lines.map((line) => ` │ ${line}`),
425 "",
426 ].join("\n");
402427 }
403428
404429 /** What the log ends with, and the exit code of the whole run. */
scripts/test-shards.ts +50 −31
@@ -22,9 +22,13 @@
2222 * log tails live;
2323 * shards that run side by side are written through whole as each
2424 * finishes, so the log reads one shard at a time. Either way the tail
25 * names every failing test from every shard. The first red shard stops
26 * the rest (fail-fast) so a known fail does not burn the remaining wall
27 * clock. Exits non-zero if any shard does.
25 * names every failing test from every shard: every shard runs to the end,
26 * whatever goes red, so one red never hides another (#7788). A shard that
27 * crashed outside any test (an unhandled error between tests, a file that
28 * would not load, a process that died before its summary) is re-run once,
29 * whole, and judged by that run; the log keeps the crashed run quoted
30 * behind ` │ `. At most `CRASH_RERUNS` shards are re-run so. Exits
31 * non-zero if any shard does.
2832 *
2933 * `--keep-going` is the verification after landing (#7786): no shard stops
3034 * the rest, a file red on its own is run once more alone (green then, it
@@ -73,7 +77,9 @@ import {
7377 budgetLast,
7478 failingFiles,
7579 onlyTestFailures,
76 stopsTheRest,
80 crashedOutside,
81 quoteCrash,
82 CRASH_RERUNS,
7783 type ShardResult,
7884 } from "./shards.ts";
7985 import { gateFiles, gateRefusal, presentTests } from "./gate.ts";
@@ -472,9 +478,10 @@ const unmeasured = new Set<string>();
472478
473479 // Failing files a red shard re-runs alone.
474480 const RETRY_CAP = 3;
475 // Set once any shard has gone red for good: no retries then.
476 let halted = false;
477 const stopping = (): boolean => halted;
481 // Shards re-run after a crash outside any test, so far.
482 let crashReruns = 0;

RED_SIGN is matched per chunk, so a marker split across two chunks streams bare. Buffer a line tail, or say in this comment that the miss is accepted.

483 /** What a live first run shows once it has gone red: held until its end. */
484 const RED_SIGN = /^(\(fail\)|# Unhandled error|error:)/m;
478485
479486 type Timed = ShardResult & { seconds: number };
480487
@@ -503,7 +510,7 @@ async function runShardIn(
503510 live: boolean,
504511 home: string,
505512 ): Promise<Timed> {
506 const started = performance.now();
513 let started = performance.now();
507514 const where = `${index + 1}/${slices.length}`;
508515 // Print before spawn so a mid-suite cgroup SIGKILL still leaves a breadcrumb.
509516 // stderr: Actions often block-buffers stdout until exit; an OOM never flushes.
@@ -562,9 +569,37 @@ async function runShardIn(
562569 process.stdout.write(text);
563570 }
564571 : undefined;
565 const first = await run(paths, cover, through);
572 // Live, the first run streams until the first sign of a red, then is held
573 // to its end: if it crashed it is quoted behind ` │` like a parallel
574 // shard's, never left bare, so nothing reading the log counts its
575 // `(fail)` lines beside the re-run. A clean run streams in full.
576 const mayRerun = crashReruns < CRASH_RERUNS;
577 const held: string[] = [];
578 const firstThrough =
579 through && mayRerun
580 ? (text: string): void => {
581 if (held.length > 0 || RED_SIGN.test(text)) held.push(text);
582 else through(text);
583 }
584 : through;
585 let first = await run(paths, cover, firstThrough);
586 // A crash outside any test re-runs the shard once, whole (#7788): the
587 // leaked-timer class ("Cannot use a closed database" between tests) is
588 // not this shard's tests failing. The re-run is the verdict, and its
589 // time the shard's time.
590 let quoted = "";
591 const crashed = crashReruns < CRASH_RERUNS && crashedOutside({ code: first.code, output: first.output.join("") });
592 if (!crashed && held.length > 0) through?.(held.join(""));
593 if (crashed) {
594 crashReruns++;
595 quoted = quoteCrash(where, first.code, first.output.join(""));
596 if (live) process.stdout.write(quoted);
597 process.stderr.write(`test-shards: re-run ${where} after a crash (exit ${first.code})\n`);
598 started = performance.now();
599 first = await run(paths, cover, through);
600 }
566601 let code = first.code;
567 let output = first.output;
602 let output = quoted === "" ? first.output : [quoted, ...first.output];
568603 // Kept going, a file red on its own is run once more alone: green then,
569604 // it was a flake, and its first output (the `(fail)` lines) is set aside.
570605 if (code !== 0 && keepGoing && slice.length === 1) {
@@ -583,13 +618,12 @@ async function runShardIn(
583618 // A sliced shard that went red: each failing file (the first few) is run
584619 // once alone, same env and flags. One that passes alone was red only
585620 // beside others, and does not fail the check; the log names it.
586 if (code !== 0 && slice.length > 1 && !covDir && !stopping()) {
587 const report = output.join("");
621 if (code !== 0 && slice.length > 1 && !covDir) {
622 const report = first.output.join("");
588623 // A file that errored (not a failed test) keeps the whole shard red.
589624 const red = onlyTestFailures(report) ? failingFiles(report) : [];
590625 const alone = new Map<string, boolean>();
591626 for (const file of red.slice(0, RETRY_CAP)) {
592 if (stopping()) break;
593627 const again = await run([file.startsWith("/") || file.startsWith("./") ? file : `./${file}`], []);
594628 alone.set(file, again.code === 0);
595629 }
@@ -629,27 +663,18 @@ async function runShardIn(
629663 };
630664 }
631665
632 /** Runs slices `from` up to `to`, at most `width` at once, in the slices' order.
633 * Stops starting new slices after the first non-zero exit and signals
634 * in-flight children so a red shard does not burn the rest of the wall. */
666 /** Runs slices `from` up to `to`, at most `width` at once, in the slices' order. */
635667 async function pool(width: number, from: number, to: number): Promise<Timed[]> {
636668 const results: Timed[] = [];
637669 let next = from;
638670 async function worker(): Promise<void> {
639671 while (next < to) {
640 if (halted) break;
641672 const index = next++;
642 results[index] = await runShard(slices[index]!, index, width === 1);
643 // A verification after landing runs everything (#7786).
644 if (!keepGoing && stopsTheRest(results[index]!)) {
645 halted = true;
646 for (const child of children) child.kill("SIGTERM");
647 }
673 results[index - from] = await runShard(slices[index]!, index, width === 1);
648674 }
649675 }
650676 await Promise.all(Array.from({ length: width }, worker));
651 // Only slices that ran (parallel fail-fast leaves holes for never-started).
652 return results.filter((result): result is Timed => result !== undefined);
677 return results;
653678 }
654679
655680 const started = performance.now();
@@ -665,12 +690,6 @@ const results = [
665690 // Budget files, one at a time, once the rest are done and green.
666691 ...(await pool(1, mainSlices.length, slices.length)),
667692 ];
668 if (results.length < slices.length) {
669 const skipped = slices.length - results.length;
670 console.log(
671 `test-shards: fail-fast — skipped ${skipped} remaining shard${skipped === 1 ? "" : "s"} after a red exit`,
672 );
673 }
674693 const wall = (performance.now() - started) / 1000;
675694 const ending = tally(results, wall);
676695 const spread = results.map((result) => result.seconds);
test/fixtures/shard-crash-once.test.ts added +23
@@ -0,0 +1,23 @@
1 // On its first run this file leaves a timer that throws after its test,
2 // while its `afterAll` still holds the process. bun reports that as an
3 // unhandled error between tests, like "Cannot use a closed database" from
4 // a leaked timer. Its second run is green: `SHARD_CRASH_MARK` names the
5 // file that remembers the first. scripts/test-shards.ts re-runs such a
6 // shard once (#7788).
7 import { existsSync, writeFileSync } from "node:fs";
8 import { afterAll, test } from "bun:test";
9
10 const mark = process.env["SHARD_CRASH_MARK"];
11 const first = mark !== undefined && !existsSync(mark);
12 if (first) writeFileSync(mark!, "");
13
14 test("leaves a timer behind on its first run", () => {
15 if (first)
16 setTimeout(() => {
17 throw new Error("Cannot use a closed database");
18 }, 0);
19 });
20
21 afterAll(async () => {
22 await Bun.sleep(30);
23 });
test/gate-summary.test.ts −9
@@ -147,15 +147,6 @@ describe("summaryLines", () => {
147147 ]);
148148 });
149149
150 test("fail-fast skipped files: the heading says how many of those named never ran", () => {
151 const lines = summaryLines({
152 ...base,
153 files: 40,
154 times: [{ file: "test/red.test.ts", seconds: 3 }],
155 });
156 expect(lines[4]).toBe("test-shards: slowest 1 of 1 files (39 of 40 skipped after a red file):");
157 });
158
159150 test("FORGE_CHECK_SHARDS is named as the reason when it is set", () => {
160151 expect(summaryLines({ ...base, shards: 1, override: "1" })[1]).toBe(
161152 "test-shards: shards: 1 = least of FORGE_CHECK_SHARDS 1; 12 files",
test/shards-keep-going.test.ts +4 −2
@@ -62,12 +62,14 @@ describe("--keep-going", () => {
6262 expect(tests).not.toContain("test/a.test.ts");
6363 }, 60_000);
6464
65 test("without it, the first red stops the rest and no map is written", async () => {
65 test("without it, a red shard no longer stops the rest (#7788), no lone re-run, and no map is written", async () => {
6666 rmSync(join(dir, "seen"), { force: true });
6767 rmSync(join(dir, ".impact.json"), { force: true });
6868 const { code, out } = await shards(["--impact"]);
6969 expect(code).toBe(1);
70 expect(out).toContain("fail-fast");
70 expect(out).not.toContain("fail-fast");
71 expect(out).not.toContain(FLAKY_ALONE);
72 expect(out).toContain("Ran 3 tests across 3 files");
7173 expect(existsSync(join(dir, ".impact.json"))).toBe(false);
7274 }, 60_000);
7375
test/shards.test.ts +94 −3
@@ -12,6 +12,9 @@ import {
1212 SECONDS_PER_BYTE_DEFAULT,
1313 SHARDS_MAX,
1414 besideOthers,
15 crashedOutside,
16 CRASH_RERUNS,
17 quoteCrash,
1518 budgetLast,
1619 callsBudget,
1720 failingFiles,
@@ -951,6 +954,94 @@ describe("a failing file is run once more alone", () => {
951954 }, 30_000);
952955 });
953956
957 describe("a crash outside any test", () => {
958 const ran = "Ran 3 tests across 2 files. [9ms]";
959 test("is a red whose report is not only failed tests", () => {
960 expect(crashedOutside({ code: 1, output: `# Unhandled error between tests\n 3 pass\n 1 error\n${ran}` })).toBe(true);
961 expect(crashedOutside({ code: 137, output: "test/a.test.ts:\n(pass) a" })).toBe(true);
962 expect(crashedOutside({ code: 1, output: `(fail) a\n 1 fail\n${ran}` })).toBe(false);
963 expect(crashedOutside({ code: 0, output: "" })).toBe(false);
964 expect(CRASH_RERUNS).toBe(3);
965 });
966
967 test("is quoted in the log so nothing reading it counts the crashed run", () => {
968 const crashed = `test/a.test.ts:\n(fail) a [1.00ms]\n# Unhandled error between tests\n 0 pass\n 1 fail\n 1 error\nRan 1 test across 1 file. [3ms]\n`;
969 const quoted = quoteCrash("2/5", 1, crashed);
970 expect(quoted.split("\n")[0]).toBe(
971 "test-shards: shard 2/5 crashed outside any test (exit 1); re-running it once. The crashed run:",
972 );
973 expect(quoted).toContain(" │ # Unhandled error between tests");
974 const rerun = "test/a.test.ts:\n(pass) a [1.00ms]\n 1 pass\n 0 fail\nRan 1 test across 1 file. [3ms]\n";
975 const ending = tally([{ files: ["test/a.test.ts"], code: 0, output: quoted + rerun }], 1);
976 expect(ending.code).toBe(0);
977 expect(ending.lines.join("\n")).not.toContain("(fail)");
978 expect(failingFiles(quoted + rerun)).toEqual([]);
979 expect(onlyTestFailures(quoted + rerun)).toBe(true);
980 });
981 });
982
983 describe("every shard runs to the end, and a crashed one once more", () => {
984 const script = new URL("../scripts/test-shards.ts", import.meta.url).pathname;
985 const scratch = mkdtempSync(join(tmpdir(), "shard-crash-"));
986 // Heavy by bytes, so it runs first and gets a shard of its own.
987 const heavyRed = join(scratch, "heavy-red.test.ts");
988 writeFileSync(heavyRed, `import { expect, test } from "bun:test";\ntest("heavy red", () => { expect(1).toBe(2); });\n// ${"padding ".repeat(4000)}\n`);
989 const filler = join(scratch, "shard-filler.test.ts");
990 writeFileSync(filler, `import { test } from "bun:test";\ntest("filler", () => {});\n// ${"padding ".repeat(4000)}\n`);
991 afterAll(() => rmSync(scratch, { recursive: true, force: true }));
992 const run = async (shards: string, files: string[], mark: string) => {
993 const env = { ...process.env, FORGE_CHECK_SHARDS: shards, FORGE_CELL_CPUS: "4", SHARD_CRASH_MARK: mark } as Record<string, string | undefined>;
994 for (const name of Object.keys(env)) if (name.startsWith("FORGE_CHECK_") && name !== "FORGE_CHECK_SHARDS") delete env[name];
995 const child = Bun.spawn(["bun", script, ...files], { stdin: "ignore", stdout: "pipe", stderr: "pipe", env });
996 const [out] = await Promise.all([new Response(child.stdout).text(), new Response(child.stderr).text()]);
997 return { code: await child.exited, out };
998 };
999
1000 test("a red file does not stop the files after it", async () => {
1001 // One worker, heaviest first: the red file runs before the green one.
1002 const got = await run("1", [heavyRed, "test/fixtures/shard-victim.test.ts"], join(scratch, "unused"));
1003 expect(got.code).toBe(1);
1004 expect(got.out).toContain("(fail) heavy red");
1005 expect(got.out).toContain("── shard 2/2: test/fixtures/shard-victim.test.ts");
1006 expect(got.out).not.toContain("fail-fast");
1007 }, 30_000);
1008
1009 test("a crash between tests re-runs its shard once, and the re-run is the verdict", async () => {
1010 const got = await run("2", [filler, "test/fixtures/shard-crash-once.test.ts", "test/fixtures/shard-victim.test.ts"], join(scratch, "crashed-once"));
1011 expect(got.out).toContain("crashed outside any test (exit 1); re-running it once. The crashed run:");
1012 expect(got.out).toContain(" │ error: Cannot use a closed database");
1013 expect(got.code).toBe(0);
1014 }, 30_000);
1015
1016 test("a single worker quotes the crashed run too: no bare error lines, and the re-run is green", async () => {
1017 const got = await run("1", ["test/fixtures/shard-crash-once.test.ts", "test/fixtures/shard-victim.test.ts"], join(scratch, "crashed-serial"));
1018 expect(got.out).toContain("crashed outside any test (exit 1); re-running it once. The crashed run:");
1019 expect(got.out).toContain(" │ error: Cannot use a closed database");
1020 const bare = got.out.split("\n").filter((line) => !line.startsWith(" │ "));
1021 expect(bare.some((line) => line.includes("Cannot use a closed database"))).toBe(false);
1022 expect(bare.some((line) => line.includes("# Unhandled error"))).toBe(false);
1023 expect(got.code).toBe(0);
1024 }, 30_000);
1025
1026 test("only CRASH_RERUNS crashed shards are re-run; the next stays red unre-run", async () => {
1027 const crashing = [1, 2, 3, 4].map((n) => {
1028 const file = join(scratch, `crash-${n}.test.ts`);
1029 writeFileSync(file, `throw new Error("boom at load ${n}");\n`);
1030 return file;
1031 });
1032 const got = await run("4", crashing, join(scratch, "unused"));
1033 expect(got.out.split("re-running it once").length - 1).toBe(CRASH_RERUNS);
1034 expect(got.code).toBe(1);
1035 }, 60_000);
1036
1037 test("a crash that happens again stays red", async () => {
1038 const got = await run("2", [filler, "test/fixtures/shard-errors.test.ts", "test/fixtures/shard-victim.test.ts"], join(scratch, "unused"));
1039 expect(got.out).toContain("re-running it once");
1040 expect(got.out).toContain("boom at load");
1041 expect(got.code).toBe(1);
1042 }, 30_000);
1043 });
1044
9541045 describe("budget files last, and a fixture suite in six shards (#7617)", () => {
9551046 const script = new URL("../scripts/test-shards.ts", import.meta.url).pathname;
9561047 const fixture = (files: Record<string, string>): string => {
@@ -1038,7 +1129,7 @@ describe("budget files last, and a fixture suite in six shards (#7617)", () => {
10381129 expect(order.slice(0, -1).join(" ").split(" ").sort()).toEqual(["a.test.ts", "b.test.ts", "c.test.ts"]);
10391130 }, 60_000);
10401131
1041 test("a red shard skips the budget files: the run is red and nothing crashes", async () => {
1132 test("a red shard does not skip the budget files: the run is red and nothing crashes", async () => {
10421133 const dir = fixture({
10431134 "bad.test.ts": `import { test, expect } from "bun:test";\ntest("the broken one", () => { expect(1).toBe(2); });\n`,
10441135 "a.test.ts": passing(1),
@@ -1048,8 +1139,8 @@ describe("budget files last, and a fixture suite in six shards (#7617)", () => {
10481139 rmSync(dir, { recursive: true, force: true });
10491140 expect(got.code).not.toBe(0);
10501141 expect(got.out).toContain("(fail) the broken one");
1051 expect(got.out).toMatch(/fail-fast — skipped \d+ remaining shards? after a red exit/);
1052 expect(finished(got.stdout).flat().join(" ")).not.toContain("slow.test.ts");
1142 expect(got.out).not.toContain("fail-fast");
1143 expect(finished(got.stdout).flat().join(" ")).toContain("slow.test.ts");
10531144 expect(got.out).not.toContain("undefined");
10541145 expect(got.out).not.toContain("TypeError");
10551146 }, 60_000);

↑↓ navigate ↵ open ⌘↵ its app esc close

Keyboard shortcuts

Docs