feat(logging): add logging to websocket transport (#2289)

src/server/chromium.ts

@@ -155,11 +155,12 @@ export class Chromium extends AbstractBrowserType<CRBrowser> {
   }
 
   async connect(options: ConnectOptions): Promise<CRBrowser> {
+    const logger = new RootLogger(options.logger);
     return await WebSocketTransport.connect(options.wsEndpoint, async transport => {
       if ((options as any).__testHookBeforeCreateBrowser)
         await (options as any).__testHookBeforeCreateBrowser();
-      return CRBrowser.connect(transport, { slowMo: options.slowMo, logger: new RootLogger(options.logger), downloadsPath: '' });
+      return CRBrowser.connect(transport, { slowMo: options.slowMo, logger, downloadsPath: '' });
-    });
+    }, logger);
   }
 
   private _defaultArgs(options: BrowserArgOptions = {}, launchType: LaunchType, userDataDir: string): string[] {

src/server/electron.ts

@@ -202,7 +202,7 @@ export class Electron  {
     const chromeMatch = await waitForLine(launchedProcess, launchedProcess.stderr, /^DevTools listening on (ws:\/\/.*)$/, helper.timeUntilDeadline(deadline), timeoutError);
     const chromeTransport = await WebSocketTransport.connect(chromeMatch[1], transport => {
       return transport;
-    });
+    }, logger);
     const browserServer = new BrowserServer(launchedProcess, gracefullyClose, null);
     const browser = await CRBrowser.connect(chromeTransport, { headful: true, logger, persistent: true, viewport: null, ownedServer: browserServer, downloadsPath: '' });
     app = new ElectronApplication(logger, browser, nodeConnection);

src/server/firefox.ts

@@ -58,7 +58,7 @@ export class Firefox extends AbstractBrowserType<FFBrowser> {
           headful: !processBrowserArgOptions(options).headless,
           ownedServer: browserServer,
         });
-      });
+      }, logger);
       return browser;
     });
   }
@@ -83,7 +83,7 @@ export class Firefox extends AbstractBrowserType<FFBrowser> {
           ownedServer: browserServer,
           headful: !processBrowserArgOptions(options).headless,
         });
-      });
+      }, logger);
       const context = browser._defaultContext!;
       if (!options.ignoreDefaultArgs || Array.isArray(options.ignoreDefaultArgs))
         await context._loadDefaultContext();
