fix(#566): guard the file-scoped test timeout instead of splitting by size

.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

.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

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": {

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

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<string, {durationMs: number, success: boolean}>} */
+  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`;
+}