ci: the clock-shift job runs every test of a file, or fails (#848)

.github/workflows/clock-shift.yml

@@ -43,21 +43,23 @@ jobs:
           echo "$RUNNER_TEMP/bin" >> "$GITHUB_PATH"
       - run: npm run build
       - run: npm run build:web
-      # Each run finishes and names what failed: a test that hangs is cancelled after 10 minutes (--test-timeout) and
-      # named in the summary with its file, and a file whose tests are done exits even with a handle left open
-      # (--test-force-exit). A step that still runs too long stops on its own, and the next step runs anyway.
+      # Each run finishes and names what failed (scripts/ci/clock-shift-run.mjs, #848): every test file runs in a
+      # `node --test` of its own, without --test-force-exit, so every test it registers runs. A test that hangs is
+      # cancelled after 10 minutes (--test-timeout), and a file still running after 25 minutes (a hang, or a handle
+      # left open after its tests) is killed and named. A step that still runs too long stops on its own, and the next
+      # step runs anyway. test/clock-shift.test.ts runs these lines on fixtures.
       - name: the tests, 45 days later
         timeout-minutes: 75
         shell: bash
         env:
           CI_REQUIRE_WEB: '1'
           TEST_CLOCK_SHIFT: '+45d'
-        run: NODE_OPTIONS="--import=$PWD/dist/test/clock-shift.js" node --import ./dist/test/isolate.js --test --test-timeout=600000 --test-force-exit "dist/test/**/*.test.js"
+        run: NODE_OPTIONS="--import=$PWD/dist/test/clock-shift.js" node scripts/ci/clock-shift-run.mjs --test-timeout=600000 --file-timeout=1500000 dist/test
       - name: the tests, 400 days later
         if: ${{ !cancelled() }}
         timeout-minutes: 75
         shell: bash
         env:
           CI_REQUIRE_WEB: '1'
           TEST_CLOCK_SHIFT: '+400d'
-        run: NODE_OPTIONS="--import=$PWD/dist/test/clock-shift.js" node --import ./dist/test/isolate.js --test --test-timeout=600000 --test-force-exit "dist/test/**/*.test.js"
+        run: NODE_OPTIONS="--import=$PWD/dist/test/clock-shift.js" node scripts/ci/clock-shift-run.mjs --test-timeout=600000 --file-timeout=1500000 dist/test

changelog.d/848-clock-shift-all-tests.md

@@ -0,0 +1,7 @@
+### Guardrail changes: what each one does
+
+- **The weekly shifted-clock job runs every test, or fails and names the file (#848).** Its two test steps ran one `node --test --test-force-exit` over the suite. Force-exit ended a file's process once the tests it knew of were done, so tests registered after a top-level await never ran, and the step still reported 0 fail: 18 of `test/slot-dir-writes.test.ts`'s tests at +400 days.
+  - The steps now run `scripts/ci/clock-shift-run.mjs`, which gives each test file a `node --test` of its own, without force-exit. A file passes only when its run exits 0 with a summary.
+  - A file still running after 25 minutes is killed, along with what it started, and named, and the step fails. This covers a test that hangs past the 10-minute `--test-timeout`, and a handle left open after the file's tests. Node 24, which the job uses, doesn't end such a file at `--test-timeout`.
+  - `test/clock-shift.test.ts` checks both steps' exact command lines from the workflow, with no `|| true` and no `continue-on-error`. It runs each step on fixtures, on the Node version of the test shard: a test registered after an await runs; a file with a handle left open, a failing test and a hanging test each fail the step, named; an empty run fails.
+  - The job stays optional, required by nothing. Nothing changes for an install.

scripts/ci/clock-shift-run.mjs

@@ -0,0 +1,126 @@
+#!/usr/bin/env node
+// The weekly clock-shift job's test run (.github/workflows/clock-shift.yml, #848): every test file under the given
+// directories, each in a `node --test` of its own, as many at once as `node --test` runs. A file passes only when its
+// run exits 0 with a summary. A file whose process is still there after --file-timeout (a test that hangs past
+// --test-timeout, or a handle left open after its tests) is killed with everything it started, and fails, named.
+//
+// WHY not one `node --test` with --test-force-exit: force-exit ends a file's process once the tests it knows of are
+// done, so tests registered after a top-level await never ran, and the run still said 0 fail (#848). Without it, on
+// Node 24 a file with a handle left open is never ended (--test-timeout bounds tests, not the file's process), and
+// the run waits for the step's own time limit, with no summary (#774).
+//
+//   node scripts/ci/clock-shift-run.mjs --test-timeout=<ms> --file-timeout=<ms> <dir>...
+import { spawn } from 'node:child_process';
+import { readdirSync } from 'node:fs';
+import { availableParallelism } from 'node:os';
+import { relative, resolve } from 'node:path';
+import { fileURLToPath } from 'node:url';
+
+const root = fileURLToPath(new URL('../../', import.meta.url));
+// Relative to `root`, each file's run's working directory, as in npm test.
+const PRELOAD = ['--import', './dist/test/isolate.js'];
+
+function usage(why) {
+  process.stderr.write(`clock-shift-run: ${why}\nusage: node scripts/ci/clock-shift-run.mjs --test-timeout=<ms> --file-timeout=<ms> <dir>...\n`);
+  process.exit(2);
+}
+
+const opts = {};
+const dirs = [];
+for (const a of process.argv.slice(2)) {
+  const m = /^--(test-timeout|file-timeout)=(\d+)$/.exec(a);
+  if (m) opts[m[1]] = Number(m[2]);
+  else if (a.startsWith('-')) usage(`unknown option ${a}`);
+  else dirs.push(a);
+}
+if (!opts['test-timeout'] || !opts['file-timeout']) usage('--test-timeout and --file-timeout are both needed, in ms, above 0');
+if (dirs.length === 0) usage('no directory given');
+
+/** Every *.test.js under `dir`, sorted. */
+function testFiles(dir) {
+  return readdirSync(dir, { recursive: true, withFileTypes: true })
+    .filter((e) => e.isFile() && e.name.endsWith('.test.js'))
+    .map((e) => resolve(e.parentPath, e.name))
+    .sort();
+}
+
+const files = dirs.flatMap(testFiles);
+if (files.length === 0) usage(`no *.test.js file under ${dirs.join(', ')}`);
+
+const KEYS = ['tests', 'pass', 'fail', 'cancelled', 'skipped', 'todo'];
+const totals = Object.fromEntries(KEYS.map((k) => [k, 0]));
+const failed = [];
+const running = new Map();
+
+/** The run's own summary, from the last top-level `# <key> <n>` lines of its TAP output; null without one. */
+function summary(out) {
+  const s = {};
+  for (const k of KEYS) {
+    const all = [...out.matchAll(new RegExp(`^# ${k} (\\d+)$`, 'gm'))];
+    if (all.length === 0) return null;
+    s[k] = Number(all.at(-1)[1]);
+  }
+  return s;
+}
+
+function runFile(file) {
+  return new Promise((done) => {
+    const name = relative(process.cwd(), file);
+    const p = spawn(process.execPath, [...PRELOAD, '--test', `--test-timeout=${opts['test-timeout']}`, '--test-reporter=tap', file], {
+      cwd: root,
+      detached: true,
+      stdio: ['ignore', 'pipe', 'pipe'],
+    });
+    running.set(name, p);
+    let out = '';
+    p.stdout.on('data', (d) => (out += d));
+    p.stderr.on('data', (d) => (out += d));
+    let timedOut = false;
+    const timer = setTimeout(() => {
+      timedOut = true;
+      try {
+        process.kill(-p.pid, 'SIGKILL');
+      } catch {}
+    }, opts['file-timeout']);
+    p.on('close', (code, signal) => {
+      clearTimeout(timer);
+      running.delete(name);
+      const s = summary(out);
+      if (s) for (const k of KEYS) totals[k] += s[k];
+      let why = null;
+      if (timedOut) why = `still running after --file-timeout=${opts['file-timeout']} ms: killed`;
+      else if (code !== 0) why = signal ? `ended by ${signal}` : `exit ${code}`;
+      else if (!s) why = 'no summary';
+      if (why) failed.push(`${name}: ${why}`);
+      process.stdout.write(`# file: ${name}${why ? ` FAILED (${why})` : ''}\n${out}${out.endsWith('\n') ? '' : '\n'}`);
+      done();
+    });
+  });
+}
+
+function report() {
+  process.stdout.write(`\n# clock-shift run: ${files.length} files\n`);
+  for (const k of KEYS) process.stdout.write(`# ${k} ${totals[k]}\n`);
+  if (running.size > 0) process.stdout.write(`# still running (ended unfinished):\n${[...running.keys()].map((n) => `#   ${n}\n`).join('')}`);
+  if (failed.length > 0) process.stdout.write(`# failed files: ${failed.length}\n${failed.map((f) => `#   ${f}\n`).join('')}`);
+}
+
+for (const sig of ['SIGINT', 'SIGTERM']) {
+  process.on(sig, () => {
+    for (const p of running.values()) {
+      try {
+        process.kill(-p.pid, 'SIGKILL');
+      } catch {}
+    }
+    report();
+    process.exit(1);
+  });
+}
+
+const queue = [...files];
+const workers = Array.from({ length: Math.max(1, Math.min(availableParallelism() - 1, files.length)) }, async () => {
+  while (queue.length > 0) await runFile(queue.shift());
+});
+await Promise.all(workers);
+report();
+process.exit(failed.length > 0 ? 1 : 0);

test/clock-shift.test.ts

@@ -4,10 +4,11 @@
 import { test } from 'node:test';
 import assert from 'node:assert/strict';
 import { spawn } from 'node:child_process';
-import { mkdtempSync, writeFileSync } from 'node:fs';
+import { existsSync, mkdtempSync, readFileSync, writeFileSync } from 'node:fs';
 import { tmpdir } from 'node:os';
 import { join } from 'node:path';
 import { pathToFileURL } from 'node:url';
+import { parse } from 'yaml';
 import { parseClockShift } from './clock-shift.js';
 import { repoRoot } from './helpers.js';
 import { TEST_PRELOAD } from './isolate.js';
@@ -123,3 +124,105 @@ test('shifted: a test that mocks Date.now sees its mock, and a mock calling the
   assert.equal(r.code, 0, r.out);
   assert.match(r.out, /# pass 3/);
 });
+
+type Step = { name?: string; run?: string; shell?: string; env?: Record<string, string>; 'continue-on-error'?: unknown };
+type Job = { steps: Step[]; 'continue-on-error'?: unknown };
+/** The whole command line of a test step: nothing before or after it can change what it runs or what it exits with. */
+const JOB_RUN = /^NODE_OPTIONS="--import=\$PWD\/dist\/test\/clock-shift\.js" node scripts\/ci\/clock-shift-run\.mjs --test-timeout=(\d+) --file-timeout=(\d+) dist\/test$/;
+
+/** The workflow's test steps, one per shift, each with its command line and environment. */
+function jobTestSteps(): Step[] {
+  const wf = parse(readFileSync(join(repoRoot, '.github', 'workflows', 'clock-shift.yml'), 'utf8')) as { jobs: Record<string, Job> };
+  for (const [id, j] of Object.entries(wf.jobs)) assert.equal(j['continue-on-error'], undefined, `job ${id}: continue-on-error`);
+  const all = Object.values(wf.jobs).flatMap((j) => j.steps);
+  for (const s of all) assert.equal(s['continue-on-error'], undefined, `${s.name ?? s.run}: continue-on-error`);
+  const steps = all.filter((s) => s.env?.TEST_CLOCK_SHIFT !== undefined);
+  assert.deepEqual(steps.map((s) => s.env!.TEST_CLOCK_SHIFT), ['+45d', '+400d']);
+  for (const s of steps) {
+    assert.equal(s.shell, 'bash', `${s.name}: shell`);
+    const m = JOB_RUN.exec(s.run ?? '');
+    assert.ok(m, `${s.name}: the run line is exactly the job's command, with no || true or other wrapper: ${s.run}`);
+    assert.ok(Number(m[2]) > Number(m[1]), `${s.name}: a file gets longer than one test`);
+  }
+  return steps;
+}
+
+/** A test step's command line as the job runs it, on the test files under `dir` instead of the suite. */
+async function runStep(s: Step, dir: string, timeouts: { test?: number; file?: number } = {}): Promise<{ code: number | null; out: string; ms: number }> {
+  let run = s.run!.replace(/ dist\/test$/, ` '${dir}'`);
+  if (timeouts.test) run = run.replace(/--test-timeout=\d+/, `--test-timeout=${timeouts.test}`);
+  if (timeouts.file) run = run.replace(/--file-timeout=\d+/, `--file-timeout=${timeouts.file}`);
+  const start = performance.now();
+  const p = spawn('bash', ['-c', run], { cwd: repoRoot, env: { ...plain, ...s.env }, stdio: ['ignore', 'pipe', 'pipe'], timeout: 120_000 });
+  let out = '';
+  p.stdout.on('data', (d: Buffer) => (out += d.toString()));
+  p.stderr.on('data', (d: Buffer) => (out += d.toString()));
+  const code = await new Promise<number | null>((ok) => p.on('close', (c) => ok(c)));
+  return { code, out, ms: performance.now() - start };
+}
+
+/** A fixture directory of ES module test files. */
+function fixture(files: Record<string, string>): string {
+  const dir = mkdtempSync(join(tmpdir(), 'clock-job-'));
+  writeFileSync(join(dir, 'package.json'), '{"type":"module"}\n');
+  for (const [name, text] of Object.entries(files)) writeFileSync(join(dir, name), text);
+  return dir;
+}
+
+test('the job runs every test of a file, one registered after an await too, at both shifts (#848)', async () => {
+  // test/slot-dir-writes.test.ts registers tests after a top-level await. Under --test-force-exit a file's process
+  // ended once the tests it knew of were done, so the later ones never ran, and the step still reported 0 fail.
+  for (const s of jobTestSteps()) {
+    const marker = join(mkdtempSync(join(tmpdir(), 'clock-job-')), 'late-ran');
+    const dir = fixture({
+      'late.test.js': [
+        "import { test } from 'node:test';",
+        "import { writeFileSync } from 'node:fs';",
+        "test('early', () => {});",
+        'await new Promise((ok) => setTimeout(ok, 200));',
+        `test('late', () => writeFileSync(${JSON.stringify(marker)}, 'x'));`,
+        '',
+      ].join('\n'),
+    });
+    const r = await runStep(s, dir);
+    assert.equal(r.code, 0, `${s.name}: ${r.out}`);
+    assert.ok(existsSync(marker), `${s.name}: the test registered after the await never ran\n${r.out}`);
+    assert.match(r.out, /^# clock-shift run: 1 files\n# tests 2\n# pass 2\n# fail 0\n/m, `${s.name}: ${r.out}`);
+  }
+});
+
+test('the job fails a file that keeps a handle open after its tests, named, and still reports the others, at both shifts (#774)', async () => {
+  for (const s of jobTestSteps()) {
+    const dir = fixture({
+      'open-handle.test.js': "import { test } from 'node:test';\nsetInterval(() => {}, 1000);\ntest('done', () => {});\n",
+      'fine.test.js': "import { test } from 'node:test';\ntest('fine', () => {});\n",
+    });
+    const r = await runStep(s, dir, { file: 5000 });
+    assert.equal(r.code, 1, `${s.name}: ${r.out}`);
+    assert.match(r.out, /^# failed files: 1\n# {3}\S*open-handle\.test\.js: still running after --file-timeout=5000 ms: killed$/m, `${s.name}: ${r.out}`);
+    assert.match(r.out, /^# file: \S*fine\.test\.js\n/m, `${s.name}: ${r.out}`);
+    assert.ok(r.ms < 60_000, `${s.name}: took ${r.ms} ms`);
+  }
+});
+
+test('the job fails on a failing test and on a test that hangs, each named, at both shifts', async () => {
+  for (const s of jobTestSteps()) {
+    const dir = fixture({
+      'fails.test.js': "import { test } from 'node:test';\nimport assert from 'node:assert/strict';\ntest('fails', () => assert.equal(1, 2));\n",
+      'hangs.test.js': "import { test } from 'node:test';\ntest('hangs', () => new Promise(() => setInterval(() => {}, 1000)));\n",
+      'fine.test.js': "import { test } from 'node:test';\ntest('fine', () => {});\n",
+    });
+    const r = await runStep(s, dir, { test: 2000, file: 8000 });
+    assert.equal(r.code, 1, `${s.name}: ${r.out}`);
+    assert.match(r.out, /^# failed files: 2\n/m, `${s.name}: ${r.out}`);
+    assert.match(r.out, /^# {3}\S*fails\.test\.js: exit 1$/m, `${s.name}: ${r.out}`);
+    assert.match(r.out, /^# {3}\S*hangs\.test\.js: /m, `${s.name}: ${r.out}`);
+  }
+});
+
+test('the job refuses to pass with no test file to run', async () => {
+  const [s] = jobTestSteps();
+  const r = await runStep(s!, fixture({}));
+  assert.equal(r.code, 2, r.out);
+  assert.match(r.out, /no \*\.test\.js file under/);
+});