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 });
});
});