test(browser): record each worker's browser log and attach it when a target closes (#513)

A browser that died between two tests left the next one only
'Target page, context or browser has been closed': Playwright logs a
browser's stderr and exit only on the pw:browser debug channel, which CI
leaves off. Each worker now keeps that channel as a bounded tail, prints
one pm-browser-exit| line on an abnormal exit and attaches the tail as
browser-stderr.txt to a test that fails on a closed or crashed target.
Nothing is retried or hidden.

Refs #513

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=<n> exited: exitCode=<c>, signal=<s>` 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

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}] <process did exit: exitCode=null, signal=SIGKILL>`);
+});

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 {

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] <process did exit: exitCode=null, signal=SIGKILL> +21ms'),
+        { pid: 7124, exitCode: null, signal: 'SIGKILL' });
+    assert.deepEqual(parseExitLine('[pid=9] <process did exit: exitCode=0, signal=null>'), { pid: 9, exitCode: 0, signal: null });
+    assert.deepEqual(parseExitLine('[pid=9] <process did exit: exitCode=11, signal=null>'), { 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('<launched> 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] <process did exit: exitCode=null, signal=SIGKILL>');
+    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] <process did exit: exitCode=0, signal=null>');
+    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] <process did exit: exitCode=null, signal=SIGKILL>');
+
+    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();
+}));

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
+// (`<process did exit: exitCode=…, signal=…>`) 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 = /<launched> pid=(\d+)/;
+const EXIT_LINE = /\[pid=(\d+)\] <process did exit: exitCode=([^,]+), signal=([^>]+)>/;
+// 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;
+}