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
This commit is contained in:
Max Schmitt 2023-09-14 18:34:26 +02:00 committed by GitHub
parent 57e5183809
commit 4431a8366d
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
6 changed files with 54 additions and 22 deletions

View File

@ -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 };
}

View File

@ -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<Suite> {

View File

@ -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<void>((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());

View File

@ -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) {

View File

@ -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);

View File

@ -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': `