diff --git a/src/chromium/crConnection.ts b/src/chromium/crConnection.ts index 4100e0f25618f..43d1843031552 100644 --- a/src/chromium/crConnection.ts +++ b/src/chromium/crConnection.ts @@ -44,6 +44,7 @@ export class CRConnection extends platform.EventEmitter { this.rootSession = new CRSession(this, '', 'browser', ''); this._sessions.set('', this.rootSession); this._debugProtocol = platform.debug('pw:protocol'); + (this._debugProtocol as any).color = '34'; } static fromSession(session: CRSession): CRConnection { diff --git a/src/firefox/ffConnection.ts b/src/firefox/ffConnection.ts index 120ab8efb465e..006d33155c5ec 100644 --- a/src/firefox/ffConnection.ts +++ b/src/firefox/ffConnection.ts @@ -58,6 +58,7 @@ export class FFConnection extends platform.EventEmitter { this.off = super.removeListener; this.removeListener = super.removeListener; this.once = super.once; + (this._debugProtocol as any).color = '34'; } async send( diff --git a/src/server/processLauncher.ts b/src/server/processLauncher.ts index 3b0be1b920ed6..d074babc83ff1 100644 --- a/src/server/processLauncher.ts +++ b/src/server/processLauncher.ts @@ -23,7 +23,6 @@ import * as readline from 'readline'; import { TimeoutError } from '../errors'; import * as platform from '../platform'; -const debugLauncher = platform.debug('pw:launcher'); const removeFolderAsync = platform.promisify(removeFolder); export type LaunchProcessOptions = { @@ -49,6 +48,12 @@ let lastLaunchedId = 0; export async function launchProcess(options: LaunchProcessOptions): Promise { const id = ++lastLaunchedId; + const debugBrowser = platform.debug(`pw:browser:proc:[${id}]`); + const debugBrowserOut = platform.debug(`pw:browser:out:[${id}]`); + const debugBrowserErr = platform.debug(`pw:browser:err:[${id}]`); + (debugBrowser as any).color = '33'; + (debugBrowserOut as any).color = '178'; + (debugBrowserErr as any).color = '160'; const stdio: ('ignore' | 'pipe')[] = options.pipe ? ['ignore', 'pipe', 'pipe', 'pipe', 'pipe'] : ['ignore', 'pipe', 'pipe']; const spawnedProcess = childProcess.spawn( options.executablePath, @@ -62,7 +67,7 @@ export async function launchProcess(options: LaunchProcessOptions): Promise ${options.executablePath} ${options.args.join(' ')}`); + debugBrowser(` ${options.executablePath} ${options.args.join(' ')}`); if (!spawnedProcess.pid) { let reject: (e: Error) => void; @@ -73,18 +78,24 @@ export async function launchProcess(options: LaunchProcessOptions): Promise {}); - spawnedProcess.stdout.on('data', () => {}); - } + const stdout = readline.createInterface({ input: spawnedProcess.stdout }); + stdout.on('line', (data: string) => { + debugBrowserOut(data); + if (options.dumpio) + console.log(`\x1b[33m[out]\x1b[0m ${data}`); // eslint-disable-line no-console + }); + + const stderr = readline.createInterface({ input: spawnedProcess.stderr }); + stderr.on('line', (data: string) => { + debugBrowserErr(data); + if (options.dumpio) + console.log(`\x1b[31m[err]\x1b[0m ${data}`); // eslint-disable-line no-console + }); let processClosed = false; const waitForProcessToClose = new Promise((fulfill, reject) => { spawnedProcess.once('exit', (exitCode, signal) => { - debugLauncher(`[${id}] `); + debugBrowser(``); processClosed = true; helper.removeEventListeners(listeners); options.onkill(exitCode, signal); @@ -117,20 +128,20 @@ export async function launchProcess(options: LaunchProcessOptions): Promise`); + debugBrowser(``); killProcess(); return; } gracefullyClosing = true; - debugLauncher(`[${id}] `); + debugBrowser(``); options.attemptToGracefullyClose().catch(() => killProcess()); await waitForProcessToClose; - debugLauncher(`[${id}] `); + debugBrowser(``); } // This method has to be sync to be used as 'exit' event handler. function killProcess() { - debugLauncher(`[${id}] `); + debugBrowser(``); helper.removeEventListeners(listeners); if (spawnedProcess.pid && !spawnedProcess.killed && !processClosed) { // Force kill the browser. diff --git a/src/webkit/wkBrowser.ts b/src/webkit/wkBrowser.ts index 48c864053a570..121a85c04cf14 100644 --- a/src/webkit/wkBrowser.ts +++ b/src/webkit/wkBrowser.ts @@ -187,7 +187,7 @@ export class WKBrowser extends platform.EventEmitter implements Browser { } _setDebugFunction(debugFunction: (message: string) => void) { - this._connection._debugFunction = debugFunction; + this._connection._debugProtocol = debugFunction; } } diff --git a/src/webkit/wkConnection.ts b/src/webkit/wkConnection.ts index 8182a354f66ff..754e5d5d77448 100644 --- a/src/webkit/wkConnection.ts +++ b/src/webkit/wkConnection.ts @@ -34,7 +34,7 @@ export class WKConnection { private readonly _onDisconnect: () => void; private _lastId = 0; private _closed = false; - _debugFunction: (message: string) => void = platform.debug('pw:protocol'); + _debugProtocol: (message: string) => void = platform.debug('pw:protocol'); readonly browserSession: WKSession; @@ -46,6 +46,7 @@ export class WKConnection { this.browserSession = new WKSession(this, '', 'Browser has been closed.', (message: any) => { this.rawSend(message); }); + (this._debugProtocol as any).color = '34'; } nextMessageId(): number { @@ -54,12 +55,12 @@ export class WKConnection { rawSend(message: any) { const data = JSON.stringify(message); - this._debugFunction('SEND ► ' + (rewriteInjectedScriptEvaluationLog(message) || data)); + this._debugProtocol('SEND ► ' + (rewriteInjectedScriptEvaluationLog(message) || data)); this._transport.send(data); } private _dispatchMessage(message: string) { - this._debugFunction('◀ RECV ' + message); + this._debugProtocol('◀ RECV ' + message); const object = JSON.parse(message); if (object.id === kBrowserCloseMessageId) return; diff --git a/test/fixtures.spec.js b/test/fixtures.spec.js index d547c44624b60..242f81bfca551 100644 --- a/test/fixtures.spec.js +++ b/test/fixtures.spec.js @@ -72,14 +72,14 @@ module.exports.describe = function({testRunner, expect, product, browserType, pl it.slow()('should dump browser process stderr', async({server}) => { let dumpioData = ''; const res = spawn('node', [path.join(__dirname, 'fixtures', 'dumpio.js'), playwrightPath, product, 'usewebsocket']); - res.stderr.on('data', data => dumpioData += data.toString('utf8')); + res.stdout.on('data', data => dumpioData += data.toString('utf8')); await new Promise(resolve => res.on('close', resolve)); expect(dumpioData).toContain('message from dumpio'); }); it.slow()('should dump browser process stderr', async({server}) => { let dumpioData = ''; const res = spawn('node', [path.join(__dirname, 'fixtures', 'dumpio.js'), playwrightPath, product]); - res.stderr.on('data', data => dumpioData += data.toString('utf8')); + res.stdout.on('data', data => dumpioData += data.toString('utf8')); await new Promise(resolve => res.on('close', resolve)); expect(dumpioData).toContain('message from dumpio'); }); diff --git a/test/playwright.spec.js b/test/playwright.spec.js index 7f5e007d3f489..5e25ea04203b7 100644 --- a/test/playwright.spec.js +++ b/test/playwright.spec.js @@ -20,6 +20,7 @@ const os = require('os'); const rm = require('rimraf').sync; const GoldenUtils = require('./golden-utils'); const {Matchers} = require('../utils/testrunner/'); +const readline = require('readline'); const YELLOW_COLOR = '\x1b[33m'; const RESET_COLOR = '\x1b[0m'; @@ -61,7 +62,6 @@ module.exports.describe = ({testRunner, product, playwrightPath}) => { executablePath, slowMo, headless, - dumpio: !!process.env.DUMPIO, }; if (defaultBrowserOptions.executablePath) { @@ -103,31 +103,29 @@ module.exports.describe = ({testRunner, product, playwrightPath}) => { beforeAll(async state => { state.browser = await browserType.launch(defaultBrowserOptions); state.browserServer = state.browser.__server__; + state._stdout = readline.createInterface({ input: state.browserServer.process().stdout }); + state._stderr = readline.createInterface({ input: state.browserServer.process().stderr }); }); afterAll(async state => { await state.browserServer.close(); state.browser = null; state.browserServer = null; - }); + state._stdout.close(); + state._stderr.close(); + }); beforeEach(async(state, test) => { - const onLine = (line) => test.output += line + '\n'; + test.output = []; + const dumpout = data => test.output.push(`\x1b[33m[pw:stdio:out]\x1b[0m ${data}`); + const dumperr = data => test.output.push(`\x1b[31m[pw:stdio:err]\x1b[0m ${data}`); + state._stdout.on('line', dumpout); + state._stderr.on('line', dumperr); if (dumpProtocolOnFailure) - state.browser._setDebugFunction(onLine); - - let rl; - if (state.browserServer.process().stderr) { - rl = require('readline').createInterface({ input: state.browserServer.process().stderr }); - test.output = ''; - rl.on('line', onLine); - } - + state.browser._setDebugFunction(data => test.output.push(`\x1b[32m[pw:protocol]\x1b[0m ${data}`)); state.tearDown = async () => { - if (rl) { - rl.removeListener('line', onLine); - rl.close(); - } + state._stdout.off('line', dumpout); + state._stderr.off('line', dumperr); if (dumpProtocolOnFailure) state.browser._setDebugFunction(() => void 0); }; diff --git a/utils/testrunner/Reporter.js b/utils/testrunner/Reporter.js index 79f02698a8597..e6b85688af0a9 100644 --- a/utils/testrunner/Reporter.js +++ b/utils/testrunner/Reporter.js @@ -207,7 +207,8 @@ class Reporter { console.log(`${prefix} ${colors.red(`[TIMEOUT ${test.timeout}ms]`)} ${test.fullName} (${formatLocation(test.location)})`); if (test.output) { console.log(' Output:'); - console.log(padLines(test.output, 4)); + for (const line of test.output) + console.log(' ' + line); } } else if (test.result === 'failed') { console.log(`${prefix} ${colors.red('[FAIL]')} ${test.fullName} (${formatLocation(test.location)})`); @@ -253,7 +254,8 @@ class Reporter { } if (test.output) { console.log(' Output:'); - console.log(padLines(test.output, 4)); + for (const line of test.output) + console.log(' ' + line); } } }