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.

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,6 +54,7 @@ export class Browser extends ChannelOwner<BrowserChannel, BrowserInitializer> {
   async newContext(options: types.BrowserContextOptions & { logger?: LoggerSink } = {}): Promise<BrowserContext> {
     const logger = options.logger;
     options = { ...options, logger: undefined };
+    return this._wrapApiCall('browser.newContext', async () => {
       const contextOptions: BrowserContextOptions = {
         ...options,
         extraHTTPHeaders: options.extraHTTPHeaders ? headersObjectToArray(options.extraHTTPHeaders) : undefined,
@@ -62,6 +63,7 @@ export class Browser extends ChannelOwner<BrowserChannel, BrowserInitializer> {
       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> {
+    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,9 +98,11 @@ export class BrowserContext extends ChannelOwner<BrowserContextChannel, BrowserC
   }
 
   async newPage(): Promise<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[]> {
@@ -108,47 +110,68 @@ export class BrowserContext extends ChannelOwner<BrowserContextChannel, BrowserC
       urls = [];
     if (urls && typeof urls === 'string')
       urls = [ urls ];
+    return this._wrapApiCall('browserContext.cookies', async () => {
       return (await this._channel.cookies({ urls: urls as string[] })).cookies;
+    });
   }
 
   async addCookies(cookies: network.SetNetworkCookieParam[]): Promise<void> {
+    return this._wrapApiCall('browserContext.addCookies', async () => {
       await this._channel.addCookies({ cookies });
+    });
   }
 
   async clearCookies(): Promise<void> {
+    return this._wrapApiCall('browserContext.clearCookies', async () => {
       await this._channel.clearCookies();
+    });
   }
 
   async grantPermissions(permissions: string[], options?: { origin?: string }): Promise<void> {
+    return this._wrapApiCall('browserContext.grantPermissions', async () => {
       await this._channel.grantPermissions({ permissions, ...options });
+    });
   }
 
   async clearPermissions(): Promise<void> {
+    return this._wrapApiCall('browserContext.clearPermissions', async () => {
       await this._channel.clearPermissions();
+    });
   }
 
   async setGeolocation(geolocation: types.Geolocation | null): Promise<void> {
+    return this._wrapApiCall('browserContext.setGeolocation', async () => {
       await this._channel.setGeolocation({ geolocation });
+    });
   }
 
   async setExtraHTTPHeaders(headers: types.Headers): Promise<void> {
+    return this._wrapApiCall('browserContext.setExtraHTTPHeaders', async () => {
       await this._channel.setExtraHTTPHeaders({ headers: headersObjectToArray(headers) });
+    });
   }
 
   async setOffline(offline: boolean): Promise<void> {
+    return this._wrapApiCall('browserContext.setOffline', async () => {
       await this._channel.setOffline({ offline });
+    });
   }
 
   async setHTTPCredentials(httpCredentials: types.Credentials | null): Promise<void> {
+    return this._wrapApiCall('browserContext.setHTTPCredentials', async () => {
       await this._channel.setHTTPCredentials({ httpCredentials });
+    });
   }
 
   async addInitScript(script: Function | string | { path?: string, content?: string }, arg?: any): Promise<void> {
+    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> {
+    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`);
@@ -157,6 +180,7 @@ export class BrowserContext extends ChannelOwner<BrowserContextChannel, BrowserC
         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> {
@@ -164,15 +188,19 @@ export class BrowserContext extends ChannelOwner<BrowserContextChannel, BrowserC
   }
 
   async route(url: types.URLMatch, handler: network.RouteHandler): Promise<void> {
+    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> {
+    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> {
+    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> {
+    return this._wrapApiCall('browserServer.kill', async () => {
       await this._channel.kill();
+    });
   }
 
   async close(): Promise<void> {
+    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]> {
+    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._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'))
+      logApiCall(logger, `=> ${apiName} started`);
-        logger.log('api', 'info', `=> ${apiName} started`, [], { color: 'cyan' });
       const result = await func();
-      if (logger && logger.isEnabled('api', 'info'))
+      logApiCall(logger, `<= ${apiName} succeeded`);
-        logger.log('api', 'info', `=> ${apiName} succeeded`, [], { color: 'cyan' });
       return result;
     } catch (e) {
-      if (logger && logger.isEnabled('api', 'info'))
+      logApiCall(logger, `<= ${apiName} failed`);
-        logger.log('api', 'info', `=> ${apiName} failed`, [], { color: 'cyan' });
+      // TODO: we could probably save "e.stack" in some log-heavy mode
-      rewriteErrorMessage(e, `${apiName}: ` + e.message);
+      // 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 this._wrapApiCall('chromiumBrowser.newBrowserCDPSession', async () => {
       return CDPSession.from((await this._channel.crNewBrowserCDPSession()).session);
+    });
   }
 
   async startTracing(page?: Page, options: { path?: string; screenshots?: boolean; categories?: string[]; } = {}) {
+    return this._wrapApiCall('chromiumBrowser.startTracing', async () => {
       await this._channel.crStartTracing({ ...options, page: page ? page._channel : undefined });
+    });
   }
 
   async stopTracing(): Promise<Buffer> {
+    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> {
+    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) {
+    return this._wrapApiCall('dialog.accept', async () => {
       await this._channel.accept({ promptText });
+    });
   }
 
   async 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> {
+  async launch(executablePath: string, options: ElectronLaunchOptions & { logger?: LoggerSink } = {}): Promise<ElectronApplication> {
-    options = { ...options };
+    const logger = options.logger;
-    delete (options as any).logger;
+    options = { ...options, logger: undefined };
+    return this._wrapApiCall('electron.launch', async () => {
       return ElectronApplication.from((await this._channel.launch({ executablePath, ...options })).electronApplication);
+    }, logger);
   }
 }
 

src/rpc/client/page.ts

@@ -259,7 +259,7 @@ export class Page extends ChannelOwner<PageChannel, PageInitializer> {
   }
 
   async addStyleTag(options: { url?: string; path?: string; content?: string; }): Promise<ElementHandle> {
-    return  await this._mainFrame.addStyleTag(options);
+    return this._attributeToPage(() => this._mainFrame.addStyleTag(options));
   }
 
   async exposeFunction(name: string, playwrightFunction: Function) {
@@ -267,16 +267,20 @@ export class Page extends ChannelOwner<PageChannel, PageInitializer> {
   }
 
   async exposeBinding(name: string, binding: FunctionWithSource) {
+    return this._wrapApiCall('page.exposeBinding', async () => {
       if (this._bindings.has(name))
         throw new Error(`Function "${name}" has been already registered`);
       if (this._browserContext._bindings.has(name))
         throw new Error(`Function "${name}" has been already registered in the browser context`);
       this._bindings.set(name, binding);
       await this._channel.exposeBinding({ name });
+    });
   }
 
   async setExtraHTTPHeaders(headers: types.Headers) {
+    return this._wrapApiCall('page.setExtraHTTPHeaders', async () => {
       await this._channel.setExtraHTTPHeaders({ headers: headersObjectToArray(headers) });
+    });
   }
 
   url(): string {
@@ -296,7 +300,9 @@ export class Page extends ChannelOwner<PageChannel, PageInitializer> {
   }
 
   async reload(options: types.NavigateOptions = {}): Promise<Response | null> {
+    return this._wrapApiCall('page.reload', async () => {
       return Response.fromNullable((await this._channel.reload(options)).response);
+    });
   }
 
   async waitForLoadState(state?: types.LifecycleEvent, options?: types.TimeoutOptions): Promise<void> {
@@ -340,20 +346,28 @@ export class Page extends ChannelOwner<PageChannel, PageInitializer> {
   }
 
   async goBack(options: types.NavigateOptions = {}): Promise<Response | null> {
+    return this._wrapApiCall('page.goBack', async () => {
       return Response.fromNullable((await this._channel.goBack(options)).response);
+    });
   }
 
   async goForward(options: types.NavigateOptions = {}): Promise<Response | null> {
+    return this._wrapApiCall('page.goForward', async () => {
       return Response.fromNullable((await this._channel.goForward(options)).response);
+    });
   }
 
   async emulateMedia(options: { media?: types.MediaType, colorScheme?: types.ColorScheme }) {
+    return this._wrapApiCall('page.emulateMedia', async () => {
       await this._channel.emulateMedia(options);
+    });
   }
 
   async setViewportSize(viewportSize: types.Size) {
+    return this._wrapApiCall('page.setViewportSize', async () => {
       this._viewportSize = viewportSize;
       await this._channel.setViewportSize({ viewportSize });
+    });
   }
 
   viewportSize(): types.Size | null {
@@ -368,20 +382,26 @@ export class Page extends ChannelOwner<PageChannel, PageInitializer> {
   }
 
   async addInitScript(script: Function | string | { path?: string, content?: string }, arg?: any) {
+    return this._wrapApiCall('page.addInitScript', async () => {
       const source = await helper.evaluationScript(script, arg);
       await this._channel.addInitScript({ source });
+    });
   }
 
   async route(url: types.URLMatch, handler: RouteHandler): Promise<void> {
+    return this._wrapApiCall('page.route', async () => {
       this._routes.push({ url, handler });
       if (this._routes.length === 1)
         await this._channel.setNetworkInterceptionEnabled({ enabled: true });
+    });
   }
 
   async unroute(url: types.URLMatch, handler?: RouteHandler): Promise<void> {
+    return this._wrapApiCall('page.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 screenshot(options: types.ScreenshotOptions = {}): Promise<Buffer> {
@@ -395,9 +415,11 @@ export class Page extends ChannelOwner<PageChannel, PageInitializer> {
   }
 
   async close(options: { runBeforeUnload?: boolean } = {runBeforeUnload: undefined}) {
+    return this._wrapApiCall('page.close', async () => {
       await this._channel.close(options);
       if (this._ownedContext)
         await this._ownedContext.close();
+    });
   }
 
   isClosed(): boolean {

test/browsercontext.spec.js

@@ -104,11 +104,11 @@ describe('BrowserContext', function() {
   });
   it('should not allow deviceScaleFactor with null viewport', async({ browser }) => {
     const error = await browser.newContext({ viewport: null, deviceScaleFactor: 1 }).catch(e => e);
-    expect(error.message).toBe('"deviceScaleFactor" option is not supported with null "viewport"');
+    expect(error.message).toContain('"deviceScaleFactor" option is not supported with null "viewport"');
   });
   it('should not allow isMobile with null viewport', async({ browser }) => {
     const error = await browser.newContext({ viewport: null, isMobile: true }).catch(e => e);
-    expect(error.message).toBe('"isMobile" option is not supported with null "viewport"');
+    expect(error.message).toContain('"isMobile" option is not supported with null "viewport"');
   });
   it('close() should work for empty context', async({ browser }) => {
     const context = await browser.newContext();
@@ -393,13 +393,13 @@ describe('BrowserContext.exposeFunction', () => {
     await context.exposeFunction('foo', () => {});
     await context.exposeFunction('bar', () => {});
     let error = await context.exposeFunction('foo', () => {}).catch(e => e);
-    expect(error.message).toBe('Function "foo" has been already registered');
+    expect(error.message).toContain('Function "foo" has been already registered');
     const page = await context.newPage();
     error = await page.exposeFunction('foo', () => {}).catch(e => e);
-    expect(error.message).toBe('Function "foo" has been already registered in the browser context');
+    expect(error.message).toContain('Function "foo" has been already registered in the browser context');
     await page.exposeFunction('baz', () => {});
     error = await context.exposeFunction('baz', () => {}).catch(e => e);
-    expect(error.message).toBe('Function "baz" has been already registered in one of the pages');
+    expect(error.message).toContain('Function "baz" has been already registered in one of the pages');
     await context.close();
   });
   it('should be callable from-inside addInitScript', async({browser, server}) => {

test/chromium/session.spec.js

@@ -66,7 +66,7 @@ describe('ChromiumBrowserContext.createSession', function() {
     }
     expect(error.message).toContain(CHANNEL ? 'Target browser or context has been closed' : 'Session closed.');
   });
-  it.skip(CHANNEL)('should throw nice errors', async function({page, browser}) {
+  it('should throw nice errors', async function({page, browser}) {
     const client = await page.context().newCDPSession(page);
     const error = await theSourceOfTheProblems().catch(error => error);
     expect(error.stack).toContain('theSourceOfTheProblems');

test/cookies.spec.js

@@ -369,7 +369,7 @@ describe('BrowserContext.addCookies', function() {
     } catch (e) {
       error = e;
     }
-    expect(error.message).toEqual(
+    expect(error.message).toContain(
         `Blank page can not have cookie "example-cookie-blank"`
     );
   });

test/emulation.spec.js

@@ -242,7 +242,7 @@ describe('Page.emulateMedia type', function() {
   it('should throw in case of bad type argument', async({page, server}) => {
     let error = null;
     await page.emulateMedia({ media: 'bad' }).catch(e => error = e);
-    expect(error.message).toBe('Unsupported media: bad');
+    expect(error.message).toContain('Unsupported media: bad');
   });
 });
 
@@ -270,7 +270,7 @@ describe('Page.emulateMedia colorScheme', function() {
   it('should throw in case of bad argument', async({page, server}) => {
     let error = null;
     await page.emulateMedia({ colorScheme: 'bad' }).catch(e => error = e);
-    expect(error.message).toBe('Unsupported color scheme: bad');
+    expect(error.message).toContain('Unsupported color scheme: bad');
   });
   it('should work during navigation', async({page, server}) => {
     await page.emulateMedia({ colorScheme: 'light' });
@@ -353,7 +353,7 @@ describe('BrowserContext({timezoneId})', function() {
       let error = null;
       const context = await browser.newContext({ timezoneId });
       const page = await context.newPage().catch(e => error = e);
-      expect(error.message).toBe(`Invalid timezone ID: ${timezoneId}`);
+      expect(error.message).toContain(`Invalid timezone ID: ${timezoneId}`);
       await context.close();
     }
   });

test/evaluation.jest.js

@@ -489,7 +489,7 @@ describe('Page.addInitScript', function() {
   });
   it('should throw without path and content', async({page, server}) => {
     const error = await page.addInitScript({ foo: 'bar' }).catch(e => e);
-    expect(error.message).toBe('Either path or content property must be present');
+    expect(error.message).toContain('Either path or content property must be present');
   });
   it('should work with browser context scripts', async({browser, server}) => {
     const context = await browser.newContext();

test/network.spec.js

@@ -458,6 +458,6 @@ describe('Page.setExtraHTTPHeaders', function() {
     } catch (e) {
       error = e;
     }
-    expect(error.message).toBe('Expected value of header "foo" to be String, but "number" is found.');
+    expect(error.message).toContain('Expected value of header "foo" to be String, but "number" is found.');
   });
 });

test/page.spec.js

@@ -101,7 +101,7 @@ describe('Page.Events.Load', function() {
   });
 });
 
-describe.skip(CHANNEL)('Async stacks', () => {
+describe('Async stacks', () => {
   it('should work', async({page, server}) => {
     server.setRoute('/empty.html', (req, res) => {
       req.socket.end();

test/permissions.spec.js

@@ -36,7 +36,7 @@ describe.skip(WEBKIT)('Permissions', function() {
     await page.goto(server.EMPTY_PAGE);
     let error = {};
     await context.grantPermissions(['foo'], { origin: server.EMPTY_PAGE }).catch(e => error = e);
-    expect(error.message).toBe('Unknown permission: foo');
+    expect(error.message).toContain('Unknown permission: foo');
   });
   it('should grant geolocation permission when listed', async({page, server, context}) => {
     await page.goto(server.EMPTY_PAGE);

test/waittask.spec.js

@@ -458,7 +458,7 @@ describe('Frame.waitForSelector', function() {
     await page.setContent(`<div class='zombo'>anything</div>`);
     expect(await page.evaluate(x => x.textContent, await waitForSelector)).toBe('anything');
   });
-  it.skip(CHANNEL)('should have correct stack trace for timeout', async({page, server}) => {
+  it('should have correct stack trace for timeout', async({page, server}) => {
     let error;
     await page.waitForSelector('.zombo', { timeout: 10 }).catch(e => error = e);
     expect(error.stack).toContain('waittask.spec.js');