From 4431a8366dcbefb8a04e39823e621e9ab8f404d1 Mon Sep 17 00:00:00 2001 From: Max Schmitt Date: Thu, 14 Sep 2023 18:34:26 +0200 Subject: [PATCH] fix: collect stdio from forked processes (#27074) A summary about the attempts we tried in https://github.com/microsoft/playwright/pull/26931 for https://github.com/microsoft/playwright/issues/26859 and https://github.com/microsoft/playwright/issues/24591. 1. attempt: collect all the stdio from the worker host. - this made it hard to capture the live console logs for the live trace 2. attempt: collect all the stdio from the worker host, but keep proxying `process.{stdout,stderr}.write`. - this solved the live console logs problem, since we could still listen on them - we found out about a race that the stdout/stderr streams can still buffer data while the test already had finished - we created a best effort flush implementation but didn't like the complexity it introduced to the project 3. attempt: keep things like they are but also listen to stdio from the worker host - this solves the race of console.log in the test (things stay like they are) - this keeps live trace working (things stay like they are) - a known pitfall is that it could result in logs which don't end up in the reporter onStdOut/onStdErr, but it is already a significant improvement over how it was before. - before: they were not getting displayed - after: they are getting displayed and there is a low likelihood that they don't end up in the reporter API if the write happens slightly before a test finished. Closes #26931 Fixes #26859 Fixes #24591 --- packages/playwright/src/common/ipc.ts | 9 +++++++ packages/playwright/src/runner/loaderHost.ts | 2 +- packages/playwright/src/runner/processHost.ts | 14 +++++++++-- packages/playwright/src/runner/workerHost.ts | 6 ++++- packages/playwright/src/worker/workerMain.ts | 21 +++------------- tests/playwright-test/exit-code.spec.ts | 24 +++++++++++++++++++ 6 files changed, 54 insertions(+), 22 deletions(-) diff --git a/packages/playwright/src/common/ipc.ts b/packages/playwright/src/common/ipc.ts index 0e5113e0eb..3310b46b3a 100644 --- a/packages/playwright/src/common/ipc.ts +++ b/packages/playwright/src/common/ipc.ts @@ -14,6 +14,7 @@ * limitations under the License. */ +import util from 'util'; import { serializeCompilationCache } from '../transform/compilationCache'; import type { FullConfigInternal } from './config'; import type { ReporterDescription, TestInfoError, TestStatus } from '../../types/test'; @@ -141,3 +142,11 @@ export function serializeConfig(config: FullConfigInternal): SerializedConfig { }; return result; } + +export function stdioChunkToParams(chunk: Uint8Array | string): TestOutputPayload { + if (chunk instanceof Uint8Array) + return { buffer: Buffer.from(chunk).toString('base64') }; + if (typeof chunk !== 'string') + return { text: util.inspect(chunk) }; + return { text: chunk }; +} diff --git a/packages/playwright/src/runner/loaderHost.ts b/packages/playwright/src/runner/loaderHost.ts index 8afaa2916a..d1e94688ed 100644 --- a/packages/playwright/src/runner/loaderHost.ts +++ b/packages/playwright/src/runner/loaderHost.ts @@ -58,7 +58,7 @@ export class OutOfProcessLoaderHost { } async start() { - await this._processHost.startRunner(serializeConfig(this._config), true); + await this._processHost.startRunner(serializeConfig(this._config)); } async loadTestFile(file: string, testErrors: TestError[]): Promise { diff --git a/packages/playwright/src/runner/processHost.ts b/packages/playwright/src/runner/processHost.ts index 60b5923ca6..689a5a1938 100644 --- a/packages/playwright/src/runner/processHost.ts +++ b/packages/playwright/src/runner/processHost.ts @@ -46,11 +46,16 @@ export class ProcessHost extends EventEmitter { this._extraEnv = env; } - async startRunner(runnerParams: any, inheritStdio: boolean) { + async startRunner(runnerParams: any, options: { onStdOut?: (chunk: Buffer | string) => void, onStdErr?: (chunk: Buffer | string) => void } = {}) { this.process = child_process.fork(require.resolve('../common/process'), { detached: false, env: { ...process.env, ...this._extraEnv }, - stdio: inheritStdio ? ['ignore', 'inherit', 'inherit', 'ipc'] : ['ignore', 'ignore', process.env.PW_RUNNER_DEBUG ? 'inherit' : 'ignore', 'ipc'], + stdio: [ + 'ignore', + options.onStdOut ? 'pipe' : 'inherit', + (options.onStdErr && !process.env.PW_RUNNER_DEBUG) ? 'pipe' : 'inherit', + 'ipc', + ], ...(process.env.PW_TS_ESM_ON ? { execArgv: execArgvWithExperimentalLoaderOptions() } : {}), }); this.process.on('exit', (code, signal) => { @@ -84,6 +89,11 @@ export class ProcessHost extends EventEmitter { } }); + if (options.onStdOut) + this.process.stdout?.on('data', options.onStdOut); + if (options.onStdErr) + this.process.stderr?.on('data', options.onStdErr); + await new Promise((resolve, reject) => { this.process!.once('exit', (code, signal) => reject(new Error(`process exited with code "${code}" and signal "${signal}" before it became ready`))); this.once('ready', () => resolve()); diff --git a/packages/playwright/src/runner/workerHost.ts b/packages/playwright/src/runner/workerHost.ts index 4a71a6af01..e2c0444dbe 100644 --- a/packages/playwright/src/runner/workerHost.ts +++ b/packages/playwright/src/runner/workerHost.ts @@ -17,6 +17,7 @@ import fs from 'fs'; import path from 'path'; import type { TestGroup } from './testGroups'; +import { stdioChunkToParams } from '../common/ipc'; import type { RunPayload, SerializedConfig, WorkerInitParams } from '../common/ipc'; import { ProcessHost } from './processHost'; import { artifactsFolderName } from '../isomorphic/folders'; @@ -54,7 +55,10 @@ export class WorkerHost extends ProcessHost { async start() { await fs.promises.mkdir(this._params.artifactsDir, { recursive: true }); - await this.startRunner(this._params, false); + await this.startRunner(this._params, { + onStdOut: chunk => this.emit('stdOut', stdioChunkToParams(chunk)), + onStdErr: chunk => this.emit('stdErr', stdioChunkToParams(chunk)), + }); } override async stop(didFail?: boolean) { diff --git a/packages/playwright/src/worker/workerMain.ts b/packages/playwright/src/worker/workerMain.ts index 5d5b7efd1c..cb1c5e5225 100644 --- a/packages/playwright/src/worker/workerMain.ts +++ b/packages/playwright/src/worker/workerMain.ts @@ -15,9 +15,8 @@ */ import { colors, rimraf } from 'playwright-core/lib/utilsBundle'; -import util from 'util'; import { debugTest, formatLocation, relativeFilePath, serializeError } from '../util'; -import type { TestBeginPayload, TestEndPayload, RunPayload, DonePayload, WorkerInitParams, TeardownErrorsPayload, TestOutputPayload } from '../common/ipc'; +import { type TestBeginPayload, type TestEndPayload, type RunPayload, type DonePayload, type WorkerInitParams, type TeardownErrorsPayload, stdioChunkToParams } from '../common/ipc'; import { setCurrentTestInfo, setIsWorkerProcess } from '../common/globals'; import { ConfigLoader } from '../common/configLoader'; import type { Suite, TestCase } from '../common/test'; @@ -76,20 +75,14 @@ export class WorkerMain extends ProcessRunner { process.on('unhandledRejection', reason => this.unhandledError(reason)); process.on('uncaughtException', error => this.unhandledError(error)); process.stdout.write = (chunk: string | Buffer) => { - const outPayload: TestOutputPayload = { - ...chunkToParams(chunk) - }; - this.dispatchEvent('stdOut', outPayload); + this.dispatchEvent('stdOut', stdioChunkToParams(chunk)); this._currentTest?._tracing.appendStdioToTrace('stdout', chunk); return true; }; if (!process.env.PW_RUNNER_DEBUG) { process.stderr.write = (chunk: string | Buffer) => { - const outPayload: TestOutputPayload = { - ...chunkToParams(chunk) - }; - this.dispatchEvent('stdErr', outPayload); + this.dispatchEvent('stdErr', stdioChunkToParams(chunk)); this._currentTest?._tracing.appendStdioToTrace('stderr', chunk); return true; }; @@ -652,12 +645,4 @@ function formatTestTitle(test: TestCase, projectName: string) { return `${projectTitle}${location} › ${titles.join(' › ')}`; } -function chunkToParams(chunk: Uint8Array | string, encoding?: BufferEncoding): { text?: string, buffer?: string } { - if (chunk instanceof Uint8Array) - return { buffer: Buffer.from(chunk).toString('base64') }; - if (typeof chunk !== 'string') - return { text: util.inspect(chunk) }; - return { text: chunk }; -} - export const create = (params: WorkerInitParams) => new WorkerMain(params); diff --git a/tests/playwright-test/exit-code.spec.ts b/tests/playwright-test/exit-code.spec.ts index 65a26cd90a..661385c950 100644 --- a/tests/playwright-test/exit-code.spec.ts +++ b/tests/playwright-test/exit-code.spec.ts @@ -40,6 +40,30 @@ test('should collect stdio', async ({ runInlineTest }) => { expect(stderr).toEqual([{ text: 'stderr text' }, { buffer: Buffer.from('stderr buffer').toString('base64') }]); }); +test('should collect stdio from forked process', async ({ runInlineTest }) => { + const { exitCode, report } = await runInlineTest({ + 'stdio.spec.js': ` + import { test } from '@playwright/test'; + import { fork } from 'child_process'; + test('stdio', async () => { + const child = fork('fork.js'); + await new Promise((resolve) => child.on('exit', (code) => resolve(code))); + }); + `, + 'fork.js': ` + process.stdout.write('stdout text'); + process.stdout.write(Buffer.from('stdout buffer')); + process.stderr.write('stderr text'); + process.stderr.write(Buffer.from('stderr buffer')); + ` + }); + expect(exitCode).toBe(0); + const testResult = report.suites[0].specs[0].tests[0].results[0]; + const { stdout, stderr } = testResult; + expect(stdout.map(e => Buffer.from((e as any).buffer, 'base64').toString()).join('')).toEqual('stdout textstdout buffer'); + expect(stderr.map(e => Buffer.from((e as any).buffer, 'base64').toString()).join('')).toEqual('stderr textstderr buffer'); +}); + test('should work with not defined errors', async ({ runInlineTest }) => { const result = await runInlineTest({ 'is-not-defined-error.spec.ts': `