feat(errors): append recent browser logs when browser disconnects (#4625)

Author: dgozman

src/server/browser.ts

@@ -21,6 +21,7 @@ import { EventEmitter } from 'events';
 import { Download } from './download';
 import { ProxySettings } from './types';
 import { ChildProcess } from 'child_process';
+import { RecentLogsCollector } from '../utils/debugLogger';
 
 export interface BrowserProcess {
   onclose: ((exitCode: number | null, signal: string | null) => void) | undefined;
@@ -37,6 +38,7 @@ export type BrowserOptions = types.UIOptions & {
   browserProcess: BrowserProcess,
   proxy?: ProxySettings,
   protocolLogger: types.ProtocolLogger,
+  browserLogsCollector: RecentLogsCollector,
 };
 
 export abstract class Browser extends EventEmitter {

src/server/browserType.ts

@@ -30,6 +30,7 @@ import { TimeoutSettings } from '../utils/timeoutSettings';
 import { validateHostRequirements } from './validateDependencies';
 import { isDebugMode } from '../utils/utils';
 import { helper } from './helper';
+import { RecentLogsCollector } from '../utils/debugLogger';
 
 const mkdirAsync = util.promisify(fs.mkdir);
 const mkdtempAsync = util.promisify(fs.mkdtemp);
@@ -81,7 +82,8 @@ export abstract class BrowserType {
 
   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);
+    const browserLogsCollector = new RecentLogsCollector();
+    const { browserProcess, downloadsPath, transport } = await this._launchProcess(progress, options, !!persistent, browserLogsCollector, userDataDir);
     if ((options as any).__testHookBeforeCreateBrowser)
       await (options as any).__testHookBeforeCreateBrowser();
     const browserOptions: BrowserOptions = {
@@ -93,6 +95,7 @@ export abstract class BrowserType {
       browserProcess,
       proxy: options.proxy,
       protocolLogger,
+      browserLogsCollector,
     };
     if (persistent)
       validateBrowserContextOptions(persistent, browserOptions);
@@ -104,7 +107,7 @@ export abstract class BrowserType {
     return browser;
   }
 
-  private async _launchProcess(progress: Progress, options: types.LaunchOptions, isPersistent: boolean, userDataDir?: string): Promise<{ browserProcess: BrowserProcess, downloadsPath: string, transport: ConnectionTransport }> {
+  private async _launchProcess(progress: Progress, options: types.LaunchOptions, isPersistent: boolean, browserLogsCollector: RecentLogsCollector, userDataDir?: string): Promise<{ browserProcess: BrowserProcess, downloadsPath: string, transport: ConnectionTransport }> {
     const {
       ignoreDefaultArgs,
       ignoreAllDefaultArgs,
@@ -172,7 +175,10 @@ export abstract class BrowserType {
       handleSIGINT,
       handleSIGTERM,
       handleSIGHUP,
-      progress,
+      log: (message: string) => {
+        progress.log(message);
+        browserLogsCollector.log(message);
+      },
       stdio: 'pipe',
       tempDirectories,
       attemptToGracefullyClose: async () => {

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, options.protocolLogger);
+    const connection = new CRConnection(transport, options.protocolLogger, options.browserLogsCollector);
     const browser = new CRBrowser(connection, options);
     browser._devtools = devtools;
     const session = connection.rootSession;

src/server/chromium/crConnection.ts

@@ -20,8 +20,9 @@ import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../trans
 import { Protocol } from './protocol';
 import { EventEmitter } from 'events';
 import { rewriteErrorMessage } from '../../utils/stackTrace';
-import { debugLogger } from '../../utils/debugLogger';
+import { debugLogger, RecentLogsCollector } from '../../utils/debugLogger';
 import { ProtocolLogger } from '../types';
+import { helper } from '../helper';
 
 export const ConnectionEvents = {
   Disconnected: Symbol('ConnectionEvents.Disconnected')
@@ -36,13 +37,15 @@ export class CRConnection extends EventEmitter {
   private readonly _transport: ConnectionTransport;
   private readonly _sessions = new Map<string, CRSession>();
   private readonly _protocolLogger: ProtocolLogger;
+  private readonly _browserLogsCollector: RecentLogsCollector;
   readonly rootSession: CRSession;
   _closed = false;
 
-  constructor(transport: ConnectionTransport, protocolLogger: ProtocolLogger) {
+  constructor(transport: ConnectionTransport, protocolLogger: ProtocolLogger, browserLogsCollector: RecentLogsCollector) {
     super();
     this._transport = transport;
     this._protocolLogger = protocolLogger;
+    this._browserLogsCollector = browserLogsCollector;
     this._transport.onmessage = this._onMessage.bind(this);
     this._transport.onclose = this._onClose.bind(this);
     this.rootSession = new CRSession(this, '', 'browser', '');
@@ -79,7 +82,7 @@ export class CRConnection extends EventEmitter {
     } else if (message.method === 'Target.detachedFromTarget') {
       const session = this._sessions.get(message.params.sessionId);
       if (session) {
-        session._onClosed();
+        session._onClosed(undefined);
         this._sessions.delete(message.params.sessionId);
       }
     }
@@ -92,8 +95,9 @@ export class CRConnection extends EventEmitter {
     this._closed = true;
     this._transport.onmessage = undefined;
     this._transport.onclose = undefined;
+    const browserDisconnectedLogs = helper.formatBrowserLogs(this._browserLogsCollector.recentLogs());
     for (const session of this._sessions.values())
-      session._onClosed();
+      session._onClosed(browserDisconnectedLogs);
     this._sessions.clear();
     Promise.resolve().then(() => this.emit(ConnectionEvents.Disconnected));
   }
@@ -126,6 +130,7 @@ export class CRSession extends EventEmitter {
   private readonly _sessionId: string;
   private readonly _rootSessionId: string;
   private _crashed: boolean = false;
+  private _browserDisconnectedLogs: string | undefined;
   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;
   addListener: <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;
   off: <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;
@@ -156,6 +161,8 @@ export class CRSession extends EventEmitter {
   ): Promise<Protocol.CommandReturnValues[T]> {
     if (this._crashed)
       throw new Error('Target crashed');
+    if (this._browserDisconnectedLogs !== undefined)
+      throw new Error(`Protocol error (${method}): Browser closed.` + this._browserDisconnectedLogs);
     if (!this._connection)
       throw new Error(`Protocol error (${method}): Session closed. Most likely the ${this._targetType} has been closed.`);
     const id = this._connection._rawSend(this._sessionId, method, params);
@@ -195,9 +202,11 @@ export class CRSession extends EventEmitter {
     await rootSession.send('Target.detachFromTarget', { sessionId: this._sessionId });
   }
 
-  _onClosed() {
+  _onClosed(browserDisconnectedLogs: string | undefined) {
+    this._browserDisconnectedLogs = browserDisconnectedLogs;
+    const errorMessage = browserDisconnectedLogs !== undefined ? 'Browser closed.' + browserDisconnectedLogs : 'Target closed.';
     for (const callback of this._callbacks.values())
-      callback.reject(rewriteErrorMessage(callback.error, `Protocol error (${callback.method}): Target closed.`));
+      callback.reject(rewriteErrorMessage(callback.error, `Protocol error (${callback.method}): ` + errorMessage));
     this._callbacks.clear();
     this._connection = null;
     Promise.resolve().then(() => this.emit(CRSessionEvents.Disconnected));

src/server/chromium/videoRecorder.ts

@@ -65,7 +65,7 @@ export class VideoRecorder {
       executablePath,
       args,
       stdio: 'stdin',
-      progress,
+      log: (message: string) => progress.log(message),
       tempDirectories: [],
       attemptToGracefullyClose: async () => {
         progress.log('Closing stdin...');

src/server/clank/clank.ts

@@ -25,6 +25,7 @@ import { Env } from '../processLauncher';
 import { CRBrowser } from '../chromium/crBrowser';
 import { AndroidBrowser, AndroidClient, AndroidDevice } from './android';
 import { AdbBackend } from './backendAdb';
+import { RecentLogsCollector } from '../../utils/debugLogger';
 
 export class Clank extends BrowserType {
   async _innerLaunch(progress: Progress, options: types.LaunchOptions, persistent: types.BrowserContextOptions | undefined, protocolLogger: types.ProtocolLogger, userDataDir?: string): Promise<Browser> {
@@ -48,6 +49,7 @@ export class Clank extends BrowserType {
       browserProcess: new ClankBrowserProcess(device, adbBrowser),
       proxy: options.proxy,
       protocolLogger,
+      browserLogsCollector: new RecentLogsCollector(),
     };
     if (persistent)
       validateBrowserContextOptions(persistent, browserOptions);

src/server/electron/electron.ts

@@ -32,6 +32,7 @@ import { helper } from '../helper';
 import { BrowserOptions, BrowserProcess } from '../browser';
 import * as childProcess from 'child_process';
 import * as readline from 'readline';
+import { RecentLogsCollector } from '../../utils/debugLogger';
 
 export type ElectronLaunchOptionsBase = {
   args?: string[],
@@ -157,14 +158,18 @@ export class Electron  {
           electronArguments.push('--no-sandbox');
       }
 
+      const browserLogsCollector = new RecentLogsCollector();
       const { launchedProcess, gracefullyClose, kill } = await launchProcess({
         executablePath,
         args: electronArguments,
         env: options.env ? envArrayToObject(options.env) : process.env,
         handleSIGINT,
         handleSIGTERM,
         handleSIGHUP,
-        progress,
+        log: (message: string) => {
+          progress.log(message);
+          browserLogsCollector.log(message);
+        },
         stdio: 'pipe',
         cwd: options.cwd,
         tempDirectories: [],
@@ -174,7 +179,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, helper.debugProtocolLogger());
+      const nodeConnection = new CRConnection(nodeTransport, helper.debugProtocolLogger(), browserLogsCollector);
 
       const chromeMatch = await waitForLine(progress, launchedProcess, /^DevTools listening on (ws:\/\/.*)$/);
       const chromeTransport = await WebSocketTransport.connect(progress, chromeMatch[1]);
@@ -190,6 +195,7 @@ export class Electron  {
         persistent: { noDefaultViewport: true },
         browserProcess,
         protocolLogger: helper.debugProtocolLogger(),
+        browserLogsCollector,
       };
       const browser = await CRBrowser.connect(chromeTransport, browserOptions);
       app = new ElectronApplication(browser, nodeConnection);

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, options.protocolLogger);
+    const connection = new FFConnection(transport, options.protocolLogger, options.browserLogsCollector);
     const browser = new FFBrowser(connection, options);
     const promises: Promise<any>[] = [
       connection.send('Browser.enable', { attachToDefaultContext: !!options.persistent }),

src/server/firefox/ffConnection.ts

@@ -20,8 +20,9 @@ import { assert } from '../../utils/utils';
 import { ConnectionTransport, ProtocolRequest, ProtocolResponse } from '../transport';
 import { Protocol } from './protocol';
 import { rewriteErrorMessage } from '../../utils/stackTrace';
-import { debugLogger } from '../../utils/debugLogger';
+import { debugLogger, RecentLogsCollector } from '../../utils/debugLogger';
 import { ProtocolLogger } from '../types';
+import { helper } from '../helper';
 
 export const ConnectionEvents = {
   Disconnected: Symbol('Disconnected'),
@@ -36,6 +37,7 @@ export class FFConnection extends EventEmitter {
   private _callbacks: Map<number, {resolve: Function, reject: Function, error: Error, method: string}>;
   private _transport: ConnectionTransport;
   private readonly _protocolLogger: ProtocolLogger;
+  private readonly _browserLogsCollector: RecentLogsCollector;
   readonly _sessions: Map<string, FFSession>;
   _closed: boolean;
 
@@ -45,10 +47,11 @@ 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, protocolLogger: ProtocolLogger) {
+  constructor(transport: ConnectionTransport, protocolLogger: ProtocolLogger, browserLogsCollector: RecentLogsCollector) {
     super();
     this._transport = transport;
     this._protocolLogger = protocolLogger;
+    this._browserLogsCollector = browserLogsCollector;
     this._lastId = 0;
     this._callbacks = new Map();
 
@@ -68,6 +71,7 @@ export class FFConnection extends EventEmitter {
     method: T,
     params?: Protocol.CommandParameters[T]
   ): Promise<Protocol.CommandReturnValues[T]> {
+    this._checkClosed(method);
     const id = this.nextMessageId();
     this._rawSend({id, method, params});
     return new Promise((resolve, reject) => {
@@ -79,6 +83,11 @@ export class FFConnection extends EventEmitter {
     return ++this._lastId;
   }
 
+  _checkClosed(method: string) {
+    if (this._closed)
+      throw new Error(`Protocol error (${method}): Browser closed.` + helper.formatBrowserLogs(this._browserLogsCollector.recentLogs()));
+  }
+
   _rawSend(message: ProtocolRequest) {
     this._protocolLogger('send', message);
     this._transport.send(message);
@@ -111,12 +120,13 @@ export class FFConnection extends EventEmitter {
     this._closed = true;
     this._transport.onmessage = undefined;
     this._transport.onclose = undefined;
-    for (const callback of this._callbacks.values())
-      callback.reject(rewriteErrorMessage(callback.error, `Protocol error (${callback.method}): Target closed.`));
-    this._callbacks.clear();
+    const formattedBrowserLogs = helper.formatBrowserLogs(this._browserLogsCollector.recentLogs());
     for (const session of this._sessions.values())
-      session.dispose();
+      session.dispose(formattedBrowserLogs);
     this._sessions.clear();
+    for (const callback of this._callbacks.values())
+      callback.reject(rewriteErrorMessage(callback.error, `Protocol error (${callback.method}): Browser closed.` + formattedBrowserLogs));
+    this._callbacks.clear();
     Promise.resolve().then(() => this.emit(ConnectionEvents.Disconnected));
   }
 
@@ -175,6 +185,7 @@ export class FFSession extends EventEmitter {
   ): Promise<Protocol.CommandReturnValues[T]> {
     if (this._crashed)
       throw new Error('Page crashed');
+    this._connection._checkClosed(method);
     if (this._disposed)
       throw new Error(`Protocol error (${method}): Session closed. Most likely the ${this._targetType} has been closed.`);
     const id = this._connection.nextMessageId();
@@ -202,9 +213,9 @@ export class FFSession extends EventEmitter {
     }
   }
 
-  dispose() {
+  dispose(formattedBrowserLogs?: string) {
     for (const callback of this._callbacks.values())
-      callback.reject(rewriteErrorMessage(callback.error, `Protocol error (${callback.method}): Target closed.`));
+      callback.reject(rewriteErrorMessage(callback.error, `Protocol error (${callback.method}): Target closed.` + formattedBrowserLogs));
     this._callbacks.clear();
     this._disposed = true;
     this._connection._sessions.delete(this._sessionId);

src/server/helper.ts

@@ -120,6 +120,12 @@ class Helper {
         debugLogger.log('protocol', (direction === 'send' ? 'SEND ► ' : '◀ RECV ') + JSON.stringify(message));
     };
   }
+
+  static formatBrowserLogs(logs: string[]) {
+    if (!logs.length)
+      return '';
+    return '\n' + '='.repeat(20) + ' Browser output: ' + '='.repeat(20) + '\n' + logs.join('\n');
+  }
 }
 
 export const helper = Helper;