fix(launchServer): stream protocol logs into options.logger (#4403)

fix(launchServer): stream protocol logs into options.logger

This has regressed in v1.4.

src/browserServerImpl.ts

@@ -14,7 +14,7 @@
  * limitations under the License.
  */
 
-import { LaunchServerOptions } from './client/types';
+import { LaunchServerOptions, Logger } from './client/types';
 import { BrowserType } from './server/browserType';
 import * as ws from 'ws';
 import * as fs from 'fs';
@@ -32,6 +32,7 @@ import { SelectorsDispatcher } from './dispatchers/selectorsDispatcher';
 import { Selectors } from './server/selectors';
 import { BrowserContext, Video } from './server/browserContext';
 import { StreamDispatcher } from './dispatchers/streamDispatcher';
+import { ProtocolLogger } from './server/types';
 
 export class BrowserServerLauncherImpl implements BrowserServerLauncher {
   private _browserType: BrowserType;
@@ -46,7 +47,7 @@ export class BrowserServerLauncherImpl implements BrowserServerLauncher {
       ignoreDefaultArgs: Array.isArray(options.ignoreDefaultArgs) ? options.ignoreDefaultArgs : undefined,
       ignoreAllDefaultArgs: !!options.ignoreDefaultArgs && !Array.isArray(options.ignoreDefaultArgs),
       env: options.env ? envObjectToArray(options.env) : undefined,
-    });
+    }, toProtocolLogger(options.logger));
     return new BrowserServerImpl(browser, options.port);
   }
 }
@@ -192,3 +193,10 @@ class ConnectedBrowser extends BrowserDispatcher {
     });
   }
 }
+
+function toProtocolLogger(logger: Logger | undefined): ProtocolLogger | undefined {
+  return logger ? (direction: 'send' | 'receive', message: object) => {
+    if (logger.isEnabled('protocol', 'verbose'))
+      logger.log('protocol', 'verbose', (direction === 'send' ? 'SEND ► ' : '◀ RECV ') + JSON.stringify(message), [], {});
+  } : undefined;
+}

src/server/browser.ts

