diff --git a/.github/workflows/viewerjs-check.yml b/.github/workflows/viewerjs-check.yml index f31d0e90..4a87231d 100644 --- a/.github/workflows/viewerjs-check.yml +++ b/.github/workflows/viewerjs-check.yml @@ -28,12 +28,14 @@ concurrency: # 7m08s/4m34s), webkit 8m16s/5m03s (tests 7m26s/3m58s); a cache miss adds up to 5m to npm ci, which # the 20-minute limits absorb. # Hangs (#425): a job killed at its limit keeps no log and skips its upload steps, so each browser -# test step has its own timeout-minutes (18) below the job's 20, and Playwright's globalTimeout -# (PM_TEST_GLOBAL_TIMEOUT_MINUTES) stops the run before the step and lists the interrupted tests. +# test step has its own timeout-minutes (18) below the job's 20. At the step limit, SIGTERM makes +# tools/vendor/running-tests-reporter.mjs print the tests still running and hand over to Playwright's +# interrupt, which writes the blob report; the always() uploads then run. # Measured on main (runs 40725289094, 40719375442, 40700439399): setup before the test step <= 52s, -# uploads <= 35s; test steps up to 14m42s (webkit shard 1/2, Playwright ~14.6m) and 13m05s for -# coverage (workflows 11.8m after ~1m of node units and the viewer suite, whose own CI limit is 3m). -# So: page workflows globalTimeout 17m, coverage workflows 15m, each step 18m. +# uploads <= 35s; test steps up to 14m42s (webkit shard 1/2) and 13m05s for coverage (shard 1/3: +# 12m53s, node units and the viewer suite before 11.8m of workflows), so coverage is the tight one +# in its 18 minutes. This holds only when the npm cache hits: a cold cache adds up to 5m to npm ci, +# and then the job limit can still end the job before the step limit does. jobs: frontend-coverage: name: frontend coverage (shard ${{ matrix.shard }}/3) @@ -87,8 +89,6 @@ jobs: run: npm run --prefix tools/vendor test - name: Page workflows with coverage, shard ${{ matrix.shard }}/3 timeout-minutes: 18 - env: - PM_TEST_GLOBAL_TIMEOUT_MINUTES: 15 run: npm run --prefix tools/vendor test:coverage:shard -- ${{ matrix.shard }}/3 - name: Upload raw coverage uses: actions/upload-artifact@v7 @@ -223,8 +223,6 @@ jobs: - run: npm ci --prefix tools/vendor --ignore-scripts - name: Page workflows in ${{ matrix.browser }}, shard ${{ matrix.shard }}/2 timeout-minutes: 18 - env: - PM_TEST_GLOBAL_TIMEOUT_MINUTES: 17 run: npm run --prefix tools/vendor test:workflows -- --project ${{ matrix.browser }} --shard ${{ matrix.shard }}/2 # Traces and the blob report (test-results/blob/) of a failed, timed-out or cancelled step. - name: Upload browser traces diff --git a/TESTING.md b/TESTING.md index 947d51f6..801a9377 100644 --- a/TESTING.md +++ b/TESTING.md @@ -264,16 +264,20 @@ with new measurements written next to it. Browser jobs (#425): GitHub keeps no log of a job killed at its limit and skips its upload steps, so the test step in each browser job in `viewerjs-check.yml` -has its own `timeout-minutes` (18, below the job's 20) and Playwright stops -first. Under `CI`, `globalTimeout` comes from `PM_TEST_GLOBAL_TIMEOUT_MINUTES` -(page workflows 17, coverage workflows 15; the viewer suite has a fixed 3); -the comment above `jobs:` holds the measurements. Locally there is no limit -unless you set that variable (fractions work: `0.5` is 30 s). Each test keeps -the 30 s default. When the run is cut off, the log ends with `Still running -when the run ended (timedout): N` and one line per test that never finished -(`tools/vendor/running-tests-reporter.mjs`; `list` cannot name them). The -blob report in `tools/vendor/test-results/blob/` and the traces upload with -`if: always()`; `npx playwright merge-reports` opens the blob. +has its own `timeout-minutes` (18, below the job's 20). At the step limit +GitHub sends SIGTERM, which would end Playwright without any report; under `CI` +`tools/vendor/running-tests-reporter.mjs` catches the first one, prints +`Still running when the run ended (SIGTERM): N` and one line per unfinished +test (path relative to the suite's `rootDir`), then sends Playwright its own +SIGINT, so the workers stop, the run ends interrupted and the blob report is +written to `tools/vendor/test-results/blob/`. That directory and the traces +upload with `if: always()`; `npx playwright merge-reports` opens the blob. +Each test keeps the 30 s default and there is no `globalTimeout`. Two limits +of this: it assumes the npm cache hits (a cold cache adds up to 5 minutes to +`npm ci`, and the job limit can then still win), and coverage shard 1 (12m53s +measured) is the tight one in its 18-minute step. Local runs keep the `list` +reporter only; reproduce with `CI=1 timeout -s TERM 40 npm run --prefix +tools/vendor test:workflows -- --project=firefox`. ### After a push diff --git a/tests/vendor/browser-server-fixture.test.mjs b/tests/vendor/browser-server-fixture.test.mjs index 7fcf6790..72481464 100644 --- a/tests/vendor/browser-server-fixture.test.mjs +++ b/tests/vendor/browser-server-fixture.test.mjs @@ -2,12 +2,12 @@ import test from 'node:test'; import assert from 'node:assert/strict'; import { createServer } from 'node:net'; import { spawn } from 'node:child_process'; -import { once } from 'node:events'; +import { EventEmitter, once } from 'node:events'; import { readFileSync } from 'node:fs'; import { fileURLToPath, pathToFileURL } from 'node:url'; import { setTimeout as delay } from 'node:timers/promises'; import { startBrowserServer, createServerSupervisor, attachServerStderr, forwardPrefixedLines, SLOW_RESET_PREFIX } from '../../tools/vendor/start-browser-server.mjs'; -import { globalTimeoutMs, reporters, workflowWorkers } from '../../tools/vendor/test-workers.mjs'; +import { reporters, workflowWorkers } from '../../tools/vendor/test-workers.mjs'; import RunningTestsReporter from '../../tools/vendor/running-tests-reporter.mjs'; const fakeServer = fileURLToPath(new URL('./fake-browser-server.mjs', import.meta.url)); @@ -257,31 +257,28 @@ test('worker count follows PM_TEST_WORKERS, then one in CI, then a quarter of th assert.throws(() => workflowWorkers({ env: { PM_TEST_WORKERS: '0' }, cpus: 8 }), /PM_TEST_WORKERS must be a positive integer/); }); -test('the Playwright run limit applies under CI, follows its override and is off locally', () => { - const variable = 'PM_TEST_GLOBAL_TIMEOUT_MINUTES'; - assert.equal(globalTimeoutMs({ env: { CI: '1' }, ciMinutes: 17, variable }), 17 * 60_000); - assert.equal(globalTimeoutMs({ env: {}, ciMinutes: 17, variable }), 0, 'local runs keep no limit'); - assert.equal(globalTimeoutMs({ env: { CI: '1', [variable]: '15' }, ciMinutes: 17, variable }), 15 * 60_000); - assert.equal(globalTimeoutMs({ env: { [variable]: '0.5' }, ciMinutes: 17, variable }), 30_000); - assert.equal(globalTimeoutMs({ env: { CI: '1', [variable]: '1' }, ciMinutes: 3 }), 3 * 60_000, - 'a config without a variable ignores the override'); - for (const bad of ['0', '-1', 'soon', '']) { - assert.throws(() => globalTimeoutMs({ env: { [variable]: bad }, ciMinutes: 17, variable }), /positive number/); - } -}); - test('CI adds the running-tests reporter and a blob report under test-results/blob/, which the trace upload covers; local runs keep list', () => { assert.equal(reporters({ env: {}, name: 'workflows' }), 'list'); assert.deepEqual(reporters({ env: { CI: '1' }, name: 'workflows' }), [['list'], ['./running-tests-reporter.mjs'], ['blob', { outputDir: './test-results/blob/workflows' }]]); }); -test('the running-tests reporter names only the tests that never ended, with how long they ran', () => { +function fakeHost() { + const host = new EventEmitter(); + Object.assign(host, { pid: 4242, signals: [], cwd: () => '/repo/tools/vendor' }); + host.kill = (pid, signal) => host.signals.push([pid, signal]); + return host; +} + +const spec = (id, title, line) => ({ id, title, location: { file: '/repo/tests/browser/a.spec.mjs', line }, + parent: { project: () => ({ name: 'firefox' }) } }); + +test('the running-tests reporter names only the tests that never ended, relative to rootDir', () => { let clock = 1_000; const output = []; - const reporter = new RunningTestsReporter({ now: () => clock, write: text => output.push(text), cwd: '/repo' }); - const spec = (id, title, line) => ({ id, title, location: { file: '/repo/tests/browser/a.spec.mjs', line }, - parent: { project: () => ({ name: 'firefox' }) } }); + const host = fakeHost(); + const reporter = new RunningTestsReporter({ now: () => clock, write: text => output.push(text), host }); + reporter.onBegin({ rootDir: '/repo/tests/browser' }); const done = spec('1', 'finishes', 10); const stuck = spec('2', 'hangs on a fetch', 20); reporter.onTestBegin(done, { retry: 0 }); @@ -289,11 +286,24 @@ test('the running-tests reporter names only the tests that never ended, with how clock += 500; reporter.onTestEnd(done, { retry: 0 }); clock += 41_500; - reporter.onEnd({ status: 'timedout' }); - assert.equal(output.join(''), '\nStill running when the run ended (timedout): 1\n' - + ' [firefox] › tests/browser/a.spec.mjs:20 › hangs on a fetch (running 42.0s)\n'); + reporter.onEnd({ status: 'interrupted' }); + assert.equal(output.join(''), '\nStill running when the run ended (interrupted): 1\n' + + ' [firefox] › a.spec.mjs:20 › hangs on a fetch (running 42.0s)\n'); + assert.equal(host.listenerCount('SIGTERM'), 0, 'the run is over: SIGTERM gets its default again'); output.length = 0; reporter.onTestEnd(stuck, { retry: 0 }); reporter.onEnd({ status: 'passed' }); assert.deepEqual(output, [], 'a run where every test ended prints nothing'); }); + +test('on the first SIGTERM the reporter prints the running tests and hands over to Playwright\'s SIGINT', () => { + const output = []; + const host = fakeHost(); + const reporter = new RunningTestsReporter({ now: () => 0, write: text => output.push(text), host }); + reporter.onBegin({ rootDir: '/repo/tests/browser' }); + reporter.onTestBegin(spec('2', 'hangs on a fetch', 20), { retry: 0 }); + host.emit('SIGTERM'); + assert.match(output.join(''), /Still running when the run ended \(SIGTERM\): 1\n {2}\[firefox\] › a\.spec\.mjs:20 › hangs on a fetch/); + assert.deepEqual(host.signals, [[4242, 'SIGINT']], 'Playwright\'s own interrupt ends the run and writes the blob'); + assert.equal(host.listenerCount('SIGTERM'), 0, 'a second SIGTERM kills the process as usual'); +}); diff --git a/tests/vendor/ci-workflow.test.mjs b/tests/vendor/ci-workflow.test.mjs index 8dccc0e3..0e3d0c62 100644 --- a/tests/vendor/ci-workflow.test.mjs +++ b/tests/vendor/ci-workflow.test.mjs @@ -248,7 +248,7 @@ test('browser job timeouts keep a real margin over measured runs', () => { }); // A hang (#425) must end inside the test step, before the job limit, so the log and the always() -// uploads survive: Playwright's globalTimeout < the step's timeout-minutes < the job's. +// uploads survive: the step's timeout-minutes < the job's. const BROWSER_TEST_STEP = /npm run --prefix tools\/vendor test:(workflows|coverage)/; test('each browser test step stops itself before its job limit and its traces upload anyway', () => { @@ -259,11 +259,8 @@ test('each browser test step stops itself before its job limit and its traces up const testAt = jobSteps.findIndex(step => BROWSER_TEST_STEP.test(step)); const testStep = jobSteps[testAt]; const stepMinutes = Number(/^ {8}timeout-minutes: (\d+)$/m.exec(testStep)?.[1]); - const globalMinutes = Number(/^ {10}PM_TEST_GLOBAL_TIMEOUT_MINUTES: (\d+)$/m.exec(testStep)?.[1]); assert.ok(stepMinutes > 0, `${id}: the test step sets its own timeout-minutes`); assert.ok(jobMinutes - stepMinutes >= 2, `${id}: the step limit leaves time for setup and the uploads`); - assert.ok(globalMinutes > 0 && stepMinutes - globalMinutes >= 1, - `${id}: Playwright's globalTimeout ends the run at least a minute before the step limit`); const upload = jobSteps.slice(testAt + 1).find(step => /^ {10}path: tools\/vendor\/test-results\/$/m.test(step)); assert.ok(upload, `${id} uploads tools/vendor/test-results/ (traces and blob report) after the tests`); assert.match(upload, /^ {8}if: always\(\)$/m, `${id} uploads them when the step failed or timed out`); diff --git a/tools/vendor/playwright.config.mjs b/tools/vendor/playwright.config.mjs index f1de39c6..81bc799d 100644 --- a/tools/vendor/playwright.config.mjs +++ b/tools/vendor/playwright.config.mjs @@ -1,8 +1,5 @@ import { defineConfig } from '@playwright/test'; -import { globalTimeoutMs, reporters } from './test-workers.mjs'; - -// The viewer suite takes under a minute in CI and runs before the coverage workflows in the same step. -const CI_GLOBAL_TIMEOUT_MINUTES = 3; +import { reporters } from './test-workers.mjs'; export default defineConfig({ testDir: './tests', @@ -12,7 +9,6 @@ export default defineConfig({ workers: 2, forbidOnly: Boolean(process.env.CI), retries: process.env.CI ? 1 : 0, - globalTimeout: globalTimeoutMs({ ciMinutes: CI_GLOBAL_TIMEOUT_MINUTES }), reporter: reporters({ name: 'viewer' }), use: { browserName: 'chromium', headless: true, trace: 'retain-on-failure' }, projects: [ diff --git a/tools/vendor/playwright.workflows.config.mjs b/tools/vendor/playwright.workflows.config.mjs index 21a973c4..d076ba92 100644 --- a/tools/vendor/playwright.workflows.config.mjs +++ b/tools/vendor/playwright.workflows.config.mjs @@ -1,9 +1,5 @@ import { defineConfig, devices } from '@playwright/test'; -import { globalTimeoutMs, reporters, workflowWorkers } from './test-workers.mjs'; - -// CI default; each browser job in viewerjs-check.yml sets PM_TEST_GLOBAL_TIMEOUT_MINUTES below its -// test step's timeout-minutes (tests/vendor/ci-workflow.test.mjs checks the order). -const CI_GLOBAL_TIMEOUT_MINUTES = 17; +import { reporters, workflowWorkers } from './test-workers.mjs'; // No global webServer: tests/browser/fixtures.mjs starts one server per worker // on an OS-chosen port. Files run in parallel; tests inside a file keep their order. @@ -15,8 +11,6 @@ export default defineConfig({ fullyParallel: false, forbidOnly: Boolean(process.env.CI), retries: 0, - // Each test keeps Playwright's 30 s default; the whole run is bounded under CI (#425). - globalTimeout: globalTimeoutMs({ ciMinutes: CI_GLOBAL_TIMEOUT_MINUTES, variable: 'PM_TEST_GLOBAL_TIMEOUT_MINUTES' }), reporter: reporters({ name: 'workflows' }), use: { trace: 'retain-on-failure', screenshot: 'only-on-failure' }, projects: [ diff --git a/tools/vendor/running-tests-reporter.mjs b/tools/vendor/running-tests-reporter.mjs index c54b1743..4a918955 100644 --- a/tools/vendor/running-tests-reporter.mjs +++ b/tools/vendor/running-tests-reporter.mjs @@ -1,21 +1,35 @@ +import { writeSync } from 'node:fs'; import { relative } from 'node:path'; -// Names the tests still running when a run ends (#425). When globalTimeout fires, Playwright's own -// teardown deadline has already passed, so a test stuck in a worker never gets onTestEnd and no -// built-in reporter lists it. This one remembers every started test and prints those that never -// ended, with how long each had been running, at the end of the log. +// Names the tests still running when a run is cut off (#425). A browser test step that reaches its +// timeout-minutes gets SIGTERM, which ends Playwright at once: no reporter's onEnd runs, so neither +// `list` nor the blob report says what was running. On the first SIGTERM this reporter prints every +// started test that has not ended, then turns the signal into SIGINT, Playwright's own interrupt, +// which stops the workers, ends the run as interrupted (non-zero exit) and writes the blob report. +// A second SIGTERM gets the default behaviour: the process dies. export default class RunningTestsReporter { - constructor({ now = () => Date.now(), write = text => process.stdout.write(text), cwd = process.cwd() } = {}) { + constructor({ now = () => Date.now(), write = text => writeSync(1, text), host = process } = {}) { this.now = now; this.write = write; - this.cwd = cwd; + this.host = host; + this.rootDir = host.cwd(); this.running = new Map(); + this.onSigterm = () => { + this.host.removeListener('SIGTERM', this.onSigterm); + this.report('SIGTERM'); + this.host.kill(this.host.pid, 'SIGINT'); + }; } printsToStdio() { return false; } + onBegin(config) { + this.rootDir = config.rootDir; + this.host.on('SIGTERM', this.onSigterm); + } + onTestBegin(test, result) { this.running.set(`${test.id}#${result.retry}`, { test, startedAt: this.now() }); } @@ -26,14 +40,19 @@ export default class RunningTestsReporter { describe({ test, startedAt }) { const project = test.parent?.project()?.name; - const where = `${relative(this.cwd, test.location.file)}:${test.location.line}`; + const where = `${relative(this.rootDir, test.location.file)}:${test.location.line}`; const seconds = ((this.now() - startedAt) / 1000).toFixed(1); return `${project ? `[${project}] › ` : ''}${where} › ${test.title} (running ${seconds}s)`; } - onEnd(result) { + report(reason) { if (!this.running.size) return; const lines = [...this.running.values()].map(entry => ` ${this.describe(entry)}`); - this.write(`\nStill running when the run ended (${result.status}): ${this.running.size}\n${lines.join('\n')}\n`); + this.write(`\nStill running when the run ended (${reason}): ${this.running.size}\n${lines.join('\n')}\n`); + } + + onEnd(result) { + this.host.removeListener('SIGTERM', this.onSigterm); + this.report(result.status); } } diff --git a/tools/vendor/test-workers.mjs b/tools/vendor/test-workers.mjs index 027edf59..44d64319 100644 --- a/tools/vendor/test-workers.mjs +++ b/tools/vendor/test-workers.mjs @@ -17,24 +17,7 @@ export function workflowWorkers({ env = process.env, cpus = availableParallelism return Math.max(1, Math.min(MAX_LOCAL_WORKERS, Math.floor(cpus / CPUS_PER_WORKER))); } -const MINUTE_MS = 60_000; - -// Playwright's globalTimeout (#425): under CI the run stops itself before the step and job limits in -// viewerjs-check.yml, so it names the tests still running instead of being killed with no log. -// `variable` (minutes, may be fractional) overrides it anywhere; locally there is no limit. -export function globalTimeoutMs({ env = process.env, ciMinutes, variable } = {}) { - const override = variable === undefined ? undefined : env[variable]; - if (override !== undefined) { - const minutes = Number(override); - if (!Number.isFinite(minutes) || minutes <= 0) { - throw new Error(`${variable} must be a positive number of minutes, got "${override}"`); - } - return Math.round(minutes * MINUTE_MS); - } - return env.CI ? ciMinutes * MINUTE_MS : 0; -} - -// Under CI, running-tests-reporter.mjs names the tests a globalTimeout or a signal cut off (`list` +// Under CI, running-tests-reporter.mjs names the tests a step timeout's signal cut off (`list` // cannot: they never end), and a blob report beside the traces is uploaded with them. export function reporters({ env = process.env, name } = {}) { if (!env.CI) return 'list';