chore: print the launch error message to console (#2304)

src/logger.ts

@@ -41,24 +41,32 @@ export function logError(logger: InnerLogger): (error: Error) => void {
 }
 
 export class RootLogger implements InnerLogger {
-  private _userSink: Logger | undefined;
-  private _debugSink: DebugLoggerSink;
+  private _logger = new MultiplexingLogger();
 
   constructor(userSink: Logger | undefined) {
-    this._userSink = userSink;
-    this._debugSink = new DebugLoggerSink();
+    if (userSink)
+      this._logger.add('user', userSink);
+    this._logger.add('debug', new DebugLogger());
   }
 
   _isLogEnabled(log: Log): boolean {
-    return (this._userSink && this._userSink.isEnabled(log.name, log.severity || 'info')) ||
-        this._debugSink.isEnabled(log.name, log.severity || 'info');
+    return this._logger.isEnabled(log.name, log.severity || 'info');
   }
 
   _log(log: Log, message: string | Error, ...args: any[]) {
-    if (this._userSink && this._userSink.isEnabled(log.name, log.severity || 'info'))
-      this._userSink.log(log.name, log.severity || 'info', message, args, log.color ? { color: log.color } : {});
-    if (this._debugSink.isEnabled(log.name, log.severity || 'info'))
-      this._debugSink.log(log.name, log.severity || 'info', message, args, log.color ? { color: log.color } : {});
+    if (this._logger.isEnabled(log.name, log.severity || 'info'))
+      this._logger.log(log.name, log.severity || 'info', message, args, log.color ? { color: log.color } : {});
+  }
+
+  startLaunchRecording() {
+    this._logger.add(`launch`, new RecordingLogger('browser'));
+  }
+
+  stopLaunchRecording(): string {
+    const logger = this._logger.remove(`launch`) as RecordingLogger;
+    if (logger)
+      return logger.recording();
+    return '';
   }
 }
 
@@ -72,7 +80,55 @@ const colorMap = new Map<string, number>([
   ['reset', 0],
 ]);
 
-class DebugLoggerSink implements Logger {
+class MultiplexingLogger implements Logger {
+  private _loggers = new Map<string, Logger>();
+
+  add(id: string, logger: Logger) {
+    this._loggers.set(id, logger);
+  }
+
+  remove(id: string): Logger | undefined {
+    const logger = this._loggers.get(id);
+    this._loggers.delete(id);
+    return logger;
+  }
+
+  isEnabled(name: string, severity: LoggerSeverity): boolean {
+    for (const logger of this._loggers.values()) {
+      if (logger.isEnabled(name, severity))
+        return true;
+    }
+    return false;
+  }
+
+  log(name: string, severity: LoggerSeverity, message: string | Error, args: any[], hints: { color?: string }) {
+    for (const logger of this._loggers.values())
+      logger.log(name, severity, message, args, hints);
+  }
+}
+
+export class RecordingLogger implements Logger {
+  private _prefix: string;
+  private _recording: string[] = [];
+
+  constructor(prefix: string) {
+    this._prefix = prefix;
+  }
+
+  isEnabled(name: string, severity: LoggerSeverity): boolean {
+    return name.startsWith(this._prefix);
+  }
+
+  log(name: string, severity: LoggerSeverity, message: string | Error, args: any[], hints: { color?: string }) {
+    this._recording.push(String(message));
+  }
+
+  recording(): string {
+    return this._recording.join('\n');
+  }
+}
+
+class DebugLogger implements Logger {
   private _debuggers = new Map<string, debug.IDebugger>();
 
   isEnabled(name: string, severity: LoggerSeverity): boolean {

src/server/browserServer.ts

@@ -17,6 +17,9 @@
 import { ChildProcess, execSync } from 'child_process';
 import { EventEmitter } from 'events';
 import { helper } from '../helper';
+import { RootLogger } from '../logger';
+import { TimeoutSettings } from '../timeoutSettings';
+import { LaunchOptionsBase } from './browserType';
 
 export class WebSocketWrapper {
   readonly wsEndpoint: string;
@@ -48,60 +51,82 @@ export class WebSocketWrapper {
 }
 
 export class BrowserServer extends EventEmitter {
-  private _process: ChildProcess;
-  private _gracefullyClose: () => Promise<void>;
-  private _webSocketWrapper: WebSocketWrapper | null;
+  private _process: ChildProcess | undefined;
+  private _gracefullyClose: (() => Promise<void>) | undefined;
+  private _webSocketWrapper: WebSocketWrapper | null = null;
+  private _launchOptions: LaunchOptionsBase;
+  readonly _logger: RootLogger;
+  readonly _launchDeadline: number;
 
-  constructor(process: ChildProcess, gracefullyClose: () => Promise<void>, webSocketWrapper: WebSocketWrapper | null) {
+  constructor(options: LaunchOptionsBase) {
     super();
+    this._launchOptions = options;
+    this._logger = new RootLogger(options.logger);
+    this._launchDeadline = TimeoutSettings.computeDeadline(typeof options.timeout === 'number' ? options.timeout : 30000);
+  }
+
+  _initialize(process: ChildProcess, gracefullyClose: () => Promise<void>, webSocketWrapper: WebSocketWrapper | null) {
     this._process = process;
     this._gracefullyClose = gracefullyClose;
     this._webSocketWrapper = webSocketWrapper;
   }
 
+  _isInitialized(): boolean {
+    return !!this._process;
+  }
+
   process(): ChildProcess {
-    return this._process;
+    return this._process!;
   }
 
   wsEndpoint(): string {
     return this._webSocketWrapper ? this._webSocketWrapper.wsEndpoint : '';
   }
 
   kill() {
-    if (this._process.pid && !this._process.killed) {
+    if (this._process!.pid && !this._process!.killed) {
       try {
         if (process.platform === 'win32')
-          execSync(`taskkill /pid ${this._process.pid} /T /F`);
+          execSync(`taskkill /pid ${this._process!.pid} /T /F`);
         else
-          process.kill(-this._process.pid, 'SIGKILL');
+          process.kill(-this._process!.pid, 'SIGKILL');
       } catch (e) {
         // the process might have already stopped
       }
     }
   }
 
   async close(): Promise<void> {
-    await this._gracefullyClose();
+    await this._gracefullyClose!();
   }
 
   async _checkLeaks(): Promise<void> {
     if (this._webSocketWrapper)
       await this._webSocketWrapper.checkLeaks();
   }
 
-  async _initializeOrClose<T>(deadline: number, init: () => Promise<T>): Promise<T> {
+  async _initializeOrClose<T>(init: () => Promise<T>): Promise<T> {
     try {
-      const result = await helper.waitWithDeadline(init(), 'the browser to launch', deadline, 'pw:browser*');
+      let promise: Promise<T>;
+      if ((this._launchOptions as any).__testHookBeforeCreateBrowser)
+        promise = (this._launchOptions as any).__testHookBeforeCreateBrowser().then(init);
+      else
+        promise = init();
+      const result = await helper.waitWithDeadline(promise, 'the browser to launch', this._launchDeadline, 'pw:browser*');
+      this._logger.stopLaunchRecording();
       return result;
     } catch (e) {
-      await this._closeOrKill(deadline);
+      e.message += '\n=============== Process output during launch: ===============\n' +
+          this._logger.stopLaunchRecording() +
+          '\n=============================================================';
+      await this._closeOrKill();
       throw e;
     }
   }
 
-  async _closeOrKill(deadline: number): Promise<void> {
+  private async _closeOrKill(): Promise<void> {
     try {
-      await helper.waitWithDeadline(this.close(), '', deadline, ''); // The error message is ignored.
+      await helper.waitWithDeadline(this.close(), '', this._launchDeadline, ''); // The error message is ignored.
     } catch (ignored) {
       this.kill();
     }

src/server/browserType.ts

@@ -25,7 +25,7 @@ export type BrowserArgOptions = {
   devtools?: boolean,
 };
 
-type LaunchOptionsBase = BrowserArgOptions & {
+export type LaunchOptionsBase = BrowserArgOptions & {
   executablePath?: string,
   ignoreDefaultArgs?: boolean | string[],
   handleSIGINT?: boolean,

src/server/chromium.ts

@@ -19,7 +19,7 @@ import * as fs from 'fs';
 import * as os from 'os';
 import * as path from 'path';
 import * as util from 'util';
-import { helper, assert, isDebugMode } from '../helper';
+import { helper, assert, isDebugMode, debugAssert } from '../helper';
 import { CRBrowser } from '../chromium/crBrowser';
 import * as ws from 'ws';
 import { launchProcess } from './processLauncher';
@@ -33,7 +33,6 @@ import { ConnectionTransport, ProtocolRequest, WebSocketTransport } from '../tra
 import { BrowserContext } from '../browserContext';
 import { InnerLogger, logError, RootLogger } from '../logger';
 import { BrowserDescriptor } from '../install/browserPaths';
-import { TimeoutSettings } from '../timeoutSettings';
 import { CRDevTools } from '../chromium/crDevTools';
 
 export class Chromium extends AbstractBrowserType<CRBrowser> {
@@ -51,12 +50,9 @@ export class Chromium extends AbstractBrowserType<CRBrowser> {
 
   async launch(options: LaunchOptions = {}): Promise<CRBrowser> {
     assert(!(options as any).userDataDir, 'userDataDir option is not supported in `browserType.launch`. Use `browserType.launchPersistentContext` instead');
-    const { timeout = 30000 } = options;
-    const deadline = TimeoutSettings.computeDeadline(timeout);
-    const { browserServer, transport, downloadsPath, logger } = await this._launchServer(options, 'local');
-    return await browserServer._initializeOrClose(deadline, async () => {
-      if ((options as any).__testHookBeforeCreateBrowser)
-        await (options as any).__testHookBeforeCreateBrowser();
+    const browserServer = new BrowserServer(options);
+    const { transport, downloadsPath } = await this._launchServer(options, 'local', browserServer);
+    return await browserServer._initializeOrClose(async () => {
       let devtools = this._devtools;
       if ((options as any).__testHookForDevTools) {
         devtools = this._createDevTools();
@@ -65,28 +61,27 @@ export class Chromium extends AbstractBrowserType<CRBrowser> {
       return await CRBrowser.connect(transport!, {
         slowMo: options.slowMo,
         headful: !processBrowserArgOptions(options).headless,
-        logger,
+        logger: browserServer._logger,
         downloadsPath,
         ownedServer: browserServer,
       }, devtools);
     });
   }
 
   async launchServer(options: LaunchServerOptions = {}): Promise<BrowserServer> {
-    return (await this._launchServer(options, 'server')).browserServer;
+    const browserServer = new BrowserServer(options);
+    await this._launchServer(options, 'server', browserServer);
+    return browserServer;
   }
 
   async launchPersistentContext(userDataDir: string, options: LaunchOptions = {}): Promise<BrowserContext> {
-    const { timeout = 30000 } = options;
-    const deadline = TimeoutSettings.computeDeadline(timeout);
-    const { transport, browserServer, downloadsPath, logger } = await this._launchServer(options, 'persistent', userDataDir);
-    return await browserServer._initializeOrClose(deadline, async () => {
-      if ((options as any).__testHookBeforeCreateBrowser)
-        await (options as any).__testHookBeforeCreateBrowser();
+    const browserServer = new BrowserServer(options);
+    const { transport, downloadsPath } = await this._launchServer(options, 'persistent', browserServer, userDataDir);
+    return await browserServer._initializeOrClose(async () => {
       const browser = await CRBrowser.connect(transport!, {
         slowMo: options.slowMo,
         persistent: true,
-        logger,
+        logger: browserServer._logger,
         downloadsPath,
         headful: !processBrowserArgOptions(options).headless,
         ownedServer: browserServer
@@ -98,7 +93,7 @@ export class Chromium extends AbstractBrowserType<CRBrowser> {
     });
   }
 
-  private async _launchServer(options: LaunchServerOptions, launchType: LaunchType, userDataDir?: string): Promise<{ browserServer: BrowserServer, transport?: ConnectionTransport, downloadsPath: string, logger: InnerLogger }> {
+  private async _launchServer(options: LaunchServerOptions, launchType: LaunchType, browserServer: BrowserServer, userDataDir?: string): Promise<{ transport?: ConnectionTransport, downloadsPath: string }> {
     const {
       ignoreDefaultArgs = false,
       args = [],
@@ -110,7 +105,7 @@ export class Chromium extends AbstractBrowserType<CRBrowser> {
       port = 0,
     } = options;
     assert(!port || launchType === 'server', 'Cannot specify a port without launching as a server.');
-    const logger = new RootLogger(options.logger);
+    const logger = browserServer._logger;
 
     let temporaryUserDataDir: string | null = null;
     if (!userDataDir) {
@@ -136,7 +131,6 @@ export class Chromium extends AbstractBrowserType<CRBrowser> {
     // Note: it is important to define these variables before launchProcess, so that we don't get
     // "Cannot access 'browserServer' before initialization" if something went wrong.
     let transport: PipeTransport | undefined = undefined;
-    let browserServer: BrowserServer | undefined = undefined;
     const { launchedProcess, gracefullyClose, downloadsPath } = await launchProcess({
       executablePath: chromeExecutable,
       args: chromeArguments,
@@ -148,7 +142,7 @@ export class Chromium extends AbstractBrowserType<CRBrowser> {
       pipe: true,
       tempDir: temporaryUserDataDir || undefined,
       attemptToGracefullyClose: async () => {
-        assert(browserServer);
+        debugAssert(browserServer._isInitialized());
         // We try to gracefully close to prevent crash reporting and core dumps.
         // Note that it's fine to reuse the pipe transport, since
         // our connection ignores kBrowserCloseMessageId.
@@ -157,15 +151,14 @@ export class Chromium extends AbstractBrowserType<CRBrowser> {
         t.send(message);
       },
       onkill: (exitCode, signal) => {
-        if (browserServer)
-          browserServer.emit(Events.BrowserServer.Close, exitCode, signal);
+        browserServer.emit(Events.BrowserServer.Close, exitCode, signal);
       },
     });
 
     const stdio = launchedProcess.stdio as unknown as [NodeJS.ReadableStream, NodeJS.WritableStream, NodeJS.WritableStream, NodeJS.WritableStream, NodeJS.ReadableStream];
     transport = new PipeTransport(stdio[3], stdio[4], logger);
-    browserServer = new BrowserServer(launchedProcess, gracefullyClose, launchType === 'server' ? wrapTransportWithWebSocket(transport, logger, port) : null);
-    return { browserServer, transport, downloadsPath, logger };
+    browserServer._initialize(launchedProcess, gracefullyClose, launchType === 'server' ? wrapTransportWithWebSocket(transport, logger, port) : null);
+    return { transport, downloadsPath };
   }
 
   async connect(options: ConnectOptions): Promise<CRBrowser> {

src/server/electron.ts

@@ -167,9 +167,8 @@ export class Electron  {
       handleSIGINT = true,
       handleSIGTERM = true,
       handleSIGHUP = true,
-      timeout = 30000,
     } = options;
-    const deadline = TimeoutSettings.computeDeadline(timeout);
+    const browserServer = new BrowserServer(options);
 
     let app: ElectronApplication | undefined = undefined;
 
@@ -193,6 +192,7 @@ export class Electron  {
       },
     });
 
+    const deadline = browserServer._launchDeadline;
     const timeoutError = new TimeoutError(`Timed out while trying to connect to Electron!`);
     const nodeMatch = await waitForLine(launchedProcess, launchedProcess.stderr, /^Debugger listening on (ws:\/\/.*)$/, helper.timeUntilDeadline(deadline), timeoutError);
     const nodeConnection = await WebSocketTransport.connect(nodeMatch[1], transport => {
@@ -203,7 +203,7 @@ export class Electron  {
     const chromeTransport = await WebSocketTransport.connect(chromeMatch[1], transport => {
       return transport;
     }, logger);
-    const browserServer = new BrowserServer(launchedProcess, gracefullyClose, null);
+    browserServer._initialize(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);
     await app._init();