import { describe, expect, test } from 'bun:test'; import { existsSync, readFileSync, readdirSync } from 'node:fs'; import { join } from 'node:path'; import { declaredBlockCaps, declaredCapEntries, mergeBlockTiming, overBudgetBlocks, parseBlockDurations, parseJunitDurations, serializeBlockTiming, tightBlocks, } from './block-timing'; const REPO_ROOT = join(import.meta.dir, '..', '..', '..'); /** * Fixtures are copied verbatim out of real `e2e/results/*​/output.log` files — * a hand-written mirror would give confident coverage of a format bun does not * emit, which is the same bug one level up. */ // modules/wireguard-manager/e2e, run 2026-09-05T04-35-43. Stage 1 ran 155s and // blew an assertion; stages 2-8 are requireStage cascade-skips. const CASCADE = ` (fail) wireguard-manager runs behind the idp on the private ingress > stage 1: firewall, registrar and public ingress [155030.65ms] 8 | function requireStage(_label: string) { (fail) wireguard-manager runs behind the idp on the private ingress > stage 2: authentik provides idp [39.19ms] ^ error: Skipped: deploy stage failed — timeout after 120000ms (fail) wireguard-manager runs behind the idp on the private ingress > stage 3: the control-plane tunnel [1.29ms] ^ error: Skipped: deploy stage failed — timeout after 120000ms ` .trim() .split('\n'); // Modeled on the wave-0 census alerting log (e2e/results/2026-09-06T04-21-57, // celilo#1291), where the layout was read verbatim: stage 1 failed for REAL at // 1021397ms, and the text under its (fail) line is stage 2's skip message, // because bun prints a block's own error ABOVE its (fail) line. The forward // window the skip filter used before read that message and deleted stage 1's // measurement — the exact block this file exists to keep. const CENSUS_SHAPE = ` CeliloCommandError: module deploy caddy failed stderr: "\\ntimeout after 180000ms", exitCode: 124, killed 1 dangling process (fail) alerting reflects real module health > stage 1: a healthy deployed module raises no alerts [1021397.57ms] 35 | describe('alerting reflects real module health', () => { error: Skipped — prior stage failed (stage 1) at requireStage (alerting.test.ts:40:31) (fail) alerting reflects real module health > stage 2: a broken service produces an alert naming the failing check [6.91ms] 35 | describe('alerting reflects real module health', () => { error: Skipped — prior stage failed (stage 1) at requireStage (alerting.test.ts:40:31) (fail) alerting reflects real module health > stage 3: a degrading system accumulates alerts [3.47ms] ` .trim() .split('\n'); const CENSUS_JUNIT = ` `; describe('parseBlockDurations', () => { test('records the block that ran and drops the cascade-skips behind it', () => { expect(parseBlockDurations(CASCADE)).toEqual({ 'stage 1: firewall, registrar and public ingress': 155031, }); }); test('a sub-millisecond skip is never recorded as a fast healthy block', () => { // The whole point: 39.19ms for "stage 2" is the absence of a measurement. // Recorded, it reads as a block with 300s of headroom. const blocks = parseBlockDurations(CASCADE); expect(Object.keys(blocks)).not.toContain('stage 2: authentik provides idp'); }); test('a real failure that is not a cascade-skip IS recorded', () => { const lines = [ '(fail) split-horizon views > deploy resolver (in dmz) + caddy [300001.00ms]', ' ^ this test timed out after 300000ms.', ]; expect(parseBlockDurations(lines)).toEqual({ 'deploy resolver (in dmz) + caddy': 300001, }); }); test('bun printing its result list twice yields one entry', () => { const once = '(pass) suite > stage 1 [1234.50ms]'; expect(parseBlockDurations([once, once])).toEqual({ 'stage 1': 1235 }); }); test('strips colour, since bun renders the list with ANSI', () => { const lines = ['\x1b[32m(pass)\x1b[0m suite \x1b[2m>\x1b[0m stage 1 \x1b[2m[900.00ms]\x1b[0m']; expect(parseBlockDurations(lines)).toEqual({ 'stage 1': 900 }); }); test('an unnested test keeps its own name', () => { expect(parseBlockDurations(['(pass) deploys caddy directly [400.00ms]'])).toEqual({ 'deploys caddy directly': 400, }); }); test('ignores lines that are not bun results', () => { expect(parseBlockDurations(['Ran 3 tests across 1 file. [1892.67s]', ' 0 pass'])).toEqual({}); }); test('a real failure is not deleted by the sibling skip messages printed under its line', () => { // The celilo#1291 regression: stage 1 ran 1021s and failed on its own // error, and the marker filter read stage 2's "Skipped — prior stage // failed" from beneath its (fail) line, classified it as a cascade-skip, // and returned {} for the whole suite. The duration guard carries the // record now: stage 1 failed and did real work, so it stays. expect(parseBlockDurations(CENSUS_SHAPE, CENSUS_JUNIT)).toEqual({ 'stage 1: a healthy deployed module raises no alerts': 1021398, }); }); test('census-shaped skip siblings are still dropped', () => { // Stages 2 and 3 never ran: they failed, and their measured durations are // a fraction of the did-no-work threshold. const blocks = parseBlockDurations(CENSUS_SHAPE, CENSUS_JUNIT); expect(Object.keys(blocks)).toEqual(['stage 1: a healthy deployed module raises no alerts']); }); }); describe('mergeBlockTiming', () => { test('replaces a suite wholesale so a split stops reporting the old block', () => { const before = { alerting: { 'stage 1': 100, 'stage 2': 200 } }; expect(mergeBlockTiming(before, 'alerting', { 'stage 1a': 50, 'stage 1b': 60 })).toEqual({ alerting: { 'stage 1a': 50, 'stage 1b': 60 }, }); }); test('a run that parsed no blocks leaves the record alone', () => { const before = { alerting: { 'stage 1': 100 } }; expect(mergeBlockTiming(before, 'alerting', {})).toBe(before); }); test('other suites are untouched', () => { const before = { alerting: { a: 1 }, smoke: { b: 2 } }; expect(mergeBlockTiming(before, 'alerting', { a: 9 })).toEqual({ alerting: { a: 9 }, smoke: { b: 2 }, }); }); }); test('serializeBlockTiming sorts suites and blocks so the file diffs by value', () => { const out = serializeBlockTiming({ zed: { b: 2, a: 1 }, alpha: { c: 3 } }); expect(out).toBe( '{\n "alpha": {\n "c": 3\n },\n "zed": {\n "a": 1,\n "b": 2\n }\n}\n', ); }); describe('declaredBlockCaps', () => { test('reads the third argument of each test block', () => { const src = [ " test('stage 1: deploy', async () => {", ' await thing();', ' }, 300_000);', '', " test('stage 2: verify', async () => {", ' }, 120_000);', ].join('\n'); expect(declaredBlockCaps(src)).toEqual({ 'stage 1: deploy': 300_000, 'stage 2: verify': 120_000, }); }); test('a block with no third argument gets no cap, not a default', () => { // It silently inherits the runner's `--timeout 3600000`. Reporting a // fabricated 300s here would hide exactly that. const src = [" test('uncapped', async () => {", ' });'].join('\n'); expect(declaredBlockCaps(src)).toEqual({}); }); test('a template-literal name is skipped rather than mis-keyed', () => { const src = [' test(`stage 2: ${host} resolves`, async () => {', ' }, 60_000);'].join('\n'); // Interpolated names cannot be matched against a runtime block name, so the // parser must not invent a key for them. expect(Object.keys(declaredBlockCaps(src))).toHaveLength(0); }); test('reads the wrapped format biome emits for stage()', () => { const src = [ ' stage(', " 'stage 1: stand up the topology',", ' async () => {', ' await thing();', ' },', ' 300_000,', ' );', ].join('\n'); expect(declaredBlockCaps(src)).toEqual({ 'stage 1: stand up the topology': 300_000 }); }); test('a wrapped block with no timeout inherits the hour, silently', () => { const src = [ ' stage(', " 'stage 2: verify',", ' async () => {', ' await thing();', ' },', ' );', ].join('\n'); expect(declaredBlockCaps(src)).toEqual({}); }); }); describe('declaredCapEntries', () => { test('reports the line of the closer that declared the cap', () => { const src = [ ' stage(', " 'stage 1: deploy',", ' async () => {', ' await thing();', ' },', ' 300_000,', ' );', ].join('\n'); expect(declaredCapEntries(src)).toEqual([{ name: 'stage 1: deploy', capMs: 300_000, line: 6 }]); }); test('a nested object close followed by `});` does not steal the block name', () => { // The literal shape that bit aspect-fanout-new-systems stage 1: a nested // `},` line arms the timeout expectation, the `});` line consumed it, and // the real block closer recorded as unattributed. const src = [ ' stage(', " 'stage 1: deploy',", ' async () => {', ' await net.respondWith({', " interview: { 'a.b': 'c' },", ' });', ' });', ' await thing();', ' },', ' 900_000,', ' );', ].join('\n'); expect(declaredBlockCaps(src)).toEqual({ 'stage 1: deploy': 900_000 }); }); test('a nested waitFor closer does not steal the block name or its cap', () => { const src = [ ' stage(', " 'stage 1: deploy',", ' async () => {', ' await net.waitFor(', ' async () => {', ' return (await probe()) === true;', ' },', ' 30_000,', " 'probe to pass',", ' );', ' },', ' 900_000,', ' );', ].join('\n'); expect(declaredBlockCaps(src)).toEqual({ 'stage 1: deploy': 900_000 }); }); test('a template-literal name yields an unattributed entry, not silence', () => { const src = [' test(`stage ${n}: x`, async () => {', ' }, 60_000);'].join('\n'); expect(declaredCapEntries(src)).toEqual([{ name: null, capMs: 60_000, line: 2 }]); }); }); describe('tightBlocks', () => { const caps = { a: 300_000, b: 300_000, c: 120_000 }; test('flags a block at or above the fraction, ordered worst first', () => { const got = tightBlocks({ a: 240_000, b: 291_000, c: 10_000 }, caps); expect(got.map((t) => t.block)).toEqual(['b', 'a']); }); test('a block with no declared cap is absent, not assumed healthy', () => { expect(tightBlocks({ unknown: 3_000_000 }, caps)).toEqual([]); }); test('a block with no measurement is absent', () => { expect(tightBlocks({}, caps)).toEqual([]); }); test('a block that blew its cap is still reported', () => { expect(tightBlocks({ a: 300_001 }, caps)[0].fraction).toBeGreaterThan(1); }); }); describe('overBudgetBlocks', () => { // The celilo#1291 recurrence gate: a check over a finished run's junit.xml // that FAILS when any block exceeds its declared cap. The census's alerting // run produced exactly this junit against exactly these caps and every // downstream consumer reported nothing, because the skip filter dropped the // block before anything compared it to a cap. This function reads the junit // directly, so the measurement cannot be filtered away first. const source = [ " test('stage 1: a healthy deployed module raises no alerts', async () => {", ' }, 300_000);', " test('stage 2: a broken service produces an alert', async () => {", ' }, 180_000);', ].join('\n'); test('flags the census overrun: 1021398ms against a 300000ms declaration', () => { const overruns = overBudgetBlocks(CENSUS_JUNIT, source); expect(overruns).toEqual([ { block: 'stage 1: a healthy deployed module raises no alerts', ms: 1021398, capMs: 300000, fraction: 1021398 / 300000, }, ]); }); test('a run within its caps passes the gate', () => { const within = CENSUS_JUNIT.replace('time="1021.398"', 'time="102.398"'); expect(overBudgetBlocks(within, source)).toEqual([]); }); test('a block with no declared cap is not enforceable and stays out', () => { const uncapped = CENSUS_JUNIT.replace( 'stage 1: a healthy deployed module raises no alerts', 'stage 1: an uncapped block', ); expect(overBudgetBlocks(uncapped, source)).toEqual([]); }); test('the census junit against the real alerting caps reports the real overrun', () => { // Reach, not reasoning: the actual fixture from the wave-0 census run, // against the caps the actual suite file declares. const src = readFileSync(join(REPO_ROOT, 'e2e', 'tests', 'alerting.test.ts'), 'utf-8'); const overruns = overBudgetBlocks(CENSUS_JUNIT, src); expect(overruns.length).toBe(1); expect(overruns[0].fraction).toBeGreaterThan(3); }); }); describe('the cap parser reaches the real suites', () => { // Measuring reach, not reasoning about it. A style change that stops the // parser matching would otherwise turn every suite into "no cap declared" — // a confident, well-formed report about nothing (celilo#1268). const files: string[] = []; const roots = [join(REPO_ROOT, 'e2e', 'tests')]; for (const m of readdirSync(join(REPO_ROOT, 'modules'))) { const d = join(REPO_ROOT, 'modules', m, 'e2e'); if (existsSync(d)) roots.push(d); } for (const r of roots) { if (!existsSync(r)) continue; for (const f of readdirSync(r)) if (f.endsWith('.test.ts')) files.push(join(r, f)); } test('finds test files to read at all', () => { expect(files.length).toBeGreaterThan(30); }); test('most e2e blocks declare a cap the parser can read', () => { let withCap = 0; let blocks = 0; for (const f of files) { const src = readFileSync(f, 'utf-8'); blocks += (src.match(/^\s*(?:test|it|stage)(?:\.\w+)?\(/gm) ?? []).length; withCap += Object.keys(declaredBlockCaps(src)).length; } // 227 of ~260 at the time this was written. The floor is deliberately well // under that: it must fail on a parser that stops working, not on a suite // being added. expect(blocks).toBeGreaterThan(150); expect(withCap / blocks).toBeGreaterThan(0.6); }); test('reads split-horizon-views, the suite this gate was written for', () => { const f = join( REPO_ROOT, 'modules', 'knot-unbound-internal', 'e2e', 'split-horizon-views.test.ts', ); const caps = declaredBlockCaps(readFileSync(f, 'utf-8')); expect(Object.keys(caps).length).toBeGreaterThan(0); for (const cap of Object.values(caps)) expect(cap).toBeLessThanOrEqual(300_000); }); }); describe('no e2e suite declares the same block name twice', () => { // The record is keyed on the block name, so two blocks sharing one inside a // suite collapse into a single entry and the slower one hides the other. Hit // for real while splitting celilo-apt-deploy: cutting stage 1 into six left a // second "stage 3" and a second "stage 4" further down the file. const files: string[] = []; const roots = [join(REPO_ROOT, 'e2e', 'tests')]; for (const m of readdirSync(join(REPO_ROOT, 'modules'))) { const d = join(REPO_ROOT, 'modules', m, 'e2e'); if (existsSync(d)) roots.push(d); } for (const r of roots) { if (!existsSync(r)) continue; for (const f of readdirSync(r)) if (f.endsWith('.test.ts')) files.push(join(r, f)); } test('every declared block name is unique within its file', () => { const dupes: string[] = []; for (const f of files) { const seen = new Set(); for (const m of readFileSync(f, 'utf-8').matchAll( /^\s*(?:test|it)(?:\.\w+)?\(\s*['"](.+?)['"]\s*,/gm, )) { const name = m[1]; if (seen.has(name)) dupes.push(`${f.slice(REPO_ROOT.length + 1)}: "${name}"`); seen.add(name); } } expect(dupes).toEqual([]); }); }); // Emitted by `bun test --reporter=junit` for the cascade shape above: one real // failure, one requireStage skip, one PASS. Copied from a real bun 1.3.3 run. const CASCADE_JUNIT = ` `; const CASCADE_STDOUT = [ '(fail) stage 1: the real work [123.54ms]', ' ^ error: expect(received).toBe(expected)', '(fail) stage 2: cascade [0.26ms]', ' ^ error: Skipped: deploy stage failed — deploy: boom', ] .join('\n') .split('\n'); describe('parseJunitDurations', () => { test('reads seconds with microsecond precision into ms', () => { expect(parseJunitDurations(CASCADE_JUNIT)).toEqual({ 'stage 1: the real work': 124, 'stage 2: cascade': 0, 'stage 3: passes': 201, }); }); test('covers a block that PASSED — the whole reason this source exists', () => { // bun's console prints nothing for a passing test. Measured across 108 // recorded output.log files: zero contain a "(pass)" line. expect(parseJunitDurations(CASCADE_JUNIT)['stage 3: passes']).toBe(201); }); test('unescapes an XML-escaped block name', () => { const xml = ''; expect(parseJunitDurations(xml)).toEqual({ 'a & b ': 1500 }); }); test('ignores a testcase with no time', () => { expect(parseJunitDurations('')).toEqual({}); }); }); describe('parseBlockDurations with a JUnit report', () => { test('records the pass and the real failure, and drops the cascade-skip', () => { expect(parseBlockDurations(CASCADE_STDOUT, CASCADE_JUNIT)).toEqual({ 'stage 1: the real work': 124, 'stage 3: passes': 201, }); }); test('falls back to stdout when a crash left no JUnit file', () => { // Every bun JUnit failure is a bare , so // nothing in the XML distinguishes a cascade-skip from a real failure, and // the stdout fallback has only durations and markers. The record keys on // the duration: stage 2's "Skipped:" marker is visible here and changes // nothing. expect(parseBlockDurations(CASCADE_STDOUT, undefined)).toEqual({ 'stage 1: the real work': 124, }); }); }); // wireguard-manager-private, run 2026-09-05T09-30-56. bun prints a six-line // source excerpt before the message when the throw carries a stack, so // `error: Skipped:` lands well past where a short window would look. The // four-line window this replaced recorded all six of these skips at 0.0s. const SKIP_WITH_SOURCE_EXCERPT = `(fail) wireguard-manager > stage 3: the control-plane tunnel [10.62ms] 67 | let net: NetworkHandle; 68 | let stageError: string | null = null; 69 | let alphaKey = ''; 70 | 71 | function requireStage(stage: string): void { 72 | if (stageError) throw new Error(\`Skipped: \${stage} stage failed — \${stageError}\`); ^ error: Skipped: tunnel stage failed — idp: celilo module import failed (exit 1) at requireStage (/repo/modules/wireguard-manager/e2e/x.test.ts:72:29) (fail) wireguard-manager > stage 4: internal resolver [0.85ms] 67 | let net: NetworkHandle; ^ error: Skipped: resolver stage failed — idp: celilo module import failed (exit 1) `.split('\n'); describe('a cascade-skip behind a source excerpt', () => { test('is dropped from the record by its did-no-work duration, marker or no marker', () => { // This log's layout is the OPPOSITE of the census alerting log's: the skip // message sits below its own (fail) line here, above it there. No window // over the text attributes soundly across both; the duration does. const junit = ` `; expect(parseBlockDurations(SKIP_WITH_SOURCE_EXCERPT, junit)).toEqual({ 'stage 1: firewall, registrar and public ingress': 300001, }); }); }); describe('a failed block that did no work is not a measurement', () => { // wireguard-manager-private 2026-09-05T09-42-54. bun prints the message AFTER // the result line as each test completes and BEFORE it in the end-of-file // listing, so the last failing block's "Skipped:" is above its own line in // both. It leaked through the marker filter at 0.25ms. const lines = [ '(fail) wireguard-manager > stage 8: pausing the manager does not disturb the tunnel [0.25ms]', '[progress:start] stopping network | network stopped', ' 0 pass', ' 8 fail', ]; const junit = ''; test('is dropped even when the marker is nowhere the filter can see it', () => { expect(parseBlockDurations(lines, junit)).toEqual({}); }); test('a fast block that PASSED is kept — that is a real measurement', () => { const passing = ['(fail) other > stage 1 [500.00ms]']; const j = ''; expect(parseBlockDurations(passing, j)).toEqual({ 'quick assertion': 2 }); }); test('a failed block that did real work is kept', () => { const j = ''; const l = [ '(fail) suite > stage 1: deploy [300001.00ms]', ' ^ this test timed out after 300000ms.', ]; expect(parseBlockDurations(l, j)).toEqual({ 'stage 1: deploy': 300001 }); }); });