@@ -159,18 +159,21 @@ export class Firefox extends AbstractBrowserType<FFBrowser> {
     const match = await waitForLine(launchedProcess, launchedProcess.stdout, /^Juggler listening on (ws:\/\/.*)$/, timeout, timeoutError);
     const innerEndpoint = match[1];
 
-    const webSocketWrapper = launchType === 'server' ? (await WebSocketTransport.connect(innerEndpoint, t => wrapTransportWithWebSocket(t, logger, port))) : new WebSocketWrapper(innerEndpoint, []);
+    const webSocketWrapper = launchType === 'server' ?
+      (await WebSocketTransport.connect(innerEndpoint, t => wrapTransportWithWebSocket(t, logger, port), logger)) :
+      new WebSocketWrapper(innerEndpoint, []);
     browserWSEndpoint = webSocketWrapper.wsEndpoint;
     browserServer = new BrowserServer(launchedProcess, gracefullyClose, webSocketWrapper);
     return { browserServer, downloadsPath, logger };
   }
 
   async connect(options: ConnectOptions): Promise<FFBrowser> {
+    const logger = new RootLogger(options.logger);
     return await WebSocketTransport.connect(options.wsEndpoint, async transport => {
       if ((options as any).__testHookBeforeCreateBrowser)
         await (options as any).__testHookBeforeCreateBrowser();
-      return FFBrowser.connect(transport, { slowMo: options.slowMo, logger: new RootLogger(options.logger), downloadsPath: '' });
+      return FFBrowser.connect(transport, { slowMo: options.slowMo, logger, downloadsPath: '' });
-    });
+    }, logger);
   }
 
   private _defaultArgs(options: BrowserArgOptions = {}, launchType: LaunchType, userDataDir: string, port: number): string[] {

src/server/webkit.ts

@@ -150,11 +150,12 @@ export class WebKit extends AbstractBrowserType<WKBrowser> {
   }
 
   async connect(options: ConnectOptions): Promise<WKBrowser> {
+    const logger = new RootLogger(options.logger);
     return await WebSocketTransport.connect(options.wsEndpoint, async transport => {
       if ((options as any).__testHookBeforeCreateBrowser)
         await (options as any).__testHookBeforeCreateBrowser();
-      return WKBrowser.connect(transport, { slowMo: options.slowMo, logger: new RootLogger(options.logger), downloadsPath: '' });
+      return WKBrowser.connect(transport, { slowMo: options.slowMo, logger, downloadsPath: '' });
-    });
+    }, logger);
   }
 
   _defaultArgs(options: BrowserArgOptions = {}, launchType: LaunchType, userDataDir: string, port: number): string[] {

src/transport.ts

@@ -17,7 +17,7 @@
 
 import * as WebSocket from 'ws';
 import { helper } from './helper';
-import { Log } from './logger';
+import { Log, InnerLogger } from './logger';
 
 export type ProtocolRequest = {
   id: number;
@@ -120,32 +120,40 @@ export class DeferWriteTransport implements ConnectionTransport {
 
 export class WebSocketTransport implements ConnectionTransport {
   _ws: WebSocket;
+  _logger?: InnerLogger;
 
   onmessage?: (message: ProtocolResponse) => void;
   onclose?: () => void;
 
   // 'onmessage' handler must be installed synchronously when 'onopen' callback is invoked to
   // avoid missing incoming messages.
-  static connect<T>(url: string, onopen: (transport: ConnectionTransport) => Promise<T> | T): Promise<T> {
+  static connect<T>(url: string, onopen: (transport: ConnectionTransport) => Promise<T> | T, logger?: InnerLogger): Promise<T> {
-    const transport = new WebSocketTransport(url);
+    logger && logger._log({ name: 'browser' }, `<ws connecting> ${url}`);
+    const transport = new WebSocketTransport(url, logger);
     return new Promise<T>((fulfill, reject) => {
       transport._ws.addEventListener('open', async () => {
+        logger && logger._log({ name: 'browser' }, `<ws connected> ${url}`);
         try {
           fulfill(await onopen(transport));
         } catch (e) {
+          logger && logger._log({ name: 'browser' }, `<ws disconnecting> ${url}`);
           try { transport._ws.close(); } catch (ignored) {}
           reject(e);
         }
       });
-      transport._ws.addEventListener('error', event => reject(new Error('WebSocket error: ' + event.message)));
+      transport._ws.addEventListener('error', event => {
+        logger && logger._log({ name: 'browser' }, `<ws connect error> ${url} ${event.message}`);
+        reject(new Error('WebSocket error: ' + event.message));
+      });
     });
   }
 
-  constructor(url: string) {
+  constructor(url: string, logger: InnerLogger | undefined) {
     this._ws = new WebSocket(url, [], {
       perMessageDeflate: false,
       maxPayload: 256 * 1024 * 1024, // 256Mb
     });
+    this._logger = logger;
     // The 'ws' module in node sometimes sends us multiple messages in a single task.
     // In Web, all IO callbacks (e.g. WebSocket callbacks)
     // are dispatched into separate tasks, so there's no need
@@ -160,6 +168,7 @@ export class WebSocketTransport implements ConnectionTransport {
     });
 
     this._ws.addEventListener('close', event => {
+      this._logger && this._logger._log({ name: 'browser' }, `<ws server disconnected> ${url}`);
       if (this.onclose)
         this.onclose.call(null);
     });
@@ -172,6 +181,7 @@ export class WebSocketTransport implements ConnectionTransport {
   }
 
   close() {
+    this._logger && this._logger._log({ name: 'browser' }, `<ws disconnecting> ${this._ws.url}`);
     this._ws.close();
   }
 }

test/fixtures.spec.js

@@ -25,6 +25,7 @@ async function testSignal(state, action, exitOnClose) {
     handleSIGTERM: true,
     handleSIGHUP: true,
     executablePath: state.browserType.executablePath(),
+    logger: undefined,
   });
   const res = spawn('node', [path.join(__dirname, 'fixtures', 'closeme.js'), path.join(state.playwrightPath, 'index-for-dev'), state.browserType.name(), JSON.stringify(options), exitOnClose ? 'true' : '']);
   let wsEndPointCallback;

test/test.config.js

@@ -18,6 +18,7 @@
 const fs = require('fs');
 const path = require('path');
 const rm = require('rimraf').sync;
+const utils = require('./utils');
 const {TestServer} = require('../utils/testserver/');
 const {Environment} = require('../utils/testrunner/Test');
 
@@ -44,10 +45,12 @@ serverEnvironment.beforeAll(async state => {
   state.httpsServer.CROSS_PROCESS_PREFIX = `https://127.0.0.1:${httpsPort}`;
   state.httpsServer.EMPTY_PAGE = `https://localhost:${httpsPort}/empty.html`;
 
+  state._extraLogger = utils.createTestLogger(valueFromEnv('DEBUGP', false), null, 'extra');
   state.defaultBrowserOptions = {
     handleSIGINT: false,
     slowMo: valueFromEnv('SLOW_MO', 0),
     headless: !!valueFromEnv('HEADLESS', true),
+    logger: state._extraLogger,
   };
   state.playwrightPath = playwrightPath;
 });
@@ -57,9 +60,13 @@ serverEnvironment.afterAll(async({server, httpsServer}) => {
     httpsServer.stop(),
   ]);
 });
-serverEnvironment.beforeEach(async({server, httpsServer}) => {
+serverEnvironment.beforeEach(async(state, testRun) => {
-  server.reset();
+  state.server.reset();
-  httpsServer.reset();
+  state.httpsServer.reset();
+  state._extraLogger.setTestRun(testRun);
+});
+serverEnvironment.afterEach(async(state) => {
+  state._extraLogger.setTestRun(null);
 });
 
 const customEnvironment = new Environment('Golden+CheckContexts');

test/test.js

@@ -17,6 +17,7 @@
 
 const fs = require('fs');
 const path = require('path');
+const utils = require('./utils');
 const TestRunner = require('../utils/testrunner/');
 const {Environment} = require('../utils/testrunner/Test');
 
@@ -120,17 +121,8 @@ function collect(browserNames) {
 
     const browserEnvironment = new Environment(browserName);
     browserEnvironment.beforeAll(async state => {
-      state._logger = null;
+      state._logger = utils.createTestLogger(config.dumpProtocolOnFailure);
-      state.browser = await state.browserType.launch({...launchOptions, logger: {
+      state.browser = await state.browserType.launch({...launchOptions, logger: state._logger});
-        isEnabled: (name, severity) => {
-          return name === 'browser' ||
-              (name === 'protocol' && config.dumpProtocolOnFailure);
-        },
-        log: (name, severity, message, args) => {
-          if (state._logger)
-            state._logger(name, severity, message);
-        }
-      }});
     });
     browserEnvironment.afterAll(async state => {
       await state.browser.close();
@@ -138,23 +130,10 @@ function collect(browserNames) {
       delete state._logger;
     });
     browserEnvironment.beforeEach(async(state, testRun) => {
-      state._logger = (name, severity, message) => {
+      state._logger.setTestRun(testRun);
-        if (name === 'browser') {
-          if (severity === 'warning')
-            testRun.log(`\x1b[31m[browser]\x1b[0m ${message}`)
-          else
-            testRun.log(`\x1b[33m[browser]\x1b[0m ${message}`)
-        } else if (name === 'protocol' && config.dumpProtocolOnFailure) {
-          testRun.log(`\x1b[32m[protocol]\x1b[0m ${message}`)
-        }
-      }
     });
     browserEnvironment.afterEach(async (state, testRun) => {
-      state._logger = null;
+      state._logger.setTestRun(null);
-      if (config.dumpProtocolOnFailure) {
-        if (testRun.ok())
-          testRun.output().splice(0);
-      }
     });
 
     const pageEnvironment = new Environment('Page');

test/utils.js

@@ -191,10 +191,37 @@ const utils = module.exports = {
     // To support isplaywrightready.
     platform = p;
   },
-};
 
-function valueFromEnv(name, defaultValue) {
+  createTestLogger(dumpProtocolOnFailure = true, testRun = null, prefix = '') {
-  if (!(name in process.env))
+    const colors = [31, 32, 33, 34, 35, 36, 37];
-    return defaultValue;
+    let colorIndex = 0;
-  return JSON.parse(process.env[name]);
+    for (let i = 0; i < prefix.length; i++)
-}
+      colorIndex += prefix.charCodeAt(i);
+    const color = colors[colorIndex % colors.length];
+    prefix = prefix ? `\x1b[${color}m[${prefix}]\x1b[0m ` : '';
+
+    const logger = {
+      isEnabled: (name, severity) => {
+        return name === 'browser' || (name === 'protocol' && dumpProtocolOnFailure);
+      },
+      log: (name, severity, message, args) => {
+        if (!testRun)
+          return;
+        if (name === 'browser') {
+          if (severity === 'warning')
+            testRun.log(`${prefix}\x1b[31m[browser]\x1b[0m ${message}`)
+          else
+            testRun.log(`${prefix}\x1b[33m[browser]\x1b[0m ${message}`)
+        } else if (name === 'protocol' && dumpProtocolOnFailure) {
+          testRun.log(`${prefix}\x1b[32m[protocol]\x1b[0m ${message}`)
+        }
+      },
+      setTestRun(tr) {
+        if (testRun && testRun.ok())
+          testRun.output().splice(0);
+        testRun = tr;
+      },
+    };
+    return logger;
+  },
+};