feat(rpc): ensure that error stack traces point to the user code (#2961)

This also adds more "_wrapApiCall" calls for correct logs and stack traces.

Author: dgozman

src/logger.ts

@@ -140,7 +140,7 @@ const colorMap = new Map<string, number>([
   ['reset', 0],
 ]);
 
-class DebugLoggerSink {
+export class DebugLoggerSink {
   private _debuggers = new Map<string, debug.IDebugger>();
 
   isEnabled(name: string, severity: LoggerSeverity): boolean {

src/rpc/client/browser.ts

@@ -54,14 +54,16 @@ export class Browser extends ChannelOwner<BrowserChannel, BrowserInitializer> {
   async newContext(options: types.BrowserContextOptions & { logger?: LoggerSink } = {}): Promise<BrowserContext> {
     const logger = options.logger;
     options = { ...options, logger: undefined };
-    const contextOptions: BrowserContextOptions = {
-      ...options,
-      extraHTTPHeaders: options.extraHTTPHeaders ? headersObjectToArray(options.extraHTTPHeaders) : undefined,
-    };
-    const context = BrowserContext.from((await this._channel.newContext(contextOptions)).context);
-    this._contexts.add(context);
-    context._logger = logger || this._logger;
-    return context;
+    return this._wrapApiCall('browser.newContext', async () => {
+      const contextOptions: BrowserContextOptions = {
+        ...options,
+        extraHTTPHeaders: options.extraHTTPHeaders ? headersObjectToArray(options.extraHTTPHeaders) : undefined,
+      };
+      const context = BrowserContext.from((await this._channel.newContext(contextOptions)).context);
+      this._contexts.add(context);
+      context._logger = logger || this._logger;
+      return context;
+    });
   }
 
   contexts(): BrowserContext[] {
@@ -81,10 +83,12 @@ export class Browser extends ChannelOwner<BrowserChannel, BrowserInitializer> {
   }
 
   async close(): Promise<void> {
-    if (!this._isClosedOrClosing) {
-      this._isClosedOrClosing = true;
-      await this._channel.close();
-    }
-    await this._closedPromise;
+    return this._wrapApiCall('browser.close', async () => {
+      if (!this._isClosedOrClosing) {
+        this._isClosedOrClosing = true;
+        await this._channel.close();
+      }
+      await this._closedPromise;
+    });
   }
 }

src/rpc/client/browserContext.ts

@@ -98,81 +98,109 @@ export class BrowserContext extends ChannelOwner<BrowserContextChannel, BrowserC
   }
 
   async newPage(): Promise<Page> {
-    if (this._ownerPage)
-      throw new Error('Please use browser.newContext()');
-    return Page.from((await this._channel.newPage()).page);
+    return this._wrapApiCall('browserContext.newPage', async () => {
+      if (this._ownerPage)
+        throw new Error('Please use browser.newContext()');
+      return Page.from((await this._channel.newPage()).page);
+    });
   }
 
   async cookies(urls?: string | string[]): Promise<network.NetworkCookie[]> {
     if (!urls)
       urls = [];
     if (urls && typeof urls === 'string')
       urls = [ urls ];
-    return (await this._channel.cookies({ urls: urls as string[] })).cookies;
+    return this._wrapApiCall('browserContext.cookies', async () => {
+      return (await this._channel.cookies({ urls: urls as string[] })).cookies;
+    });
   }
 
   async addCookies(cookies: network.SetNetworkCookieParam[]): Promise<void> {
-    await this._channel.addCookies({ cookies });
+    return this._wrapApiCall('browserContext.addCookies', async () => {
+      await this._channel.addCookies({ cookies });
+    });
   }
 
   async clearCookies(): Promise<void> {
-    await this._channel.clearCookies();
+    return this._wrapApiCall('browserContext.clearCookies', async () => {
+      await this._channel.clearCookies();
+    });
   }
 
   async grantPermissions(permissions: string[], options?: { origin?: string }): Promise<void> {
-    await this._channel.grantPermissions({ permissions, ...options });
+    return this._wrapApiCall('browserContext.grantPermissions', async () => {
+      await this._channel.grantPermissions({ permissions, ...options });
+    });
   }
 
   async clearPermissions(): Promise<void> {
-    await this._channel.clearPermissions();
+    return this._wrapApiCall('browserContext.clearPermissions', async () => {
+      await this._channel.clearPermissions();
+    });
   }
 
   async setGeolocation(geolocation: types.Geolocation | null): Promise<void> {
-    await this._channel.setGeolocation({ geolocation });
+    return this._wrapApiCall('browserContext.setGeolocation', async () => {
+      await this._channel.setGeolocation({ geolocation });
+    });
   }
 
   async setExtraHTTPHeaders(headers: types.Headers): Promise<void> {
-    await this._channel.setExtraHTTPHeaders({ headers: headersObjectToArray(headers) });
+    return this._wrapApiCall('browserContext.setExtraHTTPHeaders', async () => {
+      await this._channel.setExtraHTTPHeaders({ headers: headersObjectToArray(headers) });
+    });
   }
 
   async setOffline(offline: boolean): Promise<void> {
-    await this._channel.setOffline({ offline });
+    return this._wrapApiCall('browserContext.setOffline', async () => {
+      await this._channel.setOffline({ offline });
+    });
   }
 
   async setHTTPCredentials(httpCredentials: types.Credentials | null): Promise<void> {
-    await this._channel.setHTTPCredentials({ httpCredentials });
+    return this._wrapApiCall('browserContext.setHTTPCredentials', async () => {
+      await this._channel.setHTTPCredentials({ httpCredentials });
+    });
   }
 
   async addInitScript(script: Function | string | { path?: string, content?: string }, arg?: any): Promise<void> {
-    const source = await helper.evaluationScript(script, arg);
-    await this._channel.addInitScript({ source });
+    return this._wrapApiCall('browserContext.addInitScript', async () => {
+      const source = await helper.evaluationScript(script, arg);
+      await this._channel.addInitScript({ source });
+    });
   }
 
   async exposeBinding(name: string, binding: frames.FunctionWithSource): Promise<void> {
-    for (const page of this.pages()) {
-      if (page._bindings.has(name))
-        throw new Error(`Function "${name}" has been already registered in one of the pages`);
-    }
-    if (this._bindings.has(name))
-      throw new Error(`Function "${name}" has been already registered`);
-    this._bindings.set(name, binding);
-    await this._channel.exposeBinding({ name });
+    return this._wrapApiCall('browserContext.exposeBinding', async () => {
+      for (const page of this.pages()) {
+        if (page._bindings.has(name))
+          throw new Error(`Function "${name}" has been already registered in one of the pages`);
+      }
+      if (this._bindings.has(name))
+        throw new Error(`Function "${name}" has been already registered`);
+      this._bindings.set(name, binding);
+      await this._channel.exposeBinding({ name });
+    });
   }
 
   async exposeFunction(name: string, playwrightFunction: Function): Promise<void> {
     await this.exposeBinding(name, (source, ...args) => playwrightFunction(...args));
   }
 
   async route(url: types.URLMatch, handler: network.RouteHandler): Promise<void> {
-    this._routes.push({ url, handler });
-    if (this._routes.length === 1)
-      await this._channel.setNetworkInterceptionEnabled({ enabled: true });
+    return this._wrapApiCall('browserContext.route', async () => {
+      this._routes.push({ url, handler });
+      if (this._routes.length === 1)
+        await this._channel.setNetworkInterceptionEnabled({ enabled: true });
+    });
   }
 
   async unroute(url: types.URLMatch, handler?: network.RouteHandler): Promise<void> {
-    this._routes = this._routes.filter(route => route.url !== url || (handler && route.handler !== handler));
-    if (this._routes.length === 0)
-      await this._channel.setNetworkInterceptionEnabled({ enabled: false });
+    return this._wrapApiCall('browserContext.unroute', async () => {
+      this._routes = this._routes.filter(route => route.url !== url || (handler && route.handler !== handler));
+      if (this._routes.length === 0)
+        await this._channel.setNetworkInterceptionEnabled({ enabled: false });
+    });
   }
 
   async waitForEvent(event: string, optionsOrPredicate: types.WaitForEventOptions = {}): Promise<any> {
@@ -196,10 +224,12 @@ export class BrowserContext extends ChannelOwner<BrowserContextChannel, BrowserC
   }
 
   async close(): Promise<void> {
-    if (!this._isClosedOrClosing) {
-      this._isClosedOrClosing = true;
-      await this._channel.close();
-    }
-    await this._closedPromise;
+    return this._wrapApiCall('browserContext.close', async () => {
+      if (!this._isClosedOrClosing) {
+        this._isClosedOrClosing = true;
+        await this._channel.close();
+      }
+      await this._closedPromise;
+    });
   }
 }

src/rpc/client/browserServer.ts

@@ -38,11 +38,15 @@ export class BrowserServer extends ChannelOwner<BrowserServerChannel, BrowserSer
   }
 
   async kill(): Promise<void> {
-    await this._channel.kill();
+    return this._wrapApiCall('browserServer.kill', async () => {
+      await this._channel.kill();
+    });
   }
 
   async close(): Promise<void> {
-    await this._channel.close();
+    return this._wrapApiCall('browserServer.close', async () => {
+      await this._channel.close();
+    });
   }
 
   _checkLeaks() {}

src/rpc/client/cdpSession.ts

@@ -46,11 +46,15 @@ export class CDPSession extends ChannelOwner<CDPSessionChannel, CDPSessionInitia
     method: T,
     params?: Protocol.CommandParameters[T]
   ): Promise<Protocol.CommandReturnValues[T]> {
-    const result = await this._channel.send({ method, params });
-    return result.result as Protocol.CommandReturnValues[T];
+    return this._wrapApiCall('cdpSession.send', async () => {
+      const result = await this._channel.send({ method, params });
+      return result.result as Protocol.CommandReturnValues[T];
+    });
   }
 
   async detach() {
-    return this._channel.detach();
+    return this._wrapApiCall('cdpSession.detach', async () => {
+      return this._channel.detach();
+    });
   }
 }

