From 6576bd8b313d94567f758aa2ec9211113d6ff3e6 Mon Sep 17 00:00:00 2001 From: Pavel Feldman Date: Wed, 10 Feb 2021 21:55:46 -0800 Subject: [PATCH] chore: move before/after action instrumentation into dispatcher (#5416) --- src/client/waiter.ts | 2 +- src/dispatchers/dispatcher.ts | 58 ++++++++++++++----- src/server/dom.ts | 12 ++-- src/server/frames.ts | 2 +- src/server/instrumentation.ts | 18 ++++-- src/server/progress.ts | 39 ++++--------- src/server/supplements/inspectorController.ts | 2 +- src/trace/tracer.ts | 16 +++-- test/page-keyboard.spec.ts | 2 +- 9 files changed, 88 insertions(+), 63 deletions(-) diff --git a/src/client/waiter.ts b/src/client/waiter.ts index 0cd0497661..8a8d5d4123 100644 --- a/src/client/waiter.ts +++ b/src/client/waiter.ts @@ -101,7 +101,7 @@ function waitForTimeout(timeout: number): { promise: Promise, dispose: () return { promise, dispose }; } -const kLoggingNote = `\nNote: use DEBUG=pw:api environment variable and rerun to capture Playwright logs.`; +const kLoggingNote = `\nNote: use DEBUG=pw:api environment variable to capture Playwright logs.`; function formatLogRecording(log: string[]): string { if (!log.length) diff --git a/src/dispatchers/dispatcher.ts b/src/dispatchers/dispatcher.ts index 84eda62e83..333a05b731 100644 --- a/src/dispatchers/dispatcher.ts +++ b/src/dispatchers/dispatcher.ts @@ -21,8 +21,9 @@ import { createScheme, Validator, ValidationError } from '../protocol/validator' import { assert, createGuid, debugAssert, isUnderTest, monotonicTime } from '../utils/utils'; import { tOptional } from '../protocol/validatorPrimitives'; import { kBrowserOrContextClosedError } from '../utils/errors'; -import { CallMetadata } from '../server/instrumentation'; +import { CallMetadata, SdkObject } from '../server/instrumentation'; import { StackFrame } from '../common/types'; +import { rewriteErrorMessage } from '../utils/stackTrace'; export const dispatcherSymbol = Symbol('dispatcher'); @@ -175,23 +176,42 @@ export class DispatcherConnection { this.onmessage({ id, result: this._rootDispatcher._debugScopeState() }); return; } + + let validParams: any; + let validMetadata: channels.Metadata; try { - const validated = this._validateParams(dispatcher._type, method, params); + validParams = this._validateParams(dispatcher._type, method, params); + validMetadata = this._validateMetadata(metadata); if (typeof (dispatcher as any)[method] !== 'function') throw new Error(`Mismatching dispatcher: "${dispatcher._type}" does not implement "${method}"`); - const callMetadata: CallMetadata = { - ...this._validateMetadata(metadata), - startTime: monotonicTime(), - endTime: 0, - type: dispatcher._type, - method, - params, - log: [], - }; - const result = await (dispatcher as any)[method](validated, callMetadata); - this.onmessage({ id, result: this._replaceDispatchersWithGuids(result) }); } catch (e) { this.onmessage({ id, error: serializeError(e) }); + return; + } + + const callMetadata: CallMetadata = { + ...validMetadata, + startTime: monotonicTime(), + endTime: 0, + type: dispatcher._type, + method, + params, + log: [], + }; + + try { + if (dispatcher instanceof SdkObject) + await dispatcher.instrumentation.onBeforeCall(dispatcher, callMetadata); + const result = await (dispatcher as any)[method](validParams, callMetadata); + this.onmessage({ id, result: this._replaceDispatchersWithGuids(result) }); + } catch (e) { + // Dispatching error + if (callMetadata.log.length) + rewriteErrorMessage(e, e.message + formatLogRecording(callMetadata.log) + kLoggingNote); + this.onmessage({ id, error: serializeError(e) }); + } finally { + if (dispatcher instanceof SdkObject) + await dispatcher.instrumentation.onAfterCall(dispatcher, callMetadata); } } @@ -211,3 +231,15 @@ export class DispatcherConnection { return payload; } } + +const kLoggingNote = `\nNote: use DEBUG=pw:api environment variable to capture Playwright logs.`; + +function formatLogRecording(log: string[]): string { + if (!log.length) + return ''; + const header = ` logs `; + const headerLength = 60; + const leftLength = (headerLength - header.length) / 2; + const rightLength = headerLength - header.length - leftLength; + return `\n${'='.repeat(leftLength)}${header}${'='.repeat(rightLength)}\n${log.join('\n')}\n${'='.repeat(headerLength)}`; +} diff --git a/src/server/dom.ts b/src/server/dom.ts index 93418397c5..03719859c1 100644 --- a/src/server/dom.ts +++ b/src/server/dom.ts @@ -382,7 +382,7 @@ export class ElementHandle extends js.JSHandle { if (options && options.modifiers) restoreModifiers = await this._page.keyboard._ensureModifiers(options.modifiers); progress.log(` performing ${actionName} action`); - await progress.checkpoint('before'); + await progress.beforeInputAction(); await action(point); progress.log(` ${actionName} action done`); progress.log(' waiting for scheduled navigations to finish'); @@ -457,7 +457,7 @@ export class ElementHandle extends js.JSHandle { return this._page._frameManager.waitForSignalsCreatedBy(progress, options.noWaitAfter, async () => { progress.throwIfAborted(); // Avoid action that has side-effects. progress.log(' selecting specified option(s)'); - await progress.checkpoint('before'); + await progress.beforeInputAction(); const poll = await this._evaluateHandleInUtility(([injected, node, optionsToSelect]) => { return injected.waitForElementStatesAndPerformAction(node, ['visible', 'enabled'], injected.selectOptions.bind(injected, optionsToSelect)); }, optionsToSelect); @@ -489,7 +489,7 @@ export class ElementHandle extends js.JSHandle { if (filled === 'error:notconnected') return filled; progress.log(' element is visible, enabled and editable'); - await progress.checkpoint('before'); + await progress.beforeInputAction(); if (filled === 'needsinput') { progress.throwIfAborted(); // Avoid action that has side-effects. if (value) @@ -538,7 +538,7 @@ export class ElementHandle extends js.JSHandle { assert(multiple || files.length <= 1, 'Non-multiple file input can only accept single file!'); await this._page._frameManager.waitForSignalsCreatedBy(progress, options.noWaitAfter, async () => { progress.throwIfAborted(); // Avoid action that has side-effects. - await progress.checkpoint('before'); + await progress.beforeInputAction(); await this._page._delegate.setInputFiles(this as any as ElementHandle, files); }); await this._page._doSlowMo(); @@ -575,7 +575,7 @@ export class ElementHandle extends js.JSHandle { if (result !== 'done') return result; progress.throwIfAborted(); // Avoid action that has side-effects. - await progress.checkpoint('before'); + await progress.beforeInputAction(); await this._page.keyboard.type(text, options); return 'done'; }, 'input'); @@ -596,7 +596,7 @@ export class ElementHandle extends js.JSHandle { if (result !== 'done') return result; progress.throwIfAborted(); // Avoid action that has side-effects. - await progress.checkpoint('before'); + await progress.beforeInputAction(); await this._page.keyboard.press(key, options); return 'done'; }, 'input'); diff --git a/src/server/frames.ts b/src/server/frames.ts index 68ce46d652..18e59323d9 100644 --- a/src/server/frames.ts +++ b/src/server/frames.ts @@ -135,7 +135,7 @@ export class FrameManager { if (source === 'input') { await this._page._delegate.inputActionEpilogue(); if (progress) - await progress.checkpoint('after'); + await progress.afterInputAction(); } await barrier.waitFor(); this._signalBarriers.delete(barrier); diff --git a/src/server/instrumentation.ts b/src/server/instrumentation.ts index 50fbcd77c3..fbefbe8484 100644 --- a/src/server/instrumentation.ts +++ b/src/server/instrumentation.ts @@ -57,18 +57,24 @@ export interface Instrumentation { onContextCreated(context: BrowserContext): Promise; onContextWillDestroy(context: BrowserContext): Promise; onContextDidDestroy(context: BrowserContext): Promise; - onActionCheckpoint(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise; - onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise; - onLog(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void; + + onBeforeCall(sdkObject: SdkObject, metadata: CallMetadata): Promise; + onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise; + onAfterInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise; + onCallLog(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void; + onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise; } export interface InstrumentationListener { onContextCreated?(context: BrowserContext): Promise; onContextWillDestroy?(context: BrowserContext): Promise; onContextDidDestroy?(context: BrowserContext): Promise; - onActionCheckpoint?(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise; - onAfterAction?(sdkObject: SdkObject, metadata: CallMetadata): Promise; - onLog?(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void; + + onBeforeCall?(sdkObject: SdkObject, metadata: CallMetadata): Promise; + onBeforeInputAction?(sdkObject: SdkObject, metadata: CallMetadata): Promise; + onAfterInputAction?(sdkObject: SdkObject, metadata: CallMetadata): Promise; + onCallLog?(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void; + onAfterCall?(sdkObject: SdkObject, metadata: CallMetadata): Promise; } export function multiplexInstrumentation(listeners: InstrumentationListener[]): Instrumentation { diff --git a/src/server/progress.ts b/src/server/progress.ts index e2f849c4c7..f20aee2c9c 100644 --- a/src/server/progress.ts +++ b/src/server/progress.ts @@ -16,7 +16,6 @@ import { TimeoutError } from '../utils/errors'; import { assert, monotonicTime } from '../utils/utils'; -import { rewriteErrorMessage } from '../utils/stackTrace'; import { LogName } from '../utils/debugLogger'; import { CallMetadata, Instrumentation, SdkObject } from './instrumentation'; @@ -26,7 +25,8 @@ export interface Progress { isRunning(): boolean; cleanupWhenAborted(cleanup: () => any): void; throwIfAborted(): void; - checkpoint(name: string): Promise; + beforeInputAction(): Promise; + afterInputAction(): Promise; } export class ProgressController { @@ -71,7 +71,7 @@ export class ProgressController { log: message => { if (this._state === 'running') { this.metadata.log.push(message); - this.instrumentation.onLog(this._logName, message, this.sdkObject, this.metadata); + this.instrumentation.onCallLog(this._logName, message, this.sdkObject, this.metadata); } }, timeUntilDeadline: () => this._deadline ? this._deadline - monotonicTime() : 2147483647, // 2^31-1 safe setTimeout in Node. @@ -86,8 +86,11 @@ export class ProgressController { if (this._state === 'aborted') throw new AbortedError(); }, - checkpoint: async (name: string) => { - await this.instrumentation.onActionCheckpoint(name, this.sdkObject, this.metadata); + beforeInputAction: async () => { + await this.instrumentation.onBeforeInputAction(this.sdkObject, this.metadata); + }, + afterInputAction: async () => { + await this.instrumentation.onAfterInputAction(this.sdkObject, this.metadata); }, }; @@ -96,23 +99,15 @@ export class ProgressController { try { const promise = task(progress); const result = await Promise.race([promise, this._forceAbortPromise]); - clearTimeout(timer); this._state = 'finished'; - this.metadata.endTime = monotonicTime(); - await this.instrumentation.onAfterAction(this.sdkObject, this.metadata); return result; } catch (e) { - clearTimeout(timer); this._state = 'aborted'; await Promise.all(this._cleanups.splice(0).map(cleanup => runCleanup(cleanup))); - this.metadata.endTime = monotonicTime(); - this.metadata.error = e; - await this.instrumentation.onAfterAction(this.sdkObject, this.metadata); - rewriteErrorMessage(e, - e.message + - formatLogRecording(this.metadata.log) + - kLoggingNote); throw e; + } finally { + clearTimeout(timer); + this.metadata.endTime = monotonicTime(); } } @@ -128,16 +123,4 @@ async function runCleanup(cleanup: () => any) { } } -const kLoggingNote = `\nNote: use DEBUG=pw:api environment variable and rerun to capture Playwright logs.`; - -function formatLogRecording(log: string[]): string { - if (!log.length) - return ''; - const header = ` logs `; - const headerLength = 60; - const leftLength = (headerLength - header.length) / 2; - const rightLength = headerLength - header.length - leftLength; - return `\n${'='.repeat(leftLength)}${header}${'='.repeat(rightLength)}\n${log.join('\n')}\n${'='.repeat(headerLength)}`; -} - class AbortedError extends Error {} diff --git a/src/server/supplements/inspectorController.ts b/src/server/supplements/inspectorController.ts index 916fb28713..6926ba3b47 100644 --- a/src/server/supplements/inspectorController.ts +++ b/src/server/supplements/inspectorController.ts @@ -30,7 +30,7 @@ export class InspectorController implements InstrumentationListener { } } - onLog(logName: string, message: string): void { + onCallLog(logName: string, message: string): void { debugLogger.log(logName as any, message); } } diff --git a/src/trace/tracer.ts b/src/trace/tracer.ts index 41eee3acff..0c6600756b 100644 --- a/src/trace/tracer.ts +++ b/src/trace/tracer.ts @@ -55,19 +55,23 @@ export class Tracer implements InstrumentationListener { } } - async onActionCheckpoint(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise { - this._contextTracers.get(sdkObject.attribution.context!)?.onActionCheckpoint(name, sdkObject, metadata); + async onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise { + this._contextTracers.get(sdkObject.attribution.context!)?.onActionCheckpoint('before', sdkObject, metadata); } - async onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise { - this._contextTracers.get(sdkObject.attribution.context!)?.onAfterAction(sdkObject, metadata); + async onAfterInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise { + this._contextTracers.get(sdkObject.attribution.context!)?.onActionCheckpoint('after', sdkObject, metadata); + } + + async onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise { + this._contextTracers.get(sdkObject.attribution.context!)?.onAfterCall(sdkObject, metadata); } } const pageIdSymbol = Symbol('pageId'); const snapshotsSymbol = Symbol('snapshots'); -// TODO: this is a hacky way to pass snapshots between onActionCheckpoint and onAfterAction. +// This is an official way to pass snapshots between onBefore/AfterInputAction and onAfterCall. function snapshotsForMetadata(metadata: CallMetadata): { name: string, snapshotId: string }[] { if (!(metadata as any)[snapshotsSymbol]) (metadata as any)[snapshotsSymbol] = []; @@ -160,7 +164,7 @@ class ContextTracer implements SnapshotterDelegate { await this._snapshotter.forceSnapshot(sdkObject.attribution.page, snapshotId); } - async onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise { + async onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise { if (!sdkObject.attribution.page) return; const event: trace.ActionTraceEvent = { diff --git a/test/page-keyboard.spec.ts b/test/page-keyboard.spec.ts index 9c31bb94a7..8bc77bf5f3 100644 --- a/test/page-keyboard.spec.ts +++ b/test/page-keyboard.spec.ts @@ -288,7 +288,7 @@ it('should press Enter', async ({page, server}) => { it('should throw on unknown keys', async ({page, server}) => { let error = await page.keyboard.press('NotARealKey').catch(e => e); - expect(error.message).toBe('Unknown key: "NotARealKey"'); + expect(error.message).toContain('Unknown key: "NotARealKey"'); error = await page.keyboard.press('ё').catch(e => e); expect(error && error.message).toBe('Unknown key: "ё"');