/** * Per-`test()`-block durations, recorded where something can read them later. * * The 300s budget in `apps/celilo/CLAUDE.md` is PER TEST BLOCK, not per suite. * `.e2e-timing.json` records suite totals only, so the one number the policy is * written against was recorded nowhere. bun prints it — `(pass) suite > stage 1 * [155030.65ms]` — into `output.log`, which lives in `e2e/results//` and is * deleted with it. In practice only FAILED suites ever get read, so the * population of blocks approaching the cap was unmeasured (celilo#1268). * * That gap is what let a table comparing SUITE totals against a PER-TEST cap * stand as a finding for twenty minutes: there was no per-block number to check * it against. Two suites falsified it by passing at durations the theory called * impossible (`module-pause` 303s, `aspect-fanout-new-systems` 401s) — both * spread over many blocks, neither anywhere near the cap. * * Pure parser + a merge, in its own module so it is testable: runner.ts calls * main() at import time, so nothing declared there is reachable from a test. */ import { stripAnsi } from './extract-failure'; /** suite name → test-block name → last measured duration in ms. */ export type BlockTiming = Record>; /** * One suite's per-block durations: what ran, and how long each block took. * * Durations come from bun's JUnit report when there is one, because that is the * only source covering blocks that PASSED. Console output names a block only * when it fails. A failed block that did no work is dropped by the duration * guard below; there is no message-based skip filter, for the reason recorded * there. */ /** * A failed block below this did no work, so its duration measures nothing. * * Measured, not guessed. Over the 58 recorded runs in `e2e/results/`, every * failed block falls in one of two clumps with nothing in between: * * did no work (a `requireStage` throw) 0.00ms .. 43.6ms * did real work over 2s, up to 140s * * The gap is narrower than those two clumps suggest, because the fastest real * work seen anywhere is not 2s. `CASCADE_STDOUT` in the test file pins a real * failure at 123.54ms, and celilo#1281 measured real blocks from 145ms. So the * floor has to sit between roughly 44ms and 123ms, and where it sits decides * which of two mistakes this file makes. * * At 50 the clearance over the worst observed skip is 1.15x. That is thin * enough that one slow skip enters the duration record as a healthy fast * block, which is the mistake that matters: it pollutes the baseline every * later run is compared against. At 100 the clearance is 2.3x, and the cost is * that a REAL failure under 100ms would be dropped. That is the cheaper * mistake. This file exists to find blocks running OUT of budget, and one * using 0.03% of its cap is not a candidate. * * Nothing observed is reclassified by the move. No failed block in the recorded * runs sits between 43.6ms and 2s, and no fixture sits between 39.19ms and * 123.54ms, so both keep their current verdict. */ const NOT_A_MEASUREMENT_MS = 100; export function parseBlockDurations(lines: string[], junitXml?: string): Record { const failed = failedBlocks(lines); const measured = junitXml ? parseJunitDurations(junitXml) : parseStdoutDurations(lines); const out: Record = {}; for (const [block, ms] of Object.entries(measured)) { // A failed block that did no work is a cascade-skip, and recording it would // enter a stage that never ran as a healthy fast one. The duration is the // sound signal — NOT any "Skipped:" marker in the console text. bun prints // a block's error message in two REAL and OPPOSITE layouts: below its own // (fail) line (wireguard-manager-private 2026-09-05T09-30-56, where the // message names its own stage) and ABOVE it, under the PREVIOUS block's // line (alerting, wave-0 census e2e/results/2026-09-06T04-21-57, where the // at-frames point into the NEXT stage's body). Same bun, days apart. Any // window reading text next to a (fail) line attributes a sibling's message // to this block in one layout or the other — and the forward version did // exactly that on the census: stage 1 failed for real at 1021397ms, the // filter read stage 2's skip message under its line, and deleted the one // measurement this file exists to keep (celilo#1291). Worst case now is a // skip that measured over 50ms entering the record as a fast healthy block // — cosmetic noise nowhere near any cap — instead of a real measurement // being deleted. if (failed.has(block) && ms < NOT_A_MEASUREMENT_MS) continue; out[block] = ms; } return out; } /** Every block bun reported as failing, by name. */ function failedBlocks(lines: string[]): Set { const out = new Set(); for (const line of lines.map(stripAnsi)) { if (isResultLine(line) && line.startsWith('(fail)')) out.add(blockNameOf(line)); } return out; } /** * Per-testcase durations from bun's JUnit reporter. * * The reporter is the ONLY source that covers passing blocks. bun's console * output prints `(fail) name [Nms]` as each test fails and nothing at all for a * test that passes — measured across 108 recorded `output.log` files, of which * ZERO contain a `(pass)` line. A record built from stdout therefore holds only * the blocks that already broke, which is the exact opposite of the question * ("which blocks are running out of room?"). * * Found by shipping the stdout version and reading what it wrote: one entry, for * the one stage that failed, out of seven that ran. * * `time` is seconds with microsecond precision. */ export function parseJunitDurations(xml: string): Record { const out: Record = {}; for (const m of xml.matchAll(/]*)\/?>/g)) { const attrs = m[1]; const name = attrs.match(/\bname="([^"]*)"/)?.[1]; const time = attrs.match(/\btime="([\d.]+)"/)?.[1]; if (!name || !time) continue; out[unescapeXml(name)] = Math.round(Number(time) * 1000); } return out; } function unescapeXml(s: string): string { return s .replace(/</g, '<') .replace(/>/g, '>') .replace(/"/g, '"') .replace(/'/g, "'") .replace(/&/g, '&'); } /** * Fallback for a run that produced no JUnit file — a crash, or an older bun. * Covers failures only, for the reason above. */ function parseStdoutDurations(lines: string[]): Record { const plain = lines.map(stripAnsi); const out: Record = {}; for (const line of plain) { if (!isResultLine(line)) continue; const ms = line.match(/\[([\d.]+)ms\]\s*$/); if (!ms) continue; const block = blockNameOf(line); if (!block) continue; out[block] = Math.max(out[block] ?? 0, Math.round(Number(ms[1]))); } return out; } function isResultLine(l: string): boolean { return /^\((?:pass|fail)\)\s+\S/.test(l); } /** bun renders nesting as "describe > block"; a cap is declared against the block. */ function blockNameOf(line: string): string { const full = line.replace(/^\((?:pass|fail)\)\s+/, '').replace(/\s*\[[\d.]+ms\]\s*$/, ''); return (full.includes(' > ') ? full.slice(full.lastIndexOf(' > ') + 3) : full).trim(); } /** * Fold one suite's blocks into the stored record, replacing that suite's entry. * * The suite is replaced rather than merged so a split shows up on the next run: * a block that no longer exists must stop being reported, or the record keeps * a fixed suite looking broken forever. */ export function mergeBlockTiming( stored: BlockTiming, suite: string, blocks: Record, ): BlockTiming { if (Object.keys(blocks).length === 0) return stored; return { ...stored, [suite]: blocks }; } /** Stable key order so the committed file diffs by value, not by iteration order. */ export function serializeBlockTiming(timing: BlockTiming): string { const suites = Object.keys(timing).sort(); const ordered: BlockTiming = {}; for (const s of suites) { const blocks = timing[s]; ordered[s] = Object.fromEntries( Object.keys(blocks) .sort() .map((b) => [b, blocks[b]]), ); } return `${JSON.stringify(ordered, null, 2)}\n`; } // ─── Declared caps, and blocks that are running out of room ────────── /** * The per-block budget each block (test() or stage()) declares as its third * argument. * * There is no other place to read it from. The runner spawns * `bun test --timeout 3600000`, so the CLI value is a backstop for debug * sessions; the number that governs a block is the literal in the source, and * a block with no literal silently inherits the hour. * * Measured, not assumed: an inline third argument DOES override the CLI value * (bun 1.3.3), including when the body swallows its own errors the way a staged * e2e suite does. * * Handles both formats biome produces: the one-line open/close * (`test('name', async () => {` ... `}, 300_000);`) and the wrapped one * (`stage(\n 'name',\n async () => {` ... `},\n 300_000,\n);`). */ export function declaredBlockCaps(source: string): Record { const caps: Record = {}; for (const entry of declaredCapEntries(source)) { if (entry.name !== null) caps[entry.name] = entry.capMs; } return caps; } export interface DeclaredCapEntry { /** * The block name as declared, or null when the closer could not be * attributed to a keyed opener (a template-literal name interpolates at * runtime, so the source text can never equal the name bun prints). * The timeout-cap gate fails loudly on null-named over-bar entries rather * than letting a real cap escape the manifest. */ name: string | null; capMs: number; /** 1-indexed source line of the closer that declared the cap. */ line: number; } /** * `declaredBlockCaps` with provenance: which line declared each cap, and * which closers went unattributed. The e2e-timeout-cap gate consumes this * so the manifest cites source lines and an over-bar closer the parser * cannot key fails the gate instead of escaping silently. */ export function declaredCapEntries(source: string): DeclaredCapEntry[] { const lines = source.split('\n'); const entries: DeclaredCapEntry[] = []; let pending: string | null = null; // the open block's name, if keyable let awaitingName = false; // multi-line open: the name is on the next line let closeIndent = -1; // the indent the block's closing `},` must sit at // Biome's wrapped form indents the body close one level past the opener: // stage( <- indent 2 // 'name', // async () => { <- indent 4 // ... <- indent 6 // }, <- indent 4 = opener + 2 // 900_000, // ); // The inline form closes at the opener's own indent: // test('name', async () => { ... }, 300_000); // A nested close (an object literal, a waitFor callback) is always DEEPER // than the block's close indent, so matching on indent is what keeps a // nested `},` from stealing the pending block's name — the failure that // made stage 1 of aspect-fanout-new-systems read as unattributed. const indentOf = (line: string) => line.length - line.trimStart().length; for (const [index, line] of lines.entries()) { // Any block-open clears `pending`, including one this parser cannot key on. // Skipping the line instead would leave the PREVIOUS block's name armed, so // the next `}, N)` would overwrite that block's cap with this one's. // stage() is the shared wrapper from @celilo/e2e for staged suites (ce-3ei3); // it takes the same (name, body, timeout) shape as test(). if (/^\s*(?:test|it|stage)(?:\.\w+)?\(/.test(line)) { // A template-literal name interpolates at runtime, so the source text can // never equal the name bun prints. Left uncapped rather than keyed on a // string nothing will ever match. pending = line.match(/^\s*(?:test|it|stage)(?:\.\w+)?\(\s*['"](.+?)['"]\s*,/)?.[1] ?? null; awaitingName = /\(\s*$/.test(line); closeIndent = indentOf(line) + (awaitingName ? 2 : 0); continue; } if (awaitingName) { const name = line.match(/^\s*['"](.+?)['"]\s*,?\s*$/); pending = name?.[1] ?? null; awaitingName = false; continue; } if (closeIndent === -1 || indentOf(line) !== closeIndent) continue; const bare = line.trimStart(); const close = bare.match(/^\},\s*([0-9_]+)\s*\)\s*;?\s*$/); if (close) { entries.push({ name: pending, capMs: Number(close[1].replace(/_/g, '')), line: index + 1 }); pending = null; closeIndent = -1; continue; } if (/^\},\s*$/.test(bare)) { // Wrapped form: the timeout is the next line, at the same indent. Any // other follower means this `},` closes the block with no cap at all. const next = lines[index + 1]; const timeout = next?.match(/^\s*([0-9_]+)\s*,\s*$/); if (timeout) { entries.push({ name: pending, capMs: Number(timeout[1].replace(/_/g, '')), line: index + 2, }); } pending = null; closeIndent = -1; } } return entries; } export interface TightBlock { block: string; ms: number; capMs: number; fraction: number; } /** * Blocks that finished inside their budget but had little of it left. * * This is the signal the census could not see. A block that BLOWS its cap says * "this test timed out after 300000ms" and reads as a slow host; a block that * lands at 95% says nothing at all, and is one ordinary night's load away from * the first case. Median inflation on the grind host is 1.14x and p90 is 1.58x, * so 80% of a cap is roughly a coin flip at p90. * * Blocks with no measurement, and blocks with no declared cap, are absent from * the result rather than assumed healthy. */ export function tightBlocks( measured: Record, caps: Record, fraction = 0.8, ): TightBlock[] { const out: TightBlock[] = []; for (const [block, ms] of Object.entries(measured)) { const capMs = caps[block]; if (!capMs) continue; if (ms < capMs * fraction) continue; out.push({ block, ms, capMs, fraction: ms / capMs }); } return out.sort((a, b) => b.fraction - a.fraction); } export interface OverBudgetBlock { block: string; ms: number; capMs: number; fraction: number; } /** * Blocks whose measured duration EXCEEDS the cap they declare, and the run must * fail on them. * * This reads the JUnit durations directly and deliberately bypasses * `parseBlockDurations`, whose skip filter exists to keep stages that never ran * out of the RECORD. A budget check has the opposite obligation: every block * that ran must be measured against its declaration, and the census proved the * cost of routing it through the record first. alerting stage 1 ran 1021397ms * against its own 300000ms declaration (celilo#1291) and every downstream * consumer saw nothing, because the skip filter misattributed a sibling's * message and dropped the block before anything could compare it to a cap. * * bun's per-test timeout is NOT the enforcer of this number. It is an * EventLoopTimer that can fail to fire while other timers in the same process * fire on schedule (the census: the deploy's own 180s budget fired at exactly * 180s into a block whose 300s bun timer never fired; oven-sh/bun#32056 * family). The declaration binds HERE, after the fact: the block still holds * the rig while it overruns, but a run that let it happen does not pass. */ export function overBudgetBlocks(junitXml: string, source: string): OverBudgetBlock[] { const measured = parseJunitDurations(junitXml); const caps = declaredBlockCaps(source); const out: OverBudgetBlock[] = []; for (const [block, ms] of Object.entries(measured)) { const capMs = caps[block]; if (!capMs) continue; if (ms <= capMs) continue; out.push({ block, ms, capMs, fraction: ms / capMs }); } return out.sort((a, b) => b.fraction - a.fraction); }