@@ -36,6 +36,7 @@ export type BrowserOptions = types.UIOptions & {
   persistent?: types.BrowserContextOptions,  // Undefined means no persistent context.
   browserProcess: BrowserProcess,
   proxy?: ProxySettings,
+  protocolLogger: types.ProtocolLogger,
 };
 
 export abstract class Browser extends EventEmitter {

src/server/browserType.ts

@@ -29,6 +29,7 @@ import * as types from './types';
 import { TimeoutSettings } from '../utils/timeoutSettings';
 import { validateHostRequirements } from './validateDependencies';
 import { isDebugMode } from '../utils/utils';
+import { helper } from './helper';
 
 const mkdirAsync = util.promisify(fs.mkdir);
 const mkdtempAsync = util.promisify(fs.mkdtemp);
@@ -57,12 +58,12 @@ export abstract class BrowserType {
     return this._name;
   }
 
-  async launch(options: types.LaunchOptions = {}): Promise<Browser> {
+  async launch(options: types.LaunchOptions, protocolLogger?: types.ProtocolLogger): Promise<Browser> {
     options = validateLaunchOptions(options);
     const controller = new ProgressController();
     controller.setLogName('browser');
     const browser = await controller.run(progress => {
-      return this._innerLaunch(progress, options, undefined).catch(e => { throw this._rewriteStartupError(e); });
+      return this._innerLaunch(progress, options, undefined, helper.debugProtocolLogger(protocolLogger)).catch(e => { throw this._rewriteStartupError(e); });
     }, TimeoutSettings.timeout(options));
     return browser;
   }
@@ -73,12 +74,12 @@ export abstract class BrowserType {
     const controller = new ProgressController();
     controller.setLogName('browser');
     const browser = await controller.run(progress => {
-      return this._innerLaunch(progress, options, persistent, userDataDir).catch(e => { throw this._rewriteStartupError(e); });
+      return this._innerLaunch(progress, options, persistent, helper.debugProtocolLogger(), userDataDir).catch(e => { throw this._rewriteStartupError(e); });
     }, TimeoutSettings.timeout(options));
     return browser._defaultContext!;
   }
 
-  async _innerLaunch(progress: Progress, options: types.LaunchOptions, persistent: types.BrowserContextOptions | undefined, userDataDir?: string): Promise<Browser> {
+  async _innerLaunch(progress: Progress, options: types.LaunchOptions, persistent: types.BrowserContextOptions | undefined, protocolLogger: types.ProtocolLogger, userDataDir?: string): Promise<Browser> {
     options.proxy = options.proxy ? normalizeProxySettings(options.proxy) : undefined;
     const { browserProcess, downloadsPath, transport } = await this._launchProcess(progress, options, !!persistent, userDataDir);
     if ((options as any).__testHookBeforeCreateBrowser)
@@ -91,6 +92,7 @@ export abstract class BrowserType {
       downloadsPath,
       browserProcess,
       proxy: options.proxy,
+      protocolLogger,
     };
     if (persistent)
       validateBrowserContextOptions(persistent, browserOptions);

src/server/chromium/crBrowser.ts

@@ -46,7 +46,7 @@ export class CRBrowser extends Browser {
   private _tracingClient: CRSession | undefined;
 
   static async connect(transport: ConnectionTransport, options: BrowserOptions, devtools?: CRDevTools): Promise<CRBrowser> {
-    const connection = new CRConnection(transport);
+    const connection = new CRConnection(transport, options.protocolLogger);
     const browser = new CRBrowser(connection, options);
     browser._devtools = devtools;
     const session = connection.rootSession;

src/server/chromium/crConnection.ts

@@ -21,6 +21,7 @@ import { Protocol } from './protocol';
 import { EventEmitter } from 'events';
 import { rewriteErrorMessage } from '../../utils/stackTrace';
 import { debugLogger } from '../../utils/debugLogger';
+import { ProtocolLogger } from '../types';
 
 export const ConnectionEvents = {
   Disconnected: Symbol('ConnectionEvents.Disconnected')
@@ -34,12 +35,14 @@ export class CRConnection extends EventEmitter {
   private _lastId = 0;
   private readonly _transport: ConnectionTransport;
   private readonly _sessions = new Map<string, CRSession>();
+  private readonly _protocolLogger: ProtocolLogger;
   readonly rootSession: CRSession;
   _closed = false;
 
-  constructor(transport: ConnectionTransport) {
+  constructor(transport: ConnectionTransport, protocolLogger: ProtocolLogger) {
     super();
     this._transport = transport;
+    this._protocolLogger = protocolLogger;
     this._transport.onmessage = this._onMessage.bind(this);
     this._transport.onclose = this._onClose.bind(this);
     this.rootSession = new CRSession(this, '', 'browser', '');
@@ -59,15 +62,13 @@ export class CRConnection extends EventEmitter {
     const message: ProtocolRequest = { id, method, params };
     if (sessionId)
       message.sessionId = sessionId;
-    if (debugLogger.isEnabled('protocol'))
+    this._protocolLogger('send', message);
-      debugLogger.log('protocol', 'SEND ► ' + JSON.stringify(message));
     this._transport.send(message);
     return id;
   }
 
   async _onMessage(message: ProtocolResponse) {
-    if (debugLogger.isEnabled('protocol'))
+    this._protocolLogger('receive', message);
-      debugLogger.log('protocol', '◀ RECV ' + JSON.stringify(message));
     if (message.id === kBrowserCloseMessageId)
       return;
     if (message.method === 'Target.attachedToTarget') {

src/server/clank/clank.ts

@@ -27,7 +27,7 @@ import { AndroidBrowser, AndroidClient, AndroidDevice } from './android';
 import { AdbBackend } from './backendAdb';
 
 export class Clank extends BrowserType {
-  async _innerLaunch(progress: Progress, options: types.LaunchOptions, persistent: types.BrowserContextOptions | undefined, userDataDir?: string): Promise<Browser> {
+  async _innerLaunch(progress: Progress, options: types.LaunchOptions, persistent: types.BrowserContextOptions | undefined, protocolLogger: types.ProtocolLogger, userDataDir?: string): Promise<Browser> {
     options.proxy = options.proxy ? normalizeProxySettings(options.proxy) : undefined;
     if ((options as any).__testHookBeforeCreateBrowser)
       await (options as any).__testHookBeforeCreateBrowser();
@@ -47,6 +47,7 @@ export class Clank extends BrowserType {
       downloadsPath: undefined,
       browserProcess: new ClankBrowserProcess(device, adbBrowser),
       proxy: options.proxy,
+      protocolLogger,
     };
     if (persistent)
       validateBrowserContextOptions(persistent, browserOptions);

src/server/electron/electron.ts

@@ -29,7 +29,7 @@ import type {BrowserWindow} from 'electron';
 import { Progress, ProgressController, runAbortableTask } from '../progress';
 import { EventEmitter } from 'events';
 import { helper } from '../helper';
-import { BrowserProcess } from '../browser';
+import { BrowserOptions, BrowserProcess } from '../browser';
 import * as childProcess from 'child_process';
 import * as readline from 'readline';
 
@@ -174,7 +174,7 @@ export class Electron  {
 
       const nodeMatch = await waitForLine(progress, launchedProcess, /^Debugger listening on (ws:\/\/.*)$/);
       const nodeTransport = await WebSocketTransport.connect(progress, nodeMatch[1]);
-      const nodeConnection = new CRConnection(nodeTransport);
+      const nodeConnection = new CRConnection(nodeTransport, helper.debugProtocolLogger());
 
       const chromeMatch = await waitForLine(progress, launchedProcess, /^DevTools listening on (ws:\/\/.*)$/);
       const chromeTransport = await WebSocketTransport.connect(progress, chromeMatch[1]);
@@ -184,7 +184,14 @@ export class Electron  {
         close: gracefullyClose,
         kill
       };
-      const browser = await CRBrowser.connect(chromeTransport, { name: 'electron', headful: true, persistent: { noDefaultViewport: true }, browserProcess });
+      const browserOptions: BrowserOptions = {
+        name: 'electron',
+        headful: true,
+        persistent: { noDefaultViewport: true },
+        browserProcess,
+        protocolLogger: helper.debugProtocolLogger(),
+      };
+      const browser = await CRBrowser.connect(chromeTransport, browserOptions);
       app = new ElectronApplication(browser, nodeConnection);
       await app._init();
       return app;

src/server/firefox/ffBrowser.ts

@@ -33,7 +33,7 @@ export class FFBrowser extends Browser {
   private _version = '';
 
   static async connect(transport: ConnectionTransport, options: BrowserOptions): Promise<FFBrowser> {
-    const connection = new FFConnection(transport);
+    const connection = new FFConnection(transport, options.protocolLogger);
     const browser = new FFBrowser(connection, options);
     const promises: Promise<any>[] = [
       connection.send('Browser.enable', { attachToDefaultContext: !!options.persistent }),

src/server/firefox/ffConnection.ts

@@ -21,6 +21,7 @@ import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../trans
 import { Protocol } from './protocol';
 import { rewriteErrorMessage } from '../../utils/stackTrace';
 import { debugLogger } from '../../utils/debugLogger';
+import { ProtocolLogger } from '../types';
 
 export const ConnectionEvents = {
   Disconnected: Symbol('Disconnected'),
@@ -34,6 +35,7 @@ export class FFConnection extends EventEmitter {
   private _lastId: number;
   private _callbacks: Map<number, {resolve: Function, reject: Function, error: Error, method: string}>;
   private _transport: ConnectionTransport;
+  private readonly _protocolLogger: ProtocolLogger;
   readonly _sessions: Map<string, FFSession>;
   _closed: boolean;
 
@@ -43,9 +45,10 @@ export class FFConnection extends EventEmitter {
   removeListener: <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;
   once: <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;
 
-  constructor(transport: ConnectionTransport) {
+  constructor(transport: ConnectionTransport, protocolLogger: ProtocolLogger) {
     super();
     this._transport = transport;
+    this._protocolLogger = protocolLogger;
     this._lastId = 0;
     this._callbacks = new Map();
 
@@ -77,14 +80,12 @@ export class FFConnection extends EventEmitter {
   }
 
   _rawSend(message: ProtocolRequest) {
-    if (debugLogger.isEnabled('protocol'))
+    this._protocolLogger('send', message);
-      debugLogger.log('protocol', 'SEND ► ' + JSON.stringify(message));
     this._transport.send(message);
   }
 
   async _onMessage(message: ProtocolResponse) {
-    if (debugLogger.isEnabled('protocol'))
+    this._protocolLogger('receive', message);
-      debugLogger.log('protocol', '◀ RECV ' + JSON.stringify(message));
     if (message.id === kBrowserCloseMessageId)
       return;
     if (message.sessionId) {

src/server/helper.ts

@@ -20,6 +20,7 @@ import * as removeFolder from 'rimraf';
 import * as util from 'util';
 import * as types from './types';
 import { Progress } from './progress';
+import { debugLogger } from '../utils/debugLogger';
 
 const removeFolderAsync = util.promisify(removeFolder);
 
@@ -110,6 +111,15 @@ class Helper {
   static millisToRoundishMillis(value: number): number {
     return ((value * 1000) | 0) / 1000;
   }
+
+  static debugProtocolLogger(protocolLogger?: types.ProtocolLogger): types.ProtocolLogger {
+    return (direction: 'send' | 'receive', message: object) => {
+      if (protocolLogger)
+        protocolLogger(direction, message);
+      if (debugLogger.isEnabled('protocol'))
+        debugLogger.log('protocol', (direction === 'send' ? 'SEND ► ' : '◀ RECV ') + JSON.stringify(message));
+    };
+  }
 }
 
 export const helper = Helper;

src/server/types.ts

@@ -275,6 +275,8 @@ export type LaunchOptions = LaunchOptionsBase & UIOptions & {
 };
 export type LaunchPersistentOptions = LaunchOptionsBase & BrowserContextOptions;
 
+export type ProtocolLogger = (direction: 'send' | 'receive', message: object) => void;
+
 export type SerializedAXNode = {
   role: string,
   name: string,

src/server/webkit/wkBrowser.ts

@@ -52,7 +52,7 @@ export class WKBrowser extends Browser {
 
   constructor(transport: ConnectionTransport, options: BrowserOptions) {
     super(options);
-    this._connection = new WKConnection(transport, this._onDisconnect.bind(this));
+    this._connection = new WKConnection(transport, this._onDisconnect.bind(this), options.protocolLogger);
     this._browserSession = this._connection.browserSession;
     this._eventListeners = [
       helper.addEventListener(this._browserSession, 'Playwright.pageProxyCreated', this._onPageProxyCreated.bind(this)),

src/server/webkit/wkConnection.ts

@@ -21,6 +21,7 @@ import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../trans
 import { Protocol } from './protocol';
 import { rewriteErrorMessage } from '../../utils/stackTrace';
 import { debugLogger } from '../../utils/debugLogger';
+import { ProtocolLogger } from '../types';
 
 // WKPlaywright uses this special id to issue Browser.close command which we
 // should ignore.
@@ -34,15 +35,17 @@ export type PageProxyMessageReceivedPayload = { pageProxyId: string, message: an
 export class WKConnection {
   private readonly _transport: ConnectionTransport;
   private readonly _onDisconnect: () => void;
+  private readonly _protocolLogger: ProtocolLogger;
   private _lastId = 0;
   private _closed = false;
   readonly browserSession: WKSession;
 
-  constructor(transport: ConnectionTransport, onDisconnect: () => void) {
+  constructor(transport: ConnectionTransport, onDisconnect: () => void, protocolLogger: ProtocolLogger) {
     this._transport = transport;
     this._transport.onmessage = this._dispatchMessage.bind(this);
     this._transport.onclose = this._onClose.bind(this);
     this._onDisconnect = onDisconnect;
+    this._protocolLogger = protocolLogger;
     this.browserSession = new WKSession(this, '', 'Browser has been closed.', (message: any) => {
       this.rawSend(message);
     });
@@ -53,14 +56,12 @@ export class WKConnection {
   }
 
   rawSend(message: ProtocolRequest) {
-    if (debugLogger.isEnabled('protocol'))
+    this._protocolLogger('send', message);
-      debugLogger.log('protocol', 'SEND ► ' + JSON.stringify(message));
     this._transport.send(message);
   }
 
   private _dispatchMessage(message: ProtocolResponse) {
-    if (debugLogger.isEnabled('protocol'))
+    this._protocolLogger('receive', message);
-      debugLogger.log('protocol', '◀ RECV ' + JSON.stringify(message));
     if (message.id === kBrowserCloseMessageId)
       return;
     if (message.pageProxyId) {

test/browsertype-launch-server.spec.ts

@@ -62,4 +62,22 @@ describe('lauch server', (suite, { wire }) => {
     expect(result['exitCode']).toBe(0);
     expect(result['signal']).toBe(null);
   });
+
+  it('should log protocol', async ({browserType, browserOptions}) => {
+    const logs: string[] = [];
+    const logger = {
+      isEnabled(name: string) {
+        return true;
+      },
+      log(name: string, severity: string, message: string) {
+        logs.push(`${name}:${severity}:${message}`);
+      }
+    };
+
+    const browserServer = await browserType.launchServer({ ...browserOptions, logger });
+    await browserServer.close();
+
+    expect(logs.some(log => log.startsWith('protocol:verbose:SEND ►'))).toBe(true);
+    expect(logs.some(log => log.startsWith('protocol:verbose:◀ RECV'))).toBe(true);
+  });
 });