chore(tests): log protocol messages when a test fails on the bots (#963)

Similarly to how we handle stdio, this captures all protocol messages and logs them when a test fails. Great for when debugging tests in parallel or for bot failures!

Currently I made `DEBUGP=true` turn this on locally, and turned it on always for the CI. Open to 
suggestions for a better environment variable. I would turn it on by default always, like the stdio logging, but it adds an enormous amount of noise to our error messages.

Author: JoelEinbinder

src/browser.ts

@@ -24,6 +24,7 @@ export interface Browser extends platform.EventEmitterType {
   newPage(options?: BrowserContextOptions): Promise<Page>;
   isConnected(): boolean;
   close(): Promise<void>;
+  _setDebugFunction(debugFunction: (message: string) => void): void;
 }
 
 export type ConnectOptions = {

src/chromium/crBrowser.ts

@@ -304,4 +304,8 @@ export class CRBrowser extends platform.EventEmitter implements Browser {
   isConnected(): boolean {
     return !this._connection._closed;
   }
+
+  _setDebugFunction(debugFunction: (message: string) => void) {
+    this._connection._debugProtocol = debugFunction;
+  }
 }

src/chromium/crConnection.ts

@@ -20,8 +20,6 @@ import { ConnectionTransport } from '../transport';
 import { assert } from '../helper';
 import { Protocol } from './protocol';
 
-const debugProtocol = platform.debug('pw:protocol');
-
 export const ConnectionEvents = {
   Disconnected: Symbol('ConnectionEvents.Disconnected')
 };
@@ -36,6 +34,7 @@ export class CRConnection extends platform.EventEmitter {
   private _sessions = new Map<string, CRSession>();
   readonly rootSession: CRSession;
   _closed = false;
+  _debugProtocol: (message: string) => void;
 
   constructor(transport: ConnectionTransport) {
     super();
@@ -44,6 +43,7 @@ export class CRConnection extends platform.EventEmitter {
     this._transport.onclose = this._onClose.bind(this);
     this.rootSession = new CRSession(this, 'browser', '');
     this._sessions.set('', this.rootSession);
+    this._debugProtocol = platform.debug('pw:protocol');
   }
 
   static fromSession(session: CRSession): CRConnection {
@@ -60,13 +60,13 @@ export class CRConnection extends platform.EventEmitter {
     if (sessionId)
       message.sessionId = sessionId;
     const data = JSON.stringify(message);
-    debugProtocol('SEND ► ' + data);
+    this._debugProtocol('SEND ► ' + data);
     this._transport.send(data);
     return id;
   }
 
   async _onMessage(message: string) {
-    debugProtocol('◀ RECV ' + message);
+    this._debugProtocol('◀ RECV ' + message);
     const object = JSON.parse(message);
     if (object.id === kBrowserCloseMessageId)
       return;

src/firefox/ffBrowser.ts

@@ -242,6 +242,10 @@ export class FFBrowser extends platform.EventEmitter implements Browser {
     }, options);
     return context;
   }
+
+  _setDebugFunction(debugFunction: (message: string) => void) {
+    this._connection._debugProtocol = debugFunction;
+  }
 }
 
 class Target {

src/firefox/ffConnection.ts

@@ -20,8 +20,6 @@ import * as platform from '../platform';
 import { ConnectionTransport } from '../transport';
 import { Protocol } from './protocol';
 
-const debugProtocol = platform.debug('pw:protocol');
-
 export const ConnectionEvents = {
   Disconnected: Symbol('Disconnected'),
 };
@@ -35,6 +33,7 @@ export class FFConnection extends platform.EventEmitter {
   private _callbacks: Map<number, {resolve: Function, reject: Function, error: Error, method: string}>;
   private _transport: ConnectionTransport;
   private _sessions: Map<string, FFSession>;
+  _debugProtocol: (message: string) => void = platform.debug('pw:protocol');
   _closed: boolean;
 
   on: <T extends keyof Protocol.Events | symbol>(event: T, listener: (payload: T extends symbol ? any : Protocol.Events[T extends keyof Protocol.Events ? T : never]) => void) => this;
@@ -86,12 +85,12 @@ export class FFConnection extends platform.EventEmitter {
 
   _rawSend(message: any) {
     message = JSON.stringify(message);
-    debugProtocol('SEND ► ' + message);
+    this._debugProtocol('SEND ► ' + message);
     this._transport.send(message);
   }
 
   async _onMessage(message: string) {
-    debugProtocol('◀ RECV ' + message);
+    this._debugProtocol('◀ RECV ' + message);
     const object = JSON.parse(message);
     if (object.id === kBrowserCloseMessageId)
       return;

src/webkit/wkBrowser.ts

@@ -239,4 +239,8 @@ export class WKBrowser extends platform.EventEmitter implements Browser {
     }, options);
     return context;
   }
+
+  _setDebugFunction(debugFunction: (message: string) => void) {
+    this._connection._debugFunction = debugFunction;
+  }
 }

src/webkit/wkConnection.ts

@@ -20,8 +20,6 @@ import * as platform from '../platform';
 import { ConnectionTransport } from '../transport';
 import { Protocol } from './protocol';
 
-const debugProtocol = platform.debug('pw:protocol');
-
 // WKPlaywright uses this special id to issue Browser.close command which we
 // should ignore.
 export const kBrowserCloseMessageId = -9999;
@@ -36,6 +34,7 @@ export class WKConnection {
   private readonly _transport: ConnectionTransport;
   private _closed = false;
   private _onDisconnect: () => void;
+  _debugFunction: (message: string) => void = platform.debug('pw:protocol');
 
   readonly browserSession: WKSession;
 
@@ -55,12 +54,12 @@ export class WKConnection {
 
   rawSend(message: any) {
     message = JSON.stringify(message);
-    debugProtocol('SEND ► ' + message);
+    this._debugFunction('SEND ► ' + message);
     this._transport.send(message);
   }
 
   private _dispatchMessage(message: string) {
-    debugProtocol('◀ RECV ' + message);
+    this._debugFunction('◀ RECV ' + message);
     const object = JSON.parse(message);
     if (object.id === kBrowserCloseMessageId)
       return;

test/playwright.spec.js

@@ -42,9 +42,16 @@ module.exports.describe = ({testRunner, product, playwrightPath}) => {
   const playwrightModule = require(playwrightPath);
   const playwright = playwrightModule[product.toLowerCase()];
 
-  const headless = (process.env.HEADLESS || 'true').trim().toLowerCase() === 'true';
-  const slowMo = parseInt((process.env.SLOW_MO || '0').trim(), 10);
-
+  const headless = !!valueFromEnv('HEADLESS', true);
+  const slowMo = valueFromEnv('SLOW_MO', 0);
+  const CI = valueFromEnv('CI', false);
+  const dumpProtocolOnFailure = CI || valueFromEnv('DEBUGP', true);
+
+  function valueFromEnv(name, defaultValue) {
+    if (!(name in process.env))
+      return defaultValue;
+    return JSON.parse(process.env[name]);
+  }
   const executablePath = {
     'Chromium': process.env.CRPATH,
     'Firefox': process.env.FFPATH,
@@ -108,6 +115,8 @@ module.exports.describe = ({testRunner, product, playwrightPath}) => {
     beforeEach(async(state, test) => {
       const contexts = [];
       const onLine = (line) => test.output += line + '\n';
+      if (dumpProtocolOnFailure)
+        state.browser._setDebugFunction(onLine);
 
       let rl;
       if (state.browserServer.process().stderr) {
@@ -123,6 +132,8 @@ module.exports.describe = ({testRunner, product, playwrightPath}) => {
           rl.removeListener('line', onLine);
           rl.close();
         }
+        if (dumpProtocolOnFailure)
+          state.browser._setDebugFunction(() => void 0);
       };
 
       state.newContext = async (options) => {