feat(inspector): instrument wait for event (#5457)

src/client/android.ts

@@ -239,7 +239,7 @@ export class AndroidDevice extends ChannelOwner<channels.AndroidDeviceChannel, c
   async waitForEvent(event: string, optionsOrPredicate: types.WaitForEventOptions = {}): Promise<any> {
     const timeout = this._timeoutSettings.timeout(typeof optionsOrPredicate === 'function' ? {} : optionsOrPredicate);
     const predicate = typeof optionsOrPredicate === 'function' ? optionsOrPredicate : optionsOrPredicate.predicate;
-    const waiter = new Waiter();
+    const waiter = Waiter.createForEvent(this, event);
     waiter.rejectOnTimeout(timeout, `Timeout while waiting for event "${event}"`);
     if (event !== Events.AndroidDevice.Close)
       waiter.rejectOnEvent(this, Events.AndroidDevice.Close, new Error('Device closed'));

src/client/browserContext.ts

@@ -217,7 +217,7 @@ export class BrowserContext extends ChannelOwner<channels.BrowserContextChannel,
   async waitForEvent(event: string, optionsOrPredicate: WaitForEventOptions = {}): Promise<any> {
     const timeout = this._timeoutSettings.timeout(typeof optionsOrPredicate === 'function'  ? {} : optionsOrPredicate);
     const predicate = typeof optionsOrPredicate === 'function'  ? optionsOrPredicate : optionsOrPredicate.predicate;
-    const waiter = new Waiter();
+    const waiter = Waiter.createForEvent(this, event);
     waiter.rejectOnTimeout(timeout, `Timeout while waiting for event "${event}"`);
     if (event !== Events.BrowserContext.Close)
       waiter.rejectOnEvent(this, Events.BrowserContext.Close, new Error('Context closed'));

src/client/channelOwner.ts

@@ -21,6 +21,7 @@ import type { Logger } from './types';
 import { debugLogger } from '../utils/debugLogger';
 import { rewriteErrorMessage } from '../utils/stackTrace';
 import { createScheme, Validator, ValidationError } from '../protocol/validator';
+import { StackFrame } from '../common/types';
 
 export abstract class ChannelOwner<T extends channels.Channel = channels.Channel, Initializer = {}> extends EventEmitter {
   private _connection: Connection;
@@ -97,6 +98,18 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel
     }
   }
 
+  _waitForEventInfoBefore(waitId: string, name: string, stack: StackFrame[]) {
+    this._connection.sendMessageToServer(this._guid, 'waitForEventInfo', { info: { name, waitId, phase: 'before', stack } }).catch(() => {});
+  }
+
+  _waitForEventInfoAfter(waitId: string, error?: string) {
+    this._connection.sendMessageToServer(this._guid, 'waitForEventInfo', { info: { waitId, phase: 'after', error } }).catch(() => {});
+  }
+
+  _waitForEventInfoLog(waitId: string, message: string) {
+    this._connection.sendMessageToServer(this._guid, 'waitForEventInfo', { info: { waitId, phase: 'log', message } }).catch(() => {});
+  }
+
   private toJSON() {
     // Jest's expect library tries to print objects sometimes.
     // RPC objects can contain links to lots of other objects,

src/client/connection.ts

@@ -81,7 +81,7 @@ export class Connection {
     try {
       return await new Promise((resolve, reject) => this._callbacks.set(id, { resolve, reject }));
     } catch (e) {
-      const innerStack = (isUnderTest() && e.stack) ? e.stack.substring(e.stack.indexOf(e.message) + e.message.length) : '';
+      const innerStack = ((process.env.PWDEBUGIMPL || isUnderTest()) && e.stack) ? e.stack.substring(e.stack.indexOf(e.message) + e.message.length) : '';
       e.stack = e.message + innerStack + stack;
       throw e;
     }

src/client/electron.ts

@@ -101,7 +101,7 @@ export class ElectronApplication extends ChannelOwner<channels.ElectronApplicati
   async waitForEvent(event: string, optionsOrPredicate: WaitForEventOptions = {}): Promise<any> {
     const timeout = this._timeoutSettings.timeout(typeof optionsOrPredicate === 'function' ? {} : optionsOrPredicate);
     const predicate = typeof optionsOrPredicate === 'function' ? optionsOrPredicate : optionsOrPredicate.predicate;
-    const waiter = new Waiter();
+    const waiter = Waiter.createForEvent(this, event);
     waiter.rejectOnTimeout(timeout, `Timeout while waiting for event "${event}"`);
     if (event !== Events.ElectronApplication.Close)
       waiter.rejectOnEvent(this, Events.ElectronApplication.Close, new Error('Electron application closed'));

src/client/frame.ts

@@ -100,21 +100,20 @@ export class Frame extends ChannelOwner<channels.FrameChannel, channels.FrameIni
     });
   }
 
-  private _setupNavigationWaiter(options: { timeout?: number }): Waiter {
+  private _setupNavigationWaiter(name: string, options: { timeout?: number }): Waiter {
-    const waiter = new Waiter();
+    const waiter = new Waiter(this, name);
     waiter.rejectOnEvent(this._page!, Events.Page.Close, new Error('Navigation failed because page was closed!'));
     waiter.rejectOnEvent(this._page!, Events.Page.Crash, new Error('Navigation failed because page crashed!'));
     waiter.rejectOnEvent<Frame>(this._page!, Events.Page.FrameDetached, new Error('Navigating frame was detached!'), frame => frame === this);
     const timeout = this._page!._timeoutSettings.navigationTimeout(options);
     waiter.rejectOnTimeout(timeout, `Timeout ${timeout}ms exceeded.`);
-
     return waiter;
   }
 
   async waitForNavigation(options: WaitForNavigationOptions = {}): Promise<network.Response | null> {
     return this._wrapApiCall(this._apiName('waitForNavigation'), async () => {
       const waitUntil = verifyLoadState('waitUntil', options.waitUntil === undefined ? 'load' : options.waitUntil);
-      const waiter = this._setupNavigationWaiter(options);
+      const waiter = this._setupNavigationWaiter('waitForNavigation', options);
 
       const toUrl = typeof options.url === 'string' ? ` to "${options.url}"` : '';
       waiter.log(`waiting for navigation${toUrl} until "${waitUntil}"`);
@@ -151,7 +150,7 @@ export class Frame extends ChannelOwner<channels.FrameChannel, channels.FrameIni
     if (this._loadStates.has(state))
       return;
     return this._wrapApiCall(this._apiName('waitForLoadState'), async () => {
-      const waiter = this._setupNavigationWaiter(options);
+      const waiter = this._setupNavigationWaiter('waitForLoadState', options);
       await waiter.waitForEvent<LifecycleEvent>(this._eventEmitter, 'loadstate', s => {
         waiter.log(`  "${s}" event fired`);
         return s === state;

src/client/network.ts

@@ -365,7 +365,7 @@ export class WebSocket extends ChannelOwner<channels.WebSocketChannel, channels.
   async waitForEvent(event: string, optionsOrPredicate: WaitForEventOptions = {}): Promise<any> {
     const timeout = this._page._timeoutSettings.timeout(typeof optionsOrPredicate === 'function' ? {} : optionsOrPredicate);
     const predicate = typeof optionsOrPredicate === 'function' ? optionsOrPredicate : optionsOrPredicate.predicate;
-    const waiter = new Waiter();
+    const waiter = Waiter.createForEvent(this, event);
     waiter.rejectOnTimeout(timeout, `Timeout while waiting for event "${event}"`);
     if (event !== Events.WebSocket.Error)
       waiter.rejectOnEvent(this, Events.WebSocket.Error, new Error('Socket error'));

src/client/page.ts

@@ -395,7 +395,7 @@ export class Page extends ChannelOwner<channels.PageChannel, channels.PageInitia
   private async _waitForEvent(event: string, optionsOrPredicate: WaitForEventOptions, logLine?: string): Promise<any> {
     const timeout = this._timeoutSettings.timeout(typeof optionsOrPredicate === 'function' ? {} : optionsOrPredicate);
     const predicate = typeof optionsOrPredicate === 'function' ? optionsOrPredicate : optionsOrPredicate.predicate;
-    const waiter = new Waiter();
+    const waiter = Waiter.createForEvent(this, event);
     if (logLine)
       waiter.log(logLine);
     waiter.rejectOnTimeout(timeout, `Timeout while waiting for event "${event}"`);

src/client/waiter.ts

@@ -15,15 +15,32 @@
  */
 
 import { EventEmitter } from 'events';
-import { rewriteErrorMessage } from '../utils/stackTrace';
+import { captureStackTrace, rewriteErrorMessage } from '../utils/stackTrace';
 import { TimeoutError } from '../utils/errors';
-import { debugLogger } from '../utils/debugLogger';
+import { createGuid } from '../utils/utils';
+import { ChannelOwner } from './channelOwner';
 
 export class Waiter {
-  private _dispose: (() => void)[] = [];
+  private _dispose: (() => void)[];
   private _failures: Promise<any>[] = [];
   // TODO: can/should we move these logs into wrapApiCall?
   private _logs: string[] = [];
+  private _channelOwner: ChannelOwner;
+  private _waitId: string;
+  private _error: string | undefined;
+
+  constructor(channelOwner: ChannelOwner, name: string) {
+    this._waitId = createGuid();
+    this._channelOwner = channelOwner;
+    this._channelOwner._waitForEventInfoBefore(this._waitId, name, captureStackTrace().frames);
+    this._dispose = [
+      () => this._channelOwner._waitForEventInfoAfter(this._waitId, this._error)
+    ];
+  }
+
+  static createForEvent(channelOwner: ChannelOwner, event: string) {
+    return new Waiter(channelOwner, `waitForEvent(${event})`);
+  }
 
   async waitForEvent<T = void>(emitter: EventEmitter, event: string, predicate?: (arg: T) => boolean): Promise<T> {
     const { promise, dispose } = waitForEvent(emitter, event, predicate);
@@ -56,6 +73,7 @@ export class Waiter {
     } catch (e) {
       if (dispose)
         dispose();
+      this._error = e.message;
       this.dispose();
       rewriteErrorMessage(e, e.message + formatLogRecording(this._logs) + kLoggingNote);
       throw e;
@@ -64,7 +82,7 @@ export class Waiter {
 
   log(s: string) {
     this._logs.push(s);
-    debugLogger.log('api', s);
+    this._channelOwner._waitForEventInfoLog(this._waitId, s);
   }
 
   private _rejectOn(promise: Promise<any>, dispose?: () => void) {

src/dispatchers/dispatcher.ts

@@ -112,6 +112,10 @@ export class Dispatcher<Type, Initializer> extends EventEmitter implements chann
       objects: Array.from(this._dispatchers.values()).map(o => o._debugScopeState()),
     };
   }
+
+  async waitForEventInfo(): Promise<void> {
+    // Instrumentation takes care of this.
+  }
 }
 
 export type DispatcherScope = Dispatcher<any, any>;
@@ -151,6 +155,8 @@ export class DispatcherConnection {
     };
     const scheme = createScheme(tChannel);
     this._validateParams = (type: string, method: string, params: any): any => {
+      if (method === 'waitForEventInfo')
+        return tOptional(scheme['WaitForEventInfo'])(params.info, '');
       const name = type + method[0].toUpperCase() + method.substring(1) + 'Params';
       if (!scheme[name])
         throw new ValidationError(`Unknown scheme for ${type}.${method}`);

src/protocol/channels.ts

@@ -23,13 +23,24 @@ export type Binary = string;
 export interface Channel extends EventEmitter {
 }
 
-export type Metadata = {
+export type StackFrame = {
-  stack?: {
   file: string,
   line?: number,
   column?: number,
   function?: string,
-  }[],
+};
+
+export type Metadata = {
+  stack?: StackFrame[],
+};
+
+export type WaitForEventInfo = {
+  waitId: string,
+  phase: 'before' | 'after' | 'log',
+  name?: string,
+  stack?: StackFrame[],
+  message?: string,
+  error?: string,
 };
 
 export type Point = {

src/protocol/protocol.yml

@@ -12,14 +12,7 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-
+StackFrame:
-# This object can be send with any rpc call in the "metadata" field.
-Metadata:
-  type: object
-  properties:
-    stack:
-      type: array?
-      items:
   type: object
   properties:
     file: string
@@ -27,6 +20,33 @@ Metadata:
     column: number?
     function: string?
 
+# This object can be send with any rpc call in the "metadata" field.
+
+Metadata:
+  type: object
+  properties:
+    stack:
+      type: array?
+      items: StackFrame
+
+
+WaitForEventInfo:
+  type: object
+  properties:
+    waitId: string
+    phase:
+      type: enum
+      literals:
+      - before
+      - after
+      - log
+    name: string?
+    stack:
+      type: array?
+      items: StackFrame
+    message: string?
+    error: string?
+
 
 Point:
   type: object

src/protocol/validator.ts

@@ -33,13 +33,22 @@ export function createScheme(tChannel: (name: string) => Validator): Scheme {
     };
   };
 
-  scheme.Metadata = tObject({
+  scheme.StackFrame = tObject({
-    stack: tOptional(tArray(tObject({
     file: tString,
     line: tOptional(tNumber),
     column: tOptional(tNumber),
     function: tOptional(tString),
-    }))),
+  });
+  scheme.Metadata = tObject({
+    stack: tOptional(tArray(tType('StackFrame'))),
+  });
+  scheme.WaitForEventInfo = tObject({
+    waitId: tString,
+    phase: tEnum(['before', 'after', 'log']),
+    name: tOptional(tString),
+    stack: tOptional(tArray(tType('StackFrame'))),
+    message: tOptional(tString),
+    error: tOptional(tString),
   });
   scheme.Point = tObject({
     x: tNumber,

src/server/supplements/inspectorController.ts

@@ -22,6 +22,7 @@ import { isDebugMode, isUnderTest } from '../../utils/utils';
 
 export class InspectorController implements InstrumentationListener {
   private _recorders = new Map<BrowserContext, Promise<RecorderSupplement>>();
+  private _waitOperations = new Map<string, CallMetadata>();
 
   async onContextCreated(context: BrowserContext): Promise<void> {
     if (isDebugMode())
@@ -37,6 +38,25 @@ export class InspectorController implements InstrumentationListener {
     if (!context)
       return;
 
+    // Process logs for waitForNavigation/waitForLoadState
+    if (metadata.params?.info?.waitId) {
+      const info = metadata.params.info;
+      switch (info.phase) {
+        case 'before':
+          metadata.method = info.name;
+          metadata.stack = info.stack;
+          this._waitOperations.set(info.waitId, metadata);
+          break;
+        case 'log':
+          const originalMetadata = this._waitOperations.get(info.waitId)!;
+          originalMetadata.log.push(info.message);
+          this.onCallLog('api', info.message, sdkObject, originalMetadata);
+          // Fall through.
+        case 'after':
+          return;
+      }
+    }
+
     if (metadata.method === 'pause') {
       // Force create recorder on pause.
       if (!context._browser.options.headful && !isUnderTest())
@@ -51,22 +71,38 @@ export class InspectorController implements InstrumentationListener {
   async onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
     if (!sdkObject.attribution.context)
       return;
-    const recorder = await this._recorders.get(sdkObject.attribution.context!);
+
+    // Process logs for waitForNavigation/waitForLoadState
+    if (metadata.params?.info?.waitId) {
+      const info = metadata.params.info;
+      switch (info.phase) {
+        case 'before':
+          // Fall through.
+        case 'log':
+          return;
+        case 'after':
+          metadata = this._waitOperations.get(info.waitId)!;
+          this._waitOperations.delete(info.waitId);
+          break;
+      }
+    }
+
+    const recorder = await this._recorders.get(sdkObject.attribution.context);
     await recorder?.onAfterCall(metadata);
   }
 
   async onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
-    if (!sdkObject.attribution.page)
+    if (!sdkObject.attribution.context)
       return;
-    const recorder = await this._recorders.get(sdkObject.attribution.context!);
+    const recorder = await this._recorders.get(sdkObject.attribution.context);
     await recorder?.onBeforeInputAction(metadata);
   }
 
   async onCallLog(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
     debugLogger.log(logName as any, message);
-    if (!sdkObject.attribution.page)
+    if (!sdkObject.attribution.context)
       return;
-    const recorder = await this._recorders.get(sdkObject.attribution.context!);
+    const recorder = await this._recorders.get(sdkObject.attribution.context);
     await recorder?.updateCallLog([metadata]);
   }
 }