From ae2ffb3fb93deb80d5f6df16fba806be4ffa7630 Mon Sep 17 00:00:00 2001 From: Pavel Feldman Date: Sat, 13 Feb 2021 20:31:06 -0800 Subject: [PATCH] feat(inspector): instrument wait for event (#5457) --- src/client/android.ts | 2 +- src/client/browserContext.ts | 2 +- src/client/channelOwner.ts | 13 ++++++ src/client/connection.ts | 2 +- src/client/electron.ts | 2 +- src/client/frame.ts | 9 ++-- src/client/network.ts | 2 +- src/client/page.ts | 2 +- src/client/waiter.ts | 26 +++++++++-- src/dispatchers/dispatcher.ts | 6 +++ src/protocol/channels.ts | 23 +++++++--- src/protocol/protocol.yml | 34 +++++++++++--- src/protocol/validator.ts | 21 ++++++--- src/server/supplements/inspectorController.ts | 46 +++++++++++++++++-- 14 files changed, 151 insertions(+), 39 deletions(-) diff --git a/src/client/android.ts b/src/client/android.ts index a9fddb07d5351..337c76e29b4ab 100644 --- a/src/client/android.ts +++ b/src/client/android.ts @@ -239,7 +239,7 @@ export class AndroidDevice extends ChannelOwner { 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')); diff --git a/src/client/browserContext.ts b/src/client/browserContext.ts index 1dd1f3fc53924..fe4278b50a1c3 100644 --- a/src/client/browserContext.ts +++ b/src/client/browserContext.ts @@ -217,7 +217,7 @@ export class BrowserContext extends ChannelOwner { 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')); diff --git a/src/client/channelOwner.ts b/src/client/channelOwner.ts index 71a9ffd916eab..ae21b9df4308a 100644 --- a/src/client/channelOwner.ts +++ b/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 extends EventEmitter { private _connection: Connection; @@ -97,6 +98,18 @@ export abstract class ChannelOwner {}); + } + + _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, diff --git a/src/client/connection.ts b/src/client/connection.ts index 7cb99100c40df..6a70f44ed9bc9 100644 --- a/src/client/connection.ts +++ b/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; } diff --git a/src/client/electron.ts b/src/client/electron.ts index eac33bc7dd2f8..216223a641b75 100644 --- a/src/client/electron.ts +++ b/src/client/electron.ts @@ -101,7 +101,7 @@ export class ElectronApplication extends ChannelOwner { 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')); diff --git a/src/client/frame.ts b/src/client/frame.ts index 5b74d593a7e72..42060b6300e11 100644 --- a/src/client/frame.ts +++ b/src/client/frame.ts @@ -100,21 +100,20 @@ export class Frame extends ChannelOwner(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 { 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 { - const waiter = this._setupNavigationWaiter(options); + const waiter = this._setupNavigationWaiter('waitForLoadState', options); await waiter.waitForEvent(this._eventEmitter, 'loadstate', s => { waiter.log(` "${s}" event fired`); return s === state; diff --git a/src/client/network.ts b/src/client/network.ts index c1378d7913f0d..d50f24c6da716 100644 --- a/src/client/network.ts +++ b/src/client/network.ts @@ -365,7 +365,7 @@ export class WebSocket extends ChannelOwner { 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')); diff --git a/src/client/page.ts b/src/client/page.ts index 948a8da3e2616..466082710579d 100644 --- a/src/client/page.ts +++ b/src/client/page.ts @@ -395,7 +395,7 @@ export class Page extends ChannelOwner { 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}"`); diff --git a/src/client/waiter.ts b/src/client/waiter.ts index 8a8d5d4123a1b..7dc038577c380 100644 --- a/src/client/waiter.ts +++ b/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[] = []; // 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(emitter: EventEmitter, event: string, predicate?: (arg: T) => boolean): Promise { 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, dispose?: () => void) { diff --git a/src/dispatchers/dispatcher.ts b/src/dispatchers/dispatcher.ts index 37f16a1eb2760..eb9cfe9586f01 100644 --- a/src/dispatchers/dispatcher.ts +++ b/src/dispatchers/dispatcher.ts @@ -112,6 +112,10 @@ export class Dispatcher extends EventEmitter implements chann objects: Array.from(this._dispatchers.values()).map(o => o._debugScopeState()), }; } + + async waitForEventInfo(): Promise { + // Instrumentation takes care of this. + } } export type DispatcherScope = Dispatcher; @@ -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}`); diff --git a/src/protocol/channels.ts b/src/protocol/channels.ts index f473baff54a1e..81d194e011308 100644 --- a/src/protocol/channels.ts +++ b/src/protocol/channels.ts @@ -23,13 +23,24 @@ export type Binary = string; export interface Channel extends EventEmitter { } +export type StackFrame = { + file: string, + line?: number, + column?: number, + function?: string, +}; + export type Metadata = { - stack?: { - file: string, - line?: number, - column?: number, - function?: string, - }[], + stack?: StackFrame[], +}; + +export type WaitForEventInfo = { + waitId: string, + phase: 'before' | 'after' | 'log', + name?: string, + stack?: StackFrame[], + message?: string, + error?: string, }; export type Point = { diff --git a/src/protocol/protocol.yml b/src/protocol/protocol.yml index 0cef00d25cd11..65279dcb83f3f 100644 --- a/src/protocol/protocol.yml +++ b/src/protocol/protocol.yml @@ -12,20 +12,40 @@ # See the License for the specific language governing permissions and # limitations under the License. +StackFrame: + type: object + properties: + file: string + line: number? + 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: - type: object - properties: - file: string - line: number? - column: number? - function: string? + 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: diff --git a/src/protocol/validator.ts b/src/protocol/validator.ts index 03c2f1e266794..5e10293a05c08 100644 --- a/src/protocol/validator.ts +++ b/src/protocol/validator.ts @@ -33,13 +33,22 @@ export function createScheme(tChannel: (name: string) => Validator): Scheme { }; }; + scheme.StackFrame = tObject({ + file: tString, + line: tOptional(tNumber), + column: tOptional(tNumber), + function: tOptional(tString), + }); scheme.Metadata = tObject({ - stack: tOptional(tArray(tObject({ - file: tString, - line: tOptional(tNumber), - column: tOptional(tNumber), - function: tOptional(tString), - }))), + 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, diff --git a/src/server/supplements/inspectorController.ts b/src/server/supplements/inspectorController.ts index b73948e99ba86..db0ca6f75dc6f 100644 --- a/src/server/supplements/inspectorController.ts +++ b/src/server/supplements/inspectorController.ts @@ -22,6 +22,7 @@ import { isDebugMode, isUnderTest } from '../../utils/utils'; export class InspectorController implements InstrumentationListener { private _recorders = new Map>(); + private _waitOperations = new Map(); async onContextCreated(context: BrowserContext): Promise { 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 { 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 { - 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 { 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]); } }