diff --git a/.github/workflows/clock-shift.yml b/.github/workflows/clock-shift.yml index 3166f7ee..8c8531a0 100644 --- a/.github/workflows/clock-shift.yml +++ b/.github/workflows/clock-shift.yml @@ -43,16 +43,18 @@ 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 @@ -60,4 +62,4 @@ jobs: 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 diff --git a/changelog.d/848-clock-shift-all-tests.md b/changelog.d/848-clock-shift-all-tests.md new file mode 100644 index 00000000..0b18c962 --- /dev/null +++ b/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. diff --git a/scripts/ci/clock-shift-run.mjs b/scripts/ci/clock-shift-run.mjs new file mode 100644 index 00000000..63b57be7 --- /dev/null +++ b/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= --file-timeout= ... +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= --file-timeout= ...\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 `# ` 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); diff --git a/test/clock-shift.test.ts b/test/clock-shift.test.ts index cfddbe16..5d68d4a6 100644 --- a/test/clock-shift.test.ts +++ b/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; '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 }; + 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((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 { + 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/); +});