src/rpc/client/channelOwner.ts

@@ -19,7 +19,7 @@ import { Channel } from '../channels';
 import { Connection } from './connection';
 import { assert } from '../../helper';
 import { LoggerSink } from '../../loggerSink';
-import { rewriteErrorMessage } from '../../utils/stackTrace';
+import { DebugLoggerSink } from '../../logger';
 
 export abstract class ChannelOwner<T extends Channel = Channel, Initializer = {}> extends EventEmitter {
   private _connection: Connection;
@@ -99,19 +99,30 @@ export abstract class ChannelOwner<T extends Channel = Channel, Initializer = {}
   }
 
   protected async _wrapApiCall<T>(apiName: string, func: () => Promise<T>, logger?: LoggerSink): Promise<T> {
+    const stackObject: any = {};
+    Error.captureStackTrace(stackObject);
+    const stack = stackObject.stack.startsWith('Error') ? stackObject.stack.substring(5) : stackObject.stack;
     logger = logger || this._logger;
     try {
-      if (logger && logger.isEnabled('api', 'info'))
-        logger.log('api', 'info', `=> ${apiName} started`, [], { color: 'cyan' });
+      logApiCall(logger, `=> ${apiName} started`);
       const result = await func();
-      if (logger && logger.isEnabled('api', 'info'))
-        logger.log('api', 'info', `=> ${apiName} succeeded`, [], { color: 'cyan' });
+      logApiCall(logger, `<= ${apiName} succeeded`);
       return result;
     } catch (e) {
-      if (logger && logger.isEnabled('api', 'info'))
-        logger.log('api', 'info', `=> ${apiName} failed`, [], { color: 'cyan' });
-      rewriteErrorMessage(e, `${apiName}: ` + e.message);
+      logApiCall(logger, `<= ${apiName} failed`);
+      // TODO: we could probably save "e.stack" in some log-heavy mode
+      // because it gives some insights into the server part.
+      e.message = `${apiName}: ` + e.message;
+      e.stack = e.message + stack;
       throw e;
     }
   }
 }
