test: make debugp collect IO (take 2) (#1493)

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 {

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<T extends keyof Protocol.CommandParameters>(

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<LaunchResult> {
   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<Laun
         stdio
       }
   );
-  debugLauncher(`[${id}] <launching> ${options.executablePath} ${options.args.join(' ')}`);
+  debugBrowser(`<launching> ${options.executablePath} ${options.args.join(' ')}`);
 
   if (!spawnedProcess.pid) {
     let reject: (e: Error) => void;
@@ -73,18 +78,24 @@ export async function launchProcess(options: LaunchProcessOptions): Promise<Laun
     return result;
   }
 
-  if (options.dumpio) {
-    spawnedProcess.stdout.pipe(process.stdout);
-    spawnedProcess.stderr.pipe(process.stderr);
-  } else {
-    spawnedProcess.stderr.on('data', () => {});
-    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}] <process did exit ${exitCode}, ${signal}>`);
+      debugBrowser(`<process did exit ${exitCode}, ${signal}>`);
       processClosed = true;
       helper.removeEventListeners(listeners);
       options.onkill(exitCode, signal);
@@ -117,20 +128,20 @@ export async function launchProcess(options: LaunchProcessOptions): Promise<Laun
     // reentrancy to this function, for example user sends SIGINT second time.
     // In this case, let's forcefully kill the process.
     if (gracefullyClosing) {
-      debugLauncher(`[${id}] <forecefully close>`);
+      debugBrowser(`<forecefully close>`);
       killProcess();
       return;
     }
     gracefullyClosing = true;
-    debugLauncher(`[${id}] <gracefully close start>`);
+    debugBrowser(`<gracefully close start>`);
     options.attemptToGracefullyClose().catch(() => killProcess());
     await waitForProcessToClose;
-    debugLauncher(`[${id}] <gracefully close end>`);
+    debugBrowser(`<gracefully close end>`);
   }
 
   // This method has to be sync to be used as 'exit' event handler.
   function killProcess() {
-    debugLauncher(`[${id}] <kill>`);
+    debugBrowser(`<kill>`);
     helper.removeEventListeners(listeners);
     if (spawnedProcess.pid && !spawnedProcess.killed && !processClosed) {
       // Force kill the browser.

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

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;

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');
     });

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

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