diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 6776fbf0f..d7cb043e6 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -137,6 +137,20 @@ jobs: - name: Test (node --test via tsx) run: npm run test + # `--test-timeout` is applied to the FILE, not to each leaf (#566): a + # file whose leaves are all fast but whose total crosses the ceiling is + # killed as a unit, and the failure is reported against whichever leaf + # happened to be running. #550 sized the ceiling on the slowest file of + # the day and nothing has watched the margin since — the spec and tap + # reporters flatten a glob to suite names, so the per-file total was not + # observable at all. The step above now also writes it; this turns it + # into a gate. Deliberately a fraction of the ceiling rather than a + # committed ms baseline: the same suite measures ~36s locally on 16 + # cores and ~172s here, so an absolute number would be either + # permanently red or permanently asleep. + - name: Test file durations (per-file timeout headroom, #566) + run: npm run test:filetimes + # Anti-silent-skip guard (#565). The pg suites self-skip when the DB # is unreachable, so a broken/renamed service would once again pass # green with zero Postgres coverage. Fail loudly here instead if the diff --git a/.gitignore b/.gitignore index 1d4d3fead..e51a1304e 100644 --- a/.gitignore +++ b/.gitignore @@ -35,6 +35,9 @@ middleware/.memory/ # Teams app package artifacts (manifest + icons ARE tracked; the zipped bundle isn't) middleware/appPackage/*.zip middleware/*.zip +# Per-file test durations, written by `npm test` and read by `test:filetimes` +# (issue #566). A measurement of the machine that ran it, not a repo fact. +middleware/test-file-durations.json # ─── Editor / OS ────────────────────────────────────────────────────────── .DS_Store diff --git a/middleware/package.json b/middleware/package.json index c2783db4a..3dba599e4 100644 --- a/middleware/package.json +++ b/middleware/package.json @@ -41,7 +41,8 @@ "eval:golden": "node --import tsx test/golden/goldenSet.eval.ts", "setup:tigris-lifecycle": "tsx scripts/setup-tigris-lifecycle.ts", "pretest": "node scripts/check-node-version.mjs", - "test": "node --import tsx --test --test-timeout=120000 --test-concurrency=4 --test-reporter=spec 'test/**/*.test.ts'", + "test": "node --import tsx --test --test-timeout=120000 --test-concurrency=4 --test-reporter=spec --test-reporter-destination=stdout --test-reporter=./scripts/testFileDurations.reporter.mjs --test-reporter-destination=test-file-durations.json 'test/**/*.test.ts'", + "test:filetimes": "node scripts/check-test-file-durations.mjs", "test:pg": "node --import tsx --test --test-timeout=120000 --test-concurrency=1 --test-reporter=spec 'test/**/*.pg.test.ts'" }, "engines": { diff --git a/middleware/scripts/check-test-file-durations.mjs b/middleware/scripts/check-test-file-durations.mjs new file mode 100644 index 000000000..8311fb94d --- /dev/null +++ b/middleware/scripts/check-test-file-durations.mjs @@ -0,0 +1,138 @@ +#!/usr/bin/env node +/** + * Guards the file-scoped `--test-timeout` (issue #566). + * + * THE RISK + * -------- + * node applies `--test-timeout` to the test FILE, not to each leaf. A file + * whose leaves are each fast but whose total crosses the ceiling is killed as + * a unit — and the failure looks like a timeout on whichever leaf happened to + * be running, not like "this file grew too big". #550 sized the ceiling on the + * slowest file of the day; nothing has watched the margin since. + * + * WHY A FRACTION AND NOT A COMMITTED BASELINE + * ------------------------------------------- + * The repo's other ratchets (core-decoupling, test-typecheck, PG_TEST_FLOOR) + * commit an absolute number, because they count things that do not vary by + * machine. Durations do: the same suite measured 36.5 s locally on 16 cores + * and 172 s on a 4-vCPU CI runner — a 4.7x spread. An absolute ms baseline + * would either be tuned for CI and never fire locally, or tuned locally and + * red on every CI run, and it would need re-committing every time the suite + * legitimately grows. That is the stale-baseline failure this repo has + * already been bitten by. + * + * A fraction of the ceiling is portable and cannot go stale: it measures the + * exact thing the issue is about — how close the slowest file is to being + * killed — on whatever machine is running. + * + * THE CEILING IS NOT DUPLICATED HERE + * ---------------------------------- + * It is parsed out of the `test` script in package.json, so lowering + * `--test-timeout` automatically tightens this guard instead of silently + * widening the gap between the two numbers. + * + * node scripts/check-test-file-durations.mjs # gate + * node scripts/check-test-file-durations.mjs --report # table only, always exit 0 + */ + +import { readFileSync, existsSync } from 'node:fs'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; + +const MIDDLEWARE_ROOT = path.resolve(path.dirname(fileURLToPath(import.meta.url)), '..'); +const DURATIONS_FILE = path.join(MIDDLEWARE_ROOT, 'test-file-durations.json'); +const PACKAGE_JSON = path.join(MIDDLEWARE_ROOT, 'package.json'); + +/** Fail once a single file burns this share of its own ceiling. */ +const FAIL_FRACTION = 0.5; +/** Name-and-shame threshold — visible long before it is a problem. */ +const WARN_FRACTION = 0.25; +/** How many of the slowest files to print. */ +const TOP_N = 10; + +function readTimeoutMs() { + const pkg = JSON.parse(readFileSync(PACKAGE_JSON, 'utf8')); + const script = pkg.scripts?.test ?? ''; + const match = /--test-timeout=(\d+)/.exec(script); + if (!match) { + throw new Error( + 'Could not read --test-timeout from the `test` script in package.json. ' + + 'This guard derives the ceiling from there on purpose — if the flag moved, ' + + 'point this parser at its new home rather than hardcoding a second copy.', + ); + } + return Number(match[1]); +} + +function main() { + const reportOnly = process.argv.includes('--report'); + + if (!existsSync(DURATIONS_FILE)) { + console.error( + `No ${path.relative(MIDDLEWARE_ROOT, DURATIONS_FILE)} found. Run \`npm test\` first — ` + + 'it writes the file via the testFileDurations reporter.', + ); + process.exit(1); + } + + const { files } = JSON.parse(readFileSync(DURATIONS_FILE, 'utf8')); + if (!Array.isArray(files) || files.length === 0) { + console.error( + 'test-file-durations.json contains no files. Either the run recorded nothing ' + + '(reporter not wired up?) or every file vanished — both are worth failing on, ' + + 'because a guard that silently checks zero files is worse than no guard.', + ); + process.exit(1); + } + + const ceilingMs = readTimeoutMs(); + const failMs = ceilingMs * FAIL_FRACTION; + const warnMs = ceilingMs * WARN_FRACTION; + + const sorted = [...files].sort((a, b) => b.durationMs - a.durationMs); + const slowest = sorted[0]; + + console.log(`Slowest test files (ceiling ${ceilingMs} ms per FILE, not per test)\n`); + for (const entry of sorted.slice(0, TOP_N)) { + const share = entry.durationMs / ceilingMs; + const flag = entry.durationMs >= failMs ? 'FAIL' : entry.durationMs >= warnMs ? 'WARN' : ' '; + console.log( + ` ${flag} ${String(Math.round(entry.durationMs)).padStart(7)} ms ` + + `${(share * 100).toFixed(1).padStart(5)}% ${entry.file}`, + ); + } + + const headroom = ceilingMs / slowest.durationMs; + console.log( + `\n ${files.length} files, slowest ${Math.round(slowest.durationMs)} ms ` + + `= ${headroom.toFixed(1)}x headroom to the ${ceilingMs} ms ceiling.`, + ); + + if (reportOnly) return; + + const offenders = sorted.filter((entry) => entry.durationMs >= failMs); + if (offenders.length > 0) { + console.error( + `\nA test file is within ${(1 - FAIL_FRACTION) * 100}% of the per-file timeout:\n`, + ); + for (const entry of offenders) { + console.error(` ${entry.file} — ${Math.round(entry.durationMs)} ms of ${ceilingMs} ms`); + } + console.error( + '\n`--test-timeout` kills the whole FILE, so this does not fail as one slow test —\n' + + 'it takes every test in the file with it, and blames whichever leaf was running.\n' + + 'Split the file, or make it faster. Raising --test-timeout only moves the cliff.', + ); + process.exit(1); + } + + const warned = sorted.filter((entry) => entry.durationMs >= warnMs); + if (warned.length > 0) { + console.log( + `\n ${warned.length} file(s) past ${WARN_FRACTION * 100}% of the ceiling — worth splitting before they reach ${FAIL_FRACTION * 100}%.`, + ); + } + console.log('\n✓ No test file is near the per-file timeout.'); +} + +main(); diff --git a/middleware/scripts/testFileDurations.reporter.mjs b/middleware/scripts/testFileDurations.reporter.mjs new file mode 100644 index 000000000..c2b2a6c8e --- /dev/null +++ b/middleware/scripts/testFileDurations.reporter.mjs @@ -0,0 +1,64 @@ +/** + * Records how long each test FILE took, so the file-scoped `--test-timeout` + * can be guarded (issue #566). + * + * WHY A REPORTER + * -------------- + * `--test-timeout` is applied to the test file, not to each leaf: a file whose + * leaves are 300 ms each but whose total is 1200 ms is killed outright at + * `--test-timeout=500`. So the number that matters is the per-FILE total, and + * nothing else reports it. The spec and tap reporters flatten to suite names — + * run a glob through them and the filename is gone — which is exactly why this + * risk has been invisible. + * + * `test:summary` is the one event that carries both `file` and `duration_ms`, + * and node emits it once per file. Collecting it costs nothing on top of a run + * that is happening anyway, which is the point: the guard must not double the + * CI test time it is guarding. + * + * Pair it with a second `--test-reporter-destination`, so the human-readable + * reporter keeps stdout: + * + * node --test \ + * --test-reporter=spec --test-reporter-destination=stdout \ + * --test-reporter=./scripts/testFileDurations.reporter.mjs \ + * --test-reporter-destination=test-file-durations.json + * + * Then `scripts/check-test-file-durations.mjs` turns the JSON into a gate. + */ + +import path from 'node:path'; + +export default async function* testFileDurations(source) { + /** @type {Map} */ + const files = new Map(); + + for await (const event of source) { + if (event.type !== 'test:summary') continue; + + const file = event.data?.file; + // A `test:summary` without a file is the run-level summary — not a file. + if (!file) continue; + + const durationMs = event.data?.duration_ms; + if (typeof durationMs !== 'number' || !Number.isFinite(durationMs)) continue; + + // node emits one summary per file; keep the longest if that ever changes, + // so the guard can only become more conservative, never less. + const previous = files.get(file); + if (previous && previous.durationMs >= durationMs) continue; + + files.set(file, { durationMs, success: event.data?.success !== false }); + } + + const cwd = process.cwd(); + const entries = [...files.entries()] + .map(([file, info]) => ({ + file: path.relative(cwd, file), + durationMs: Math.round(info.durationMs * 1000) / 1000, + success: info.success, + })) + .sort((a, b) => b.durationMs - a.durationMs); + + yield `${JSON.stringify({ files: entries }, null, 2)}\n`; +}