chore: move before/after action instrumentation into dispatcher (#5416)

src/client/waiter.ts

@@ -101,7 +101,7 @@ function waitForTimeout(timeout: number): { promise: Promise<void>, 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)

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)}`;
+}

src/server/dom.ts

@@ -382,7 +382,7 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
       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<T extends Node = Node> extends js.JSHandle<T> {
     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<T extends Node = Node> extends js.JSHandle<T> {
       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<T extends Node = Node> extends js.JSHandle<T> {
     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<HTMLInputElement>, files);
     });
     await this._page._doSlowMo();
@@ -575,7 +575,7 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
       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<T extends Node = Node> extends js.JSHandle<T> {
       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');

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);

src/server/instrumentation.ts

@@ -57,18 +57,24 @@ export interface Instrumentation {
   onContextCreated(context: BrowserContext): Promise<void>;
   onContextWillDestroy(context: BrowserContext): Promise<void>;
   onContextDidDestroy(context: BrowserContext): Promise<void>;
-  onActionCheckpoint(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+
-  onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  onBeforeCall(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
-  onLog(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void;
+  onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  onAfterInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  onCallLog(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void;
+  onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
 }
 
 export interface InstrumentationListener {
   onContextCreated?(context: BrowserContext): Promise<void>;
   onContextWillDestroy?(context: BrowserContext): Promise<void>;
   onContextDidDestroy?(context: BrowserContext): Promise<void>;
-  onActionCheckpoint?(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+
-  onAfterAction?(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  onBeforeCall?(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
-  onLog?(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void;
+  onBeforeInputAction?(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  onAfterInputAction?(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
+  onCallLog?(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void;
+  onAfterCall?(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
 }
 
 export function multiplexInstrumentation(listeners: InstrumentationListener[]): Instrumentation {

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<void>;
+  beforeInputAction(): Promise<void>;
+  afterInputAction(): Promise<void>;
 }
 
 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) => {
+      beforeInputAction: async () => {
-        await this.instrumentation.onActionCheckpoint(name, this.sdkObject, this.metadata);
+        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 {}

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);
   }
 }

src/trace/tracer.ts

@@ -55,19 +55,23 @@ export class Tracer implements InstrumentationListener {
     }
   }
 
-  async onActionCheckpoint(name: string, sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
+  async onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
-    this._contextTracers.get(sdkObject.attribution.context!)?.onActionCheckpoint(name, sdkObject, metadata);
+    this._contextTracers.get(sdkObject.attribution.context!)?.onActionCheckpoint('before', sdkObject, metadata);
   }
 
-  async onAfterAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
+  async onAfterInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
-    this._contextTracers.get(sdkObject.attribution.context!)?.onAfterAction(sdkObject, metadata);
+    this._contextTracers.get(sdkObject.attribution.context!)?.onActionCheckpoint('after', sdkObject, metadata);
+  }
+
+  async onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
+    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<void> {
+  async onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
     if (!sdkObject.attribution.page)
       return;
     const event: trace.ActionTraceEvent = {

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: "ё"');