diff --git a/TESTING.md b/TESTING.md index 4d585eca..ea57c61d 100644 --- a/TESTING.md +++ b/TESTING.md @@ -53,6 +53,14 @@ stdin open and the server (`--exit-on-stdin-eof`) shuts down cleanly, removing i temp root, when that pipe closes, so a worker killed without teardown leaves no server behind. A test that fails gets the stderr its server wrote during the test attached to the report as `server-stderr` (an aiohttp traceback behind a 500). +Each worker also records its browser's own log (#513, `tools/vendor/browser-logs.mjs`): +Playwright's `pw:browser` channel, kept as a 300-line tail without printing it +unless `DEBUG` asks for it. A browser that exits abnormally writes one +`pm-browser-exit| browser pid= exited: exitCode=, signal=` line to the job +log, and a test that fails on a closed or crashed target ("Target page, context or +browser has been closed") gets the tail attached as `browser-stderr.txt`, which the +uploaded test-results carry. `tests/browser/browser-logs.spec.mjs` kills a browser of +its own on purpose, so each browser job logs that line once for it. A `/__test__/.../reset` still running after 2 s writes a report to the job log, passing test or not: every thread's stack taken while it waits, the default executor's threads and queue, the open connections and WAL size, then the total diff --git a/tests/browser/browser-logs.spec.mjs b/tests/browser/browser-logs.spec.mjs new file mode 100644 index 00000000..3c8bc3a3 --- /dev/null +++ b/tests/browser/browser-logs.spec.mjs @@ -0,0 +1,26 @@ +// #513: a worker records its browser's own log, so a browser that dies between two tests leaves its exit and stderr +// behind instead of only "Target page, context or browser has been closed" on the next test. +import { test, expect } from './fixtures.mjs'; +import { isTargetGone } from '../../tools/vendor/browser-logs.mjs'; + +test('the worker records the launch of the browser its tests use', async ({ browser, browserLogs }) => { + expect(browser.isConnected()).toBe(true); + expect(browserLogs.launches().length).toBeGreaterThan(0); +}); + +test('a killed browser leaves its signal and stderr in the worker log', async ({ playwright, browserName, browserLogs }) => { + const before = browserLogs.launches(); + const victim = await playwright[browserName].launch(); + const pid = browserLogs.launches().find(item => !before.includes(item)); + expect(pid, 'the new browser\'s launch was recorded').toBeGreaterThan(0); + const disconnected = new Promise(resolve => victim.once('disconnected', resolve)); + // Playwright starts a browser in a process group of its own; WebKit's launched pid is a wrapper script. + process.kill(-pid, 'SIGKILL'); + await disconnected; + const error = await victim.newContext().then(() => null, item => item); + expect(error, 'a dead browser refuses a new context').not.toBeNull(); + expect(isTargetGone(error.message)).toBe(true); + // The pipe can close before the launcher has logged the exit. + await expect.poll(() => browserLogs.exits()).toContainEqual({ pid, exitCode: null, signal: 'SIGKILL' }); + expect(browserLogs.tail()).toContain(`[pid=${pid}] `); +}); diff --git a/tests/browser/fixtures.mjs b/tests/browser/fixtures.mjs index 511e5124..357f8c19 100644 --- a/tests/browser/fixtures.mjs +++ b/tests/browser/fixtures.mjs @@ -4,13 +4,29 @@ // points at that worker's server. A server that dies fails the running test // with its stderr tail, and the next test in the worker gets a fresh server. // A test that fails gets the stderr its server wrote during it attached as -// `server-stderr`. +// `server-stderr`. The worker also records its browser's own log (#513): a +// browser that exits abnormally prints one `pm-browser-exit|` line, and a test +// that fails on a closed or crashed target gets that log attached as +// `browser-stderr`. import { test as base, expect } from '../../tools/vendor/node_modules/@playwright/test/index.mjs'; import { attachServerStderr, createServerSupervisor, startBrowserServer } from '../../tools/vendor/start-browser-server.mjs'; +import { attachBrowserLogs, createBrowserLogRecorder } from '../../tools/vendor/browser-logs.mjs'; const SERVER_FIXTURE_TIMEOUT_MS = 90_000; export const test = base.extend({ + browserLogs: [async ({}, use) => { + const recorder = createBrowserLogRecorder(); + try { + await use(recorder); + } finally { + recorder.uninstall(); + } + }, { scope: 'worker', auto: true }], + browserLogsOnFailure: [async ({ browserLogs }, use, testInfo) => { + await use(); + await attachBrowserLogs(testInfo, browserLogs); + }, { auto: true }], testServer: [async ({}, use) => { const supervisor = createServerSupervisor({ start: () => startBrowserServer() }); try { diff --git a/tests/vendor/browser-logs.test.mjs b/tests/vendor/browser-logs.test.mjs new file mode 100644 index 00000000..206f7c44 --- /dev/null +++ b/tests/vendor/browser-logs.test.mjs @@ -0,0 +1,127 @@ +import test from 'node:test'; +import assert from 'node:assert/strict'; +import { mkdtempSync, readFileSync, rmSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { attachBrowserLogs, BROWSER_EXIT_PREFIX, createBrowserLogRecorder, isAbnormalExit, isTargetGone, parseExitLine, + playwrightDebug } from '../../tools/vendor/browser-logs.mjs'; + +const debug = playwrightDebug(); + +/** Runs `body` with DEBUG set to `namespaces` and restores the caller's setting afterwards. */ +function withDebug(namespaces, body) { + const saved = debug.disable(); + const savedLog = debug.log; + if (namespaces) debug.enable(namespaces); + try { + return body(); + } finally { + debug.log = savedLog; + debug.disable(); + if (saved) debug.enable(saved); + } +} + +const outputDir = mkdtempSync(join(tmpdir(), 'pm-browser-logs-')); +test.after(() => rmSync(outputDir, { recursive: true, force: true })); + +function testInfo({ status = 'failed', errors = [] } = {}) { + const attachments = []; + const dir = mkdtempSync(join(outputDir, 'test-')); + return { status, expectedStatus: 'passed', errors, attachments, outputPath: name => join(dir, name), + attach: async (name, options) => { attachments.push({ name, ...options }); } }; +} + +test('parses the exit line Playwright logs for a browser process', () => { + assert.deepEqual(parseExitLine('[pid=7124] +21ms'), + { pid: 7124, exitCode: null, signal: 'SIGKILL' }); + assert.deepEqual(parseExitLine('[pid=9] '), { pid: 9, exitCode: 0, signal: null }); + assert.deepEqual(parseExitLine('[pid=9] '), { pid: 9, exitCode: 11, signal: null }); + assert.equal(parseExitLine('[pid=9][err] JavaScript warning'), null); + assert.equal(isAbnormalExit({ pid: 9, exitCode: 0, signal: null }), false); + assert.equal(isAbnormalExit({ pid: 9, exitCode: null, signal: 'SIGKILL' }), true); + assert.equal(isAbnormalExit({ pid: 9, exitCode: 139, signal: null }), true); +}); + +test('recognises the errors of a page, context or browser that went away', () => { + for (const message of ['Error: browser.newContext: Target page, context or browser has been closed', + 'Protocol error (Page.navigate): Target closed', 'page.goto: Page crashed', 'Target crashed']) { + assert.equal(isTargetGone(message), true, message); + } + for (const message of ['expect(locator).toBeVisible() failed', undefined, 'Test timeout of 30000ms exceeded.']) { + assert.equal(isTargetGone(message), false, String(message)); + } +}); + +test('records the browser channel into a bounded tail without printing it', () => withDebug('', () => { + const printed = []; + debug.log = (...args) => printed.push(args.join(' ')); + const written = []; + const recorder = createBrowserLogRecorder({ debug, limit: 3, write: text => written.push(text) }); + const browser = debug('pw:browser'); + browser(' pid=5'); + for (const n of [1, 2, 3, 4]) browser(`[pid=5][err] line ${n}`); + assert.deepEqual(printed, [], 'the browser channel stays quiet when DEBUG did not ask for it'); + assert.match(recorder.tail(), /line 2[\s\S]*line 3[\s\S]*line 4/); + assert.doesNotMatch(recorder.tail(), /line 1/); + assert.deepEqual(written, []); + assert.deepEqual(recorder.launches(), [5], 'launches outlive the bounded tail'); + browser('[pid=5] '); + assert.deepEqual(recorder.exits(), [{ pid: 5, exitCode: null, signal: 'SIGKILL' }]); + assert.deepEqual(written, [`${BROWSER_EXIT_PREFIX}browser pid=5 exited: exitCode=null, signal=SIGKILL\n`]); + browser('[pid=6] '); + assert.equal(written.length, 1, 'a clean exit prints nothing'); + recorder.uninstall(); + assert.equal(debug.enabled('pw:browser'), false, 'uninstall restores the caller\'s DEBUG'); +})); + +test('keeps printing the channels the user enabled, the browser one included', () => withDebug('pw:api,pw:browser', () => { + const printed = []; + debug.log = function (...args) { printed.push(`${this.namespace} ${args.join(' ')}`); }; + const recorder = createBrowserLogRecorder({ debug, write: () => {} }); + debug('pw:api')('call'); + debug('pw:browser')('[pid=1][out] hello'); + debug('pw:protocol')('not enabled'); + assert.equal(printed.length, 2); + assert.match(printed[0], /^pw:api /); + assert.match(printed[1], /^pw:browser /); + assert.doesNotMatch(recorder.tail(), /call/); + recorder.uninstall(); + assert.equal(debug.enabled('pw:api'), true); + assert.equal(debug.enabled('pw:browser'), true); +})); + +test('attaches the tail and the exit only to a test whose target went away', async () => withDebug('', async () => { + debug.log = () => {}; + const recorder = createBrowserLogRecorder({ debug, write: () => {} }); + const browser = debug('pw:browser'); + browser('\u001b[30m[pid=8][err] Crash Annotation GraphicsCriticalError\u001b[0m'); + browser('[pid=8] '); + + const passed = testInfo({ status: 'passed' }); + assert.equal(await attachBrowserLogs(passed, recorder), false); + const assertion = testInfo({ errors: [{ message: 'expect(locator).toBeVisible() failed' }] }); + assert.equal(await attachBrowserLogs(assertion, recorder), false); + assert.deepEqual(assertion.attachments, []); + + const closed = testInfo({ errors: [{ message: 'Error: browser.newContext: Target page, context or browser has been closed' }] }); + assert.equal(await attachBrowserLogs(closed, recorder), true); + assert.equal(closed.attachments.length, 1); + const [{ name, path, contentType }] = closed.attachments; + assert.equal(name, 'browser-stderr'); + assert.equal(contentType, 'text/plain'); + const body = readFileSync(path, 'utf8'); + assert.match(body, /^browser pid=8 exited: exitCode=null, signal=SIGKILL\n/); + assert.match(body, /\[pid=8\]\[err\] Crash Annotation GraphicsCriticalError/); + assert.doesNotMatch(body, /\u001b/, 'the attached log has no terminal colours'); + recorder.uninstall(); +})); + +test('says so when the worker logged no abnormal exit', async () => withDebug('', async () => { + debug.log = () => {}; + const recorder = createBrowserLogRecorder({ debug, write: () => {} }); + const closed = testInfo({ errors: [{ message: 'x', stack: 'Error: Target closed\n at y' }] }); + assert.equal(await attachBrowserLogs(closed, recorder), true); + assert.match(readFileSync(closed.attachments[0].path, 'utf8'), /^no abnormal browser exit was logged in this worker\n/); + recorder.uninstall(); +})); diff --git a/tools/vendor/browser-logs.mjs b/tools/vendor/browser-logs.mjs new file mode 100644 index 00000000..102ab077 --- /dev/null +++ b/tools/vendor/browser-logs.mjs @@ -0,0 +1,91 @@ +// What a browser printed before it died (#513). Playwright writes a browser's stderr, its launch and its exit +// (``) only to its `pw:browser` debug channel, which is off unless DEBUG is +// set, so a browser that dies between two tests leaves the next test only "Target page, context or browser has been +// closed". A worker records that channel into a bounded tail, prints one line when a browser exits abnormally and +// attaches the tail to a test that fails on a closed or crashed target. Nothing is retried or hidden. +import { createRequire } from 'node:module'; +import { writeFile } from 'node:fs/promises'; +import { format, stripVTControlCharacters } from 'node:util'; + +const BROWSER_NAMESPACE = 'pw:browser'; +export const BROWSER_LOG_LIMIT = 300; +export const BROWSER_EXIT_PREFIX = 'pm-browser-exit| '; +const LAUNCH_LINE = / pid=(\d+)/; +const EXIT_LINE = /\[pid=(\d+)\] ]+)>/; +// The client's TargetClosedError, a protocol error of a closed or crashed target, and a crashed page. +const TARGET_GONE = /Target page, context or browser has been closed|Target (?:closed|crashed)|Browser closed|browser has disconnected|Page crashed/i; + +/** The `debug` module Playwright logs through (the instance this worker's tests launch browsers with). */ +export function playwrightDebug() { + return createRequire(import.meta.url)('playwright-core/lib/utilsBundle').debug; +} + +/** The pid, exit code and signal of a `process did exit` line, or null. */ +export function parseExitLine(line) { + const match = EXIT_LINE.exec(line); + if (!match) return null; + const value = text => (text === 'null' ? null : text); + const code = value(match[2]); + return { pid: Number(match[1]), exitCode: code === null ? null : Number(code), signal: value(match[3]) }; +} + +export const isAbnormalExit = exit => exit !== null && (exit.exitCode !== 0 || exit.signal !== null); + +/** True for an error message that says the page, context or browser under the test went away. */ +export const isTargetGone = message => TARGET_GONE.test(String(message ?? '')); + +/** + * Records `pw:browser` into a tail of at most `limit` lines. Other debug channels keep printing as before; the + * browser channel prints only when the user's own DEBUG asked for it. `write` gets one line per abnormal exit. + */ +export function createBrowserLogRecorder({ debug = playwrightDebug(), limit = BROWSER_LOG_LIMIT, + write = text => process.stderr.write(text) } = {}) { + const lines = []; + const launches = []; + const exits = []; + const userWantsBrowser = debug.enabled(BROWSER_NAMESPACE); + const previous = debug.disable(); + const original = debug.log; + debug.log = function record(...args) { + if (this?.namespace !== BROWSER_NAMESPACE || userWantsBrowser) { + (original ?? (() => {})).apply(this, args); + } + if (this?.namespace !== BROWSER_NAMESPACE) return; + const line = stripVTControlCharacters(format(...args)); + lines.push(line); + if (lines.length > limit) lines.splice(0, lines.length - limit); + const launched = LAUNCH_LINE.exec(line); + if (launched) launches.push(Number(launched[1])); + const exit = parseExitLine(line); + if (!exit) return; + exits.push(exit); + if (isAbnormalExit(exit)) { + write(`${BROWSER_EXIT_PREFIX}browser pid=${exit.pid} exited: exitCode=${exit.exitCode}, signal=${exit.signal}\n`); + } + }; + debug.enable([previous, BROWSER_NAMESPACE].filter(Boolean).join(',')); + return { + tail: () => lines.join('\n'), + launches: () => [...launches], + exits: () => [...exits], + uninstall() { + debug.log = original; + debug.disable(); + if (previous) debug.enable(previous); + }, + }; +} + +/** Attaches the browser log tail to a test that failed because its page, context or browser went away. */ +export async function attachBrowserLogs(testInfo, recorder) { + if (testInfo.status === testInfo.expectedStatus) return false; + if (!testInfo.errors.some(error => isTargetGone(error.message) || isTargetGone(error.stack))) return false; + const exits = recorder.exits().filter(isAbnormalExit) + .map(exit => `browser pid=${exit.pid} exited: exitCode=${exit.exitCode}, signal=${exit.signal}`); + const summary = exits.length ? exits.join('\n') : 'no abnormal browser exit was logged in this worker'; + // A file, so the log travels with the uploaded test-results (the list reporter shortens a long body). + const path = testInfo.outputPath('browser-stderr.txt'); + await writeFile(path, `${summary}\n--- last ${BROWSER_LOG_LIMIT} pw:browser lines ---\n${recorder.tail()}\n`); + await testInfo.attach('browser-stderr', { path, contentType: 'text/plain' }); + return true; +}