+
+const debugLogger = new DebugLoggerSink();
+function logApiCall(logger: LoggerSink | undefined, message: string) {
+  if (logger && logger.isEnabled('api', 'info'))
+    logger.log('api', 'info', message, [], { color: 'cyan' });
+  if (debugLogger.isEnabled('api', 'info'))
+    debugLogger.log('api', 'info', message, [], { color: 'cyan' });
+}

src/rpc/client/chromiumBrowser.ts

@@ -20,14 +20,20 @@ import { Browser } from './browser';
 
 export class ChromiumBrowser extends Browser {
   async newBrowserCDPSession(): Promise<CDPSession> {
-    return CDPSession.from((await this._channel.crNewBrowserCDPSession()).session);
+    return this._wrapApiCall('chromiumBrowser.newBrowserCDPSession', async () => {
+      return CDPSession.from((await this._channel.crNewBrowserCDPSession()).session);
+    });
   }
 
   async startTracing(page?: Page, options: { path?: string; screenshots?: boolean; categories?: string[]; } = {}) {
-    await this._channel.crStartTracing({ ...options, page: page ? page._channel : undefined });
+    return this._wrapApiCall('chromiumBrowser.startTracing', async () => {
+      await this._channel.crStartTracing({ ...options, page: page ? page._channel : undefined });
+    });
   }
 
   async stopTracing(): Promise<Buffer> {
-    return Buffer.from((await this._channel.crStopTracing()).binary, 'base64');
+    return this._wrapApiCall('chromiumBrowser.stopTracing', async () => {
+      return Buffer.from((await this._channel.crStopTracing()).binary, 'base64');
+    });
   }
 }

