feat(tracing): trace actions (#3825)

- Fill and click actions pass metadata to Progress.
- Progress reports success/failure through instrumentation.
- Tracer consumes ActionResult and ActionMetadata and records them.

Currently, only click and fill actions pass metadata to
contain the size of the change. Everything else should follow.

src/debug/debugController.ts

@@ -17,8 +17,7 @@
 import { BrowserContext } from '../server/browserContext';
 import * as frames from '../server/frames';
 import { Page } from '../server/page';
-import { InstrumentingAgent } from '../server/instrumentation';
-import { Progress } from '../server/progress';
+import { ActionMetadata, ActionResult, InstrumentingAgent } from '../server/instrumentation';
 import { isDebugMode } from '../utils/utils';
 import * as debugScriptSource from '../generated/debugScriptSource';
 
@@ -43,6 +42,6 @@ export class DebugController implements InstrumentingAgent {
   async onContextDestroyed(context: BrowserContext): Promise<void> {
   }
 
-  async onBeforePageAction(page: Page, progress: Progress): Promise<void> {
+  async onAfterAction(result: ActionResult, metadata?: ActionMetadata): Promise<void> {
   }
 }

src/dispatchers/elementHandlerDispatcher.ts

@@ -20,6 +20,8 @@ import * as channels from '../protocol/channels';
 import { DispatcherScope, lookupNullableDispatcher } from './dispatcher';
 import { JSHandleDispatcher, serializeResult, parseArgument } from './jsHandleDispatcher';
 import { FrameDispatcher } from './frameDispatcher';
+import { runAbortableTask } from '../server/progress';
+import { ActionMetadata } from '../server/instrumentation';
 
 export function createHandle(scope: DispatcherScope, handle: js.JSHandle): JSHandleDispatcher {
   return handle.asElement() ? new ElementHandleDispatcher(scope, handle.asElement()!) : new JSHandleDispatcher(scope, handle);
@@ -77,8 +79,11 @@ export class ElementHandleDispatcher extends JSHandleDispatcher implements chann
     await this._elementHandle.hover(params);
   }
 
-  async click(params: channels.ElementHandleClickParams): Promise<void> {
-    await this._elementHandle.click(params);
+  async click(params: channels.ElementHandleClickParams, metadata?: channels.Metadata): Promise<void> {
+    const clickMetadata: ActionMetadata = { ...metadata, type: 'click', target: this._elementHandle, page: this._elementHandle._page };
+    return runAbortableTask(async progress => {
+      return await this._elementHandle.click(progress, params);
+    }, this._elementHandle._page._timeoutSettings.timeout(params), clickMetadata);
   }
 
   async dblclick(params: channels.ElementHandleDblclickParams): Promise<void> {
@@ -90,8 +95,11 @@ export class ElementHandleDispatcher extends JSHandleDispatcher implements chann
     return { values: await this._elementHandle.selectOption(elements, params.options || [], params) };
   }
 
-  async fill(params: channels.ElementHandleFillParams): Promise<void> {
-    await this._elementHandle.fill(params.value, params);
+  async fill(params: channels.ElementHandleFillParams, metadata?: channels.Metadata): Promise<void> {
+    const fillMetadata: ActionMetadata = { ...metadata, type: 'fill', value: params.value, target: this._elementHandle, page: this._elementHandle._page };
+    return runAbortableTask(async progress => {
+      return await this._elementHandle.fill(progress, params.value, params);
+    }, this._elementHandle._page._timeoutSettings.timeout(params), fillMetadata);
   }
 
   async selectText(params: channels.ElementHandleSelectTextParams): Promise<void> {

src/dispatchers/frameDispatcher.ts

@@ -20,6 +20,8 @@ import { Dispatcher, DispatcherScope, lookupNullableDispatcher, existingDispatch
 import { ElementHandleDispatcher, createHandle } from './elementHandlerDispatcher';
 import { parseArgument, serializeResult } from './jsHandleDispatcher';
 import { ResponseDispatcher, RequestDispatcher } from './networkDispatchers';
+import { ActionMetadata } from '../server/instrumentation';
+import { runAbortableTask } from '../server/progress';
 
 export class FrameDispatcher extends Dispatcher<Frame, channels.FrameInitializer> implements channels.FrameChannel {
   private _frame: Frame;
@@ -108,16 +110,22 @@ export class FrameDispatcher extends Dispatcher<Frame, channels.FrameInitializer
     return { element: new ElementHandleDispatcher(this._scope, await this._frame.addStyleTag(params)) };
   }
 
-  async click(params: channels.FrameClickParams): Promise<void> {
-    await this._frame.click(params.selector, params);
+  async click(params: channels.FrameClickParams, metadata?: channels.Metadata): Promise<void> {
+    const clickMetadata: ActionMetadata = { ...metadata, type: 'click', target: params.selector, page: this._frame._page };
+    await runAbortableTask(async progress => {
+      return await this._frame.click(progress, params.selector, params);
+    }, this._frame._page._timeoutSettings.timeout(params), clickMetadata);
   }
 
   async dblclick(params: channels.FrameDblclickParams): Promise<void> {
     await this._frame.dblclick(params.selector, params);
   }
 
-  async fill(params: channels.FrameFillParams): Promise<void> {
-    await this._frame.fill(params.selector, params.value, params);
+  async fill(params: channels.FrameFillParams, metadata?: channels.Metadata): Promise<void> {
+    const fillMetadata: ActionMetadata = { ...metadata, type: 'fill', value: params.value, target: params.selector, page: this._frame._page };
+    await runAbortableTask(async progress => {
+      return await this._frame.fill(progress, params.selector, params.value, params);
+    }, this._frame._page._timeoutSettings.timeout(params), fillMetadata);
   }
 
   async focus(params: channels.FrameFocusParams): Promise<void> {

src/server/dom.ts

@@ -99,18 +99,20 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
   readonly _context: FrameExecutionContext;
   readonly _page: Page;
   readonly _objectId: string;
+  readonly _previewPromise: Promise<string>;
 
   constructor(context: FrameExecutionContext, objectId: string) {
     super(context, 'node', objectId);
     this._objectId = objectId;
     this._context = context;
     this._page = context.frame._page;
-    this._initializePreview().catch(e => {});
+    this._previewPromise = this._initializePreview().catch(e => 'node');
+    this._previewPromise.then(preview => this._setPreview('JSHandle@' + preview));
   }
 
   async _initializePreview() {
     const utility = await this._context.injectedScript();
-    this._setPreview(await utility.evaluate((injected, e) => 'JSHandle@' + injected.previewNode(e), this));
+    return utility.evaluate((injected, e) => injected.previewNode(e), this);
   }
 
   asElement(): ElementHandle<T> | null {
@@ -367,11 +369,9 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
     return this._retryPointerAction(progress, 'hover', false /* waitForEnabled */, point => this._page.mouse.move(point.x, point.y), options);
   }
 
-  click(options: types.MouseClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise<void> {
-    return this._page._runAbortableTask(async progress => {
-      const result = await this._click(progress, options);
-      return assertDone(throwRetargetableDOMError(result));
-    }, this._page._timeoutSettings.timeout(options));
+  async click(progress: Progress, options: types.MouseClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}): Promise<void> {
+    const result = await this._click(progress, options);
+    return assertDone(throwRetargetableDOMError(result));
   }
 
   _click(progress: Progress, options: types.MouseClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions): Promise<'error:notconnected' | 'done'> {
@@ -406,11 +406,9 @@ export class ElementHandle<T extends Node = Node> extends js.JSHandle<T> {
     });
   }
 
-  async fill(value: string, options: types.NavigatingActionWaitOptions = {}): Promise<void> {
-    return this._page._runAbortableTask(async progress => {
-      const result = await this._fill(progress, value, options);
-      assertDone(throwRetargetableDOMError(result));
-    }, this._page._timeoutSettings.timeout(options));
+  async fill(progress: Progress, value: string, options: types.NavigatingActionWaitOptions = {}): Promise<void> {
+    const result = await this._fill(progress, value, options);
+    assertDone(throwRetargetableDOMError(result));
   }
 
   async _fill(progress: Progress, value: string, options: types.NavigatingActionWaitOptions): Promise<'error:notconnected' | 'done'> {

src/server/frames.ts

@@ -770,43 +770,50 @@ export class Frame extends EventEmitter {
     return result!;
   }
 
+  private async _retryWithProgressIfNotConnected<R>(
+    progress: Progress,
+    selector: string,
+    action: (handle: dom.ElementHandle<Element>) => Promise<R | 'error:notconnected'>): Promise<R> {
+    const info = this._page.selectors._parseSelector(selector);
+    while (progress.isRunning()) {
+      progress.log(`waiting for selector "${selector}"`);
+      const task = dom.waitForSelectorTask(info, 'attached');
+      const handle = await this._scheduleRerunnableHandleTask(progress, info.world, task);
+      const element = handle.asElement() as dom.ElementHandle<Element>;
+      progress.cleanupWhenAborted(() => {
+        // Do not await here to avoid being blocked, either by stalled
+        // page (e.g. alert) or unresolved navigation in Chromium.
+        element.dispose();
+      });
+      const result = await action(element);
+      element.dispose();
+      if (result === 'error:notconnected') {
+        progress.log('element was detached from the DOM, retrying');
+        continue;
+      }
+      return result;
+    }
+    return undefined as any;
+  }
+
   private async _retryWithSelectorIfNotConnected<R>(
     selector: string, options: types.TimeoutOptions,
     action: (progress: Progress, handle: dom.ElementHandle<Element>) => Promise<R | 'error:notconnected'>): Promise<R> {
-    const info = this._page.selectors._parseSelector(selector);
     return this._page._runAbortableTask(async progress => {
-      while (progress.isRunning()) {
-        progress.log(`waiting for selector "${selector}"`);
-        const task = dom.waitForSelectorTask(info, 'attached');
-        const handle = await this._scheduleRerunnableHandleTask(progress, info.world, task);
-        const element = handle.asElement() as dom.ElementHandle<Element>;
-        progress.cleanupWhenAborted(() => {
-          // Do not await here to avoid being blocked, either by stalled
-          // page (e.g. alert) or unresolved navigation in Chromium.
-          element.dispose();
-        });
-        const result = await action(progress, element);
-        element.dispose();
-        if (result === 'error:notconnected') {
-          progress.log('element was detached from the DOM, retrying');
-          continue;
-        }
-        return result;
-      }
-      return undefined as any;
+      return this._retryWithProgressIfNotConnected(progress, selector, handle => action(progress, handle));
     }, this._page._timeoutSettings.timeout(options));
   }
 
-  async click(selector: string, options: types.MouseClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._click(progress, options));
+  async click(progress: Progress, selector: string, options: types.MouseClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions) {
+    return this._retryWithProgressIfNotConnected(progress, selector, handle => handle._click(progress, options));
   }
 
   async dblclick(selector: string, options: types.MouseMultiClickOptions & types.PointerActionWaitOptions & types.NavigatingActionWaitOptions = {}) {
     await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._dblclick(progress, options));
   }
 
-  async fill(selector: string, value: string, options: types.NavigatingActionWaitOptions = {}) {
-    await this._retryWithSelectorIfNotConnected(selector, options, (progress, handle) => handle._fill(progress, value, options));
+  async fill(progress: Progress, selector: string, value: string, options: types.NavigatingActionWaitOptions) {
+    return this._retryWithProgressIfNotConnected(progress, selector, handle => handle._fill(progress, value, options));
   }
 
   async focus(selector: string, options: types.TimeoutOptions = {}) {

src/server/instrumentation.ts

@@ -14,14 +14,29 @@
  * limitations under the License.
  */
 
-import { BrowserContext } from './browserContext';
-import { Page } from './page';
-import { Progress } from './progress';
+import type { BrowserContext } from './browserContext';
+import type { ElementHandle } from './dom';
+import type { Page } from './page';
+
+export type ActionMetadata = {
+  type: 'click' | 'fill',
+  page: Page,
+  target: ElementHandle | string,
+  value?: string,
+  stack?: string,
+};
+
+export type ActionResult = {
+  logs: string[],
+  startTime: number,
+  endTime: number,
+  error?: Error,
+};
 
 export interface InstrumentingAgent {
   onContextCreated(context: BrowserContext): Promise<void>;
   onContextDestroyed(context: BrowserContext): Promise<void>;
-  onBeforePageAction(page: Page, progress: Progress): Promise<void>;
+  onAfterAction(result: ActionResult, metadata?: ActionMetadata): Promise<void>;
 }
 
 export const instrumentingAgents = new Set<InstrumentingAgent>();

src/server/page.ts

@@ -32,7 +32,6 @@ import { Progress, runAbortableTask } from './progress';
 import { assert, isError } from '../utils/utils';
 import { debugLogger } from '../utils/debugLogger';
 import { Selectors } from './selectors';
-import { instrumentingAgents } from './instrumentation';
 
 export interface PageDelegate {
   readonly rawMouse: input.RawMouse;
@@ -200,11 +199,7 @@ export class Page extends EventEmitter {
   }
 
   async _runAbortableTask<T>(task: (progress: Progress) => Promise<T>, timeout: number): Promise<T> {
-    return runAbortableTask(async progress => {
-      for (const agent of instrumentingAgents)
-        await agent.onBeforePageAction(this, progress);
-      return task(progress);
-    }, timeout);
+    return runAbortableTask(task, timeout);
   }
 
   async _onFileChooserOpened(handle: dom.ElementHandle) {

src/server/progress.ts

@@ -18,6 +18,7 @@ import { TimeoutError } from '../utils/errors';
 import { assert, monotonicTime } from '../utils/utils';
 import { rewriteErrorMessage } from '../utils/stackTrace';
 import { debugLogger, LogName } from '../utils/debugLogger';
+import { ActionResult, instrumentingAgents, ActionMetadata } from './instrumentation';
 
 export interface Progress {
   readonly aborted: Promise<void>;
@@ -28,8 +29,8 @@ export interface Progress {
   throwIfAborted(): void;
 }
 
-export async function runAbortableTask<T>(task: (progress: Progress) => Promise<T>, timeout: number): Promise<T> {
-  const controller = new ProgressController(timeout);
+export async function runAbortableTask<T>(task: (progress: Progress) => Promise<T>, timeout: number, metadata?: ActionMetadata): Promise<T> {
+  const controller = new ProgressController(timeout, metadata);
   return controller.run(task);
 }
 
@@ -47,15 +48,17 @@ export class ProgressController {
   // Cleanups to be run only in the case of abort.
   private _cleanups: (() => any)[] = [];
 
+  private _metadata?: ActionMetadata;
   private _logName: LogName = 'api';
   private _state: 'before' | 'running' | 'aborted' | 'finished' = 'before';
   private _deadline: number;
   private _timeout: number;
   private _logRecordring: string[] = [];
 
-  constructor(timeout: number) {
+  constructor(timeout: number, metadata?: ActionMetadata) {
     this._timeout = timeout;
     this._deadline = timeout ? monotonicTime() + timeout : 0;
+    this._metadata = metadata;
 
     this._forceAbortPromise = new Promise((resolve, reject) => this._forceAbort = reject);
     this._forceAbortPromise.catch(e => null);  // Prevent unhandle promsie rejection.
@@ -93,11 +96,19 @@ export class ProgressController {
 
     const timeoutError = new TimeoutError(`Timeout ${this._timeout}ms exceeded.`);
     const timer = setTimeout(() => this._forceAbort(timeoutError), progress.timeUntilDeadline());
+    const startTime = monotonicTime();
     try {
       const promise = task(progress);
       const result = await Promise.race([promise, this._forceAbortPromise]);
       clearTimeout(timer);
       this._state = 'finished';
+      const actionResult: ActionResult = {
+        startTime,
+        endTime: monotonicTime(),
+        logs: this._logRecordring,
+      };
+      for (const agent of instrumentingAgents)
+        await agent.onAfterAction(actionResult, this._metadata);
       this._logRecordring = [];
       return result;
     } catch (e) {
@@ -108,8 +119,16 @@ export class ProgressController {
           kLoggingNote);
       clearTimeout(timer);
       this._state = 'aborted';
-      this._logRecordring = [];
       await Promise.all(this._cleanups.splice(0).map(cleanup => runCleanup(cleanup)));
+      const actionResult: ActionResult = {
+        startTime,
+        endTime: monotonicTime(),
+        logs: this._logRecordring,
+        error: e,
+      };
+      for (const agent of instrumentingAgents)
+        await agent.onAfterAction(actionResult, this._metadata);
+      this._logRecordring = [];
       throw e;
     }
   }

src/trace/snapshotter.ts

@@ -45,7 +45,6 @@ export type FrameSnapshot = {
   resourceOverrides: { url: string, sha1: string }[],
 };
 export type PageSnapshot = {
-  label: string,
   viewportSize?: { width: number, height: number },
   // First frame is the main frame.
   frames: FrameSnapshot[],
@@ -54,7 +53,6 @@ export type PageSnapshot = {
 export interface SnapshotterDelegate {
   onBlob(blob: SnapshotterBlob): void;
   onResource(resource: SanpshotterResource): void;
-  onSnapshot(snapshot: PageSnapshot): void;
 }
 
 export class Snapshotter {
@@ -74,13 +72,6 @@ export class Snapshotter {
     helper.removeEventListeners(this._eventListeners);
   }
 
-  async takeSnapshot(progress: Progress, page: Page, label: string): Promise<void> {
-    assert(page.context() === this._context);
-    const snapshot = await this._snapshotPage(progress, page, label);
-    if (snapshot)
-      this._delegate.onSnapshot(snapshot);
-  }
-
   private _onPage(page: Page) {
     this._eventListeners.push(helper.addEventListener(page, Page.Events.Response, (response: network.Response) => {
       this._saveResource(response).catch(e => debugLogger.log('error', e));
@@ -118,7 +109,9 @@ export class Snapshotter {
       this._delegate.onBlob({ sha1, buffer: body });
   }
 
-  private async _snapshotPage(progress: Progress, page: Page, label: string): Promise<PageSnapshot | null> {
+  async takeSnapshot(progress: Progress, page: Page): Promise<PageSnapshot | null> {
+    assert(page.context() === this._context);
+
     const frames = page.frames();
     const promises = frames.map(frame => this._snapshotFrame(progress, frame));
     const results = await Promise.all(promises);
@@ -169,7 +162,6 @@ export class Snapshotter {
     }
 
     return {
-      label,
       viewportSize,
       frames: [mainFrame.snapshot, ...childFrames],
     };