src/rpc/client/chromiumBrowserContext.ts

@@ -51,7 +51,9 @@ export class ChromiumBrowserContext extends BrowserContext {
   }
 
   async newCDPSession(page: Page): Promise<CDPSession> {
-    const result = await this._channel.crNewCDPSession({ page: page._channel });
-    return CDPSession.from(result.session);
+    return this._wrapApiCall('chromiumBrowserContext.newCDPSession', async () => {
+      const result = await this._channel.crNewCDPSession({ page: page._channel });
+      return CDPSession.from(result.session);
+    });
   }
 }

src/rpc/client/dialog.ts

@@ -39,10 +39,14 @@ export class Dialog extends ChannelOwner<DialogChannel, DialogInitializer> {
   }
 
   async accept(promptText: string | undefined) {
-    await this._channel.accept({ promptText });
+    return this._wrapApiCall('dialog.accept', async () => {
+      await this._channel.accept({ promptText });
+    });
   }
 
   async dismiss() {
-    await this._channel.dismiss();
+    return this._wrapApiCall('dialog.dismiss', async () => {
+      await this._channel.dismiss();
+    });
   }
 }

src/rpc/client/electron.ts

@@ -25,6 +25,7 @@ import { TimeoutSettings } from '../../timeoutSettings';
 import { Waiter } from './waiter';
 import { TimeoutError } from '../../errors';
 import { Events } from '../../events';
+import { LoggerSink } from '../../loggerSink';
 
 export class Electron extends ChannelOwner<ElectronChannel, ElectronInitializer> {
   static from(electron: ElectronChannel): Electron {
@@ -35,10 +36,12 @@ export class Electron extends ChannelOwner<ElectronChannel, ElectronInitializer>
     super(parent, type, guid, initializer, true);
   }
 
-  async launch(executablePath: string, options: ElectronLaunchOptions = {}): Promise<ElectronApplication> {
-    options = { ...options };
-    delete (options as any).logger;
-    return ElectronApplication.from((await this._channel.launch({ executablePath, ...options })).electronApplication);
+  async launch(executablePath: string, options: ElectronLaunchOptions & { logger?: LoggerSink } = {}): Promise<ElectronApplication> {
+    const logger = options.logger;
+    options = { ...options, logger: undefined };
+    return this._wrapApiCall('electron.launch', async () => {
+      return ElectronApplication.from((await this._channel.launch({ executablePath, ...options })).electronApplication);
+    }, logger);
   }
 }