chore(tracing): include events in the trace (#6285)

src/dispatchers/dispatcher.ts

@@ -77,7 +77,7 @@ export class Dispatcher<Type extends { guid: string }, Initializer> extends Even
 
     (object as any)[dispatcherSymbol] = this;
     if (this._parent)
-      this._connection.sendMessageToClient(this._parent._guid, '__create__', { type, initializer, guid });
+      this._connection.sendMessageToClient(this._parent._guid, type, '__create__', { type, initializer, guid });
   }
 
   _dispatchEvent(method: string, params: Dispatcher<any, any> | any = {}) {
@@ -87,7 +87,8 @@ export class Dispatcher<Type extends { guid: string }, Initializer> extends Even
       // Just ignore this event outside of tests.
       return;
     }
-    this._connection.sendMessageToClient(this._guid, method, params);
+    const sdkObject = this._object instanceof SdkObject ? this._object : undefined;
+    this._connection.sendMessageToClient(this._guid, this._type, method, params, sdkObject);
   }
 
   _dispose() {
@@ -105,7 +106,7 @@ export class Dispatcher<Type extends { guid: string }, Initializer> extends Even
     this._dispatchers.clear();
 
     if (this._isScope)
-      this._connection.sendMessageToClient(this._guid, '__dispose__', {});
+      this._connection.sendMessageToClient(this._guid, this._type, '__dispose__', {});
   }
 
   _debugScopeState(): any {
@@ -135,8 +136,25 @@ export class DispatcherConnection {
   private _validateMetadata: (metadata: any) => { stack?: StackFrame[] };
   private _waitOperations = new Map<string, CallMetadata>();
 
-  sendMessageToClient(guid: string, method: string, params: any) {
+  sendMessageToClient(guid: string, type: string, method: string, params: any, sdkObject?: SdkObject) {
-    this.onmessage({ guid, method, params: this._replaceDispatchersWithGuids(params) });
+    params = this._replaceDispatchersWithGuids(params);
+    if (sdkObject) {
+      const eventMetadata: CallMetadata = {
+        id: `event@${++lastEventId}`,
+        objectId: sdkObject?.guid,
+        pageId: sdkObject?.attribution.page?.guid,
+        frameId: sdkObject?.attribution.frame?.guid,
+        startTime: monotonicTime(),
+        endTime: 0,
+        type,
+        method,
+        params: params || {},
+        log: [],
+        snapshots: []
+      };
+      sdkObject.instrumentation.onEvent(sdkObject, eventMetadata);
+    }
+    this.onmessage({ guid, method, params });
   }
 
   constructor() {
@@ -200,8 +218,9 @@ export class DispatcherConnection {
 
     const sdkObject = dispatcher._object instanceof SdkObject ? dispatcher._object : undefined;
     let callMetadata: CallMetadata = {
-      id,
+      id: `call@${id}`,
       ...validMetadata,
+      objectId: sdkObject?.guid,
       pageId: sdkObject?.attribution.page?.guid,
       frameId: sdkObject?.attribution.frame?.guid,
       startTime: monotonicTime(),
@@ -210,6 +229,7 @@ export class DispatcherConnection {
       method,
       params: params || {},
       log: [],
+      snapshots: []
     };
 
     try {
@@ -295,3 +315,5 @@ function formatLogRecording(log: string[]): string {
   const rightLength = headerLength - header.length - leftLength;
   return `\n${'='.repeat(leftLength)}${header}${'='.repeat(rightLength)}\n${log.join('\n')}\n${'='.repeat(headerLength)}`;
 }
+
+let lastEventId = 0;

src/server/frames.ts

@@ -132,11 +132,8 @@ export class FrameManager {
     if (progress)
       progress.cleanupWhenAborted(() => this._signalBarriers.delete(barrier));
     const result = await action();
-    if (source === 'input') {
+    if (source === 'input')
       await this._page._delegate.inputActionEpilogue();
-      if (progress)
-        await progress.afterInputAction();
-    }
     await barrier.waitFor();
     this._signalBarriers.delete(barrier);
     // Resolve in the next task, after all waitForNavigations.

src/server/instrumentation.ts

@@ -33,7 +33,7 @@ export type Attribution = {
 };
 
 export type CallMetadata = {
-  id: number;
+  id: string;
   startTime: number;
   endTime: number;
   pauseStartTime?: number;
@@ -44,8 +44,10 @@ export type CallMetadata = {
   apiName?: string;
   stack?: StackFrame[];
   log: string[];
+  snapshots: { title: string, snapshotName: string }[];
   error?: string;
   point?: Point;
+  objectId?: string;
   pageId?: string;
   frameId?: string;
 };
@@ -71,9 +73,10 @@ export interface Instrumentation {
 
   onBeforeCall(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
   onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata, element: ElementHandle): 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>;
+
+  onEvent(sdkObject: SdkObject, metadata: CallMetadata): void;
 }
 
 export interface InstrumentationListener {
@@ -83,9 +86,10 @@ export interface InstrumentationListener {
 
   onBeforeCall?(sdkObject: SdkObject, metadata: CallMetadata): Promise<void>;
   onBeforeInputAction?(sdkObject: SdkObject, metadata: CallMetadata, element: ElementHandle): 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>;
+
+  onEvent?(sdkObject: SdkObject, metadata: CallMetadata): void;
 }
 
 export function multiplexInstrumentation(listeners: InstrumentationListener[]): Instrumentation {
@@ -103,12 +107,13 @@ export function multiplexInstrumentation(listeners: InstrumentationListener[]):
 
 export function internalCallMetadata(): CallMetadata {
   return {
-    id: 0,
+    id: '',
     startTime: 0,
     endTime: 0,
     type: 'Internal',
     method: '',
     params: {},
     log: [],
+    snapshots: []
   };
 }

src/server/progress.ts

@@ -27,7 +27,6 @@ export interface Progress {
   cleanupWhenAborted(cleanup: () => any): void;
   throwIfAborted(): void;
   beforeInputAction(element: ElementHandle): Promise<void>;
-  afterInputAction(): Promise<void>;
   metadata: CallMetadata;
 }
 
@@ -91,9 +90,6 @@ export class ProgressController {
       beforeInputAction: async (element: ElementHandle) => {
         await this.instrumentation.onBeforeInputAction(this.sdkObject, this.metadata, element);
       },
-      afterInputAction: async () => {
-        await this.instrumentation.onAfterInputAction(this.sdkObject, this.metadata);
-      },
       metadata: this.metadata
     };
 

src/server/supplements/recorder/recorderTypes.ts

@@ -33,7 +33,7 @@ export type UIState = {
 export type CallLogStatus = 'in-progress' | 'done' | 'error' | 'paused';
 
 export type CallLog = {
-  id: number;
+  id: string;
   title: string;
   messages: string[];
   status: CallLogStatus;

src/server/supplements/recorderSupplement.ts

@@ -56,9 +56,9 @@ export class RecorderSupplement {
   private _recorderSources: Source[];
   private _userSources = new Map<string, Source>();
   private _snapshotter: InMemorySnapshotter;
-  private _hoveredSnapshot: { callLogId: number, phase: 'before' | 'after' | 'action' } | undefined;
+  private _hoveredSnapshot: { callLogId: string, phase: 'before' | 'after' | 'action' } | undefined;
   private _snapshots = new Set<string>();
-  private _allMetadatas = new Map<number, CallMetadata>();
+  private _allMetadatas = new Map<string, CallMetadata>();
   private _contextDebugger: ContextDebugger;
 
   static show(context: BrowserContext, params: channels.BrowserContextRecorderSupplementEnableParams = {}): Promise<RecorderSupplement> {

src/server/trace/common/traceEvents.ts

@@ -60,7 +60,7 @@ export type ScreencastFrameTraceEvent = {
 
 export type ActionTraceEvent = {
   timestamp: number,
-  type: 'action',
+  type: 'action' | 'event',
   contextId: string,
   metadata: CallMetadata,
   snapshots?: { title: string, snapshotName: string }[],

src/server/trace/recorder/tracer.ts

@@ -54,26 +54,20 @@ export class Tracer implements InstrumentationListener {
   }
 
   async onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata, element: ElementHandle): Promise<void> {
-    this._contextTracers.get(sdkObject.attribution.context!)?._captureSnapshot('action', sdkObject, metadata, element);
+    this._contextTracers.get(sdkObject.attribution.context!)?.onBeforeInputAction(sdkObject, metadata, element);
   }
 
-  async onBeforeCall(sdkObject: SdkObject, metadata: CallMetadata, element?: ElementHandle): Promise<void> {
+  async onBeforeCall(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
-    this._contextTracers.get(sdkObject.attribution.context!)?._captureSnapshot('before', sdkObject, metadata, element);
+    this._contextTracers.get(sdkObject.attribution.context!)?.onBeforeCall(sdkObject, metadata);
   }
 
   async onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
-    this._contextTracers.get(sdkObject.attribution.context!)?._captureSnapshot('after', sdkObject, metadata);
     this._contextTracers.get(sdkObject.attribution.context!)?.onAfterCall(sdkObject, metadata);
   }
-}
 
-const snapshotsSymbol = Symbol('snapshots');
+  async onEvent(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
-
+    this._contextTracers.get(sdkObject.attribution.context!)?.onEvent(sdkObject, metadata);
-// This is an official way to pass snapshots between onBefore/AfterInputAction and onAfterCall.
+  }
-function snapshotsForMetadata(metadata: CallMetadata): { title: string, snapshotName: string }[] {
-  if (!(metadata as any)[snapshotsSymbol])
-    (metadata as any)[snapshotsSymbol] = [];
-  return (metadata as any)[snapshotsSymbol];
 }
 
 class ContextTracer {
@@ -82,6 +76,7 @@ class ContextTracer {
   private _snapshotter: PersistentSnapshotter;
   private _eventListeners: RegisteredListener[];
   private _disposed = false;
+  private _pendingCalls = new Map<string, { sdkObject: SdkObject, metadata: CallMetadata }>();
 
   constructor(context: BrowserContext, resourcesDir: string, tracePrefix: string) {
     const traceFile = tracePrefix + '-actions.trace';
@@ -108,23 +103,45 @@ class ContextTracer {
     await this._snapshotter.start(false);
   }
 
-  async _captureSnapshot(name: 'before' | 'after' | 'action', sdkObject: SdkObject, metadata: CallMetadata, element?: ElementHandle): Promise<void> {
+  _captureSnapshot(name: 'before' | 'after' | 'action' | 'event', sdkObject: SdkObject, metadata: CallMetadata, element?: ElementHandle) {
     if (!sdkObject.attribution.page)
       return;
     const snapshotName = `${name}@${metadata.id}`;
-    snapshotsForMetadata(metadata).push({ title: name, snapshotName });
+    metadata.snapshots.push({ title: name, snapshotName });
     this._snapshotter.captureSnapshot(sdkObject.attribution.page, snapshotName, element);
   }
 
-  async onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise<void> {
+  onBeforeCall(sdkObject: SdkObject, metadata: CallMetadata) {
+    this._captureSnapshot('before', sdkObject, metadata);
+    this._pendingCalls.set(metadata.id, { sdkObject, metadata });
+  }
+
+  onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata, element: ElementHandle) {
+    this._captureSnapshot('action', sdkObject, metadata, element);
+  }
+
+  onAfterCall(sdkObject: SdkObject, metadata: CallMetadata) {
+    this._captureSnapshot('after', sdkObject, metadata);
     if (!sdkObject.attribution.page)
       return;
     const event: trace.ActionTraceEvent = {
-      timestamp: monotonicTime(),
+      timestamp: metadata.startTime,
       type: 'action',
       contextId: this._contextId,
       metadata,
-      snapshots: snapshotsForMetadata(metadata),
+    };
+    this._appendTraceEvent(event);
+    this._pendingCalls.delete(metadata.id);
+  }
+
+  onEvent(sdkObject: SdkObject, metadata: CallMetadata) {
+    if (!sdkObject.attribution.page)
+      return;
+    const event: trace.ActionTraceEvent = {
+      timestamp: metadata.startTime,
+      type: 'event',
+      contextId: this._contextId,
+      metadata,
     };
     this._appendTraceEvent(event);
   }
@@ -226,6 +243,8 @@ class ContextTracer {
     this._disposed = true;
     helper.removeEventListeners(this._eventListeners);
     await this._snapshotter.dispose();
+    for (const { sdkObject, metadata } of this._pendingCalls.values())
+      this.onAfterCall(sdkObject, metadata);
     const event: trace.ContextDestroyedTraceEvent = {
       timestamp: monotonicTime(),
       type: 'context-destroyed',

src/server/trace/viewer/traceModel.ts

@@ -84,9 +84,8 @@ export class TraceModel {
       case 'action': {
         const metadata = event.metadata;
         const { pageEntry } = this.pageEntries.get(metadata.pageId!)!;
-        const actionId = event.contextId + '/' + metadata.pageId + '/' + pageEntry.actions.length;
         const action: ActionEntry = {
-          actionId,
+          actionId: metadata.id,
           resources: [],
           ...event,
         };
@@ -106,28 +105,6 @@ export class TraceModel {
     contextEntry.startTime = Math.min(contextEntry.startTime, event.timestamp);
     contextEntry.endTime = Math.max(contextEntry.endTime, event.timestamp);
   }
-
-  actionById(actionId: string): { context: ContextEntry, page: PageEntry, action: ActionEntry } {
-    const [contextId, pageId, actionIndex] = actionId.split('/');
-    const context = this.contextEntries.get(contextId)!;
-    const page = context.pages.find(entry => entry.created.pageId === pageId)!;
-    const action = page.actions[+actionIndex];
-    return { context, page, action };
-  }
-
-  findPage(pageId: string): { contextEntry: ContextEntry | undefined, pageEntry: PageEntry | undefined } {
-    let contextEntry;
-    let pageEntry;
-    for (const c of this.contextEntries.values()) {
-      for (const p of c.pages) {
-        if (p.created.pageId === pageId) {
-          contextEntry = c;
-          pageEntry = p;
-        }
-      }
-    }
-    return { contextEntry, pageEntry };
-  }
 }
 
 export type ContextEntry = {

src/web/recorder/callLog.tsx

@@ -29,7 +29,7 @@ export const CallLogView: React.FC<CallLogProps> = ({
   onHover,
 }) => {
   const messagesEndRef = React.createRef<HTMLDivElement>();
-  const [expandOverrides, setExpandOverrides] = React.useState<Map<number, boolean>>(new Map());
+  const [expandOverrides, setExpandOverrides] = React.useState<Map<string, boolean>>(new Map());
   React.useLayoutEffect(() => {
     if (log.find(callLog => callLog.reveal))
       messagesEndRef.current?.scrollIntoView({ block: 'center', inline: 'nearest' });

src/web/recorder/main.tsx

@@ -33,14 +33,14 @@ export const Main: React.FC = ({
 }) => {
   const [sources, setSources] = React.useState<Source[]>([]);
   const [paused, setPaused] = React.useState(false);
-  const [log, setLog] = React.useState(new Map<number, CallLog>());
+  const [log, setLog] = React.useState(new Map<string, CallLog>());
   const [mode, setMode] = React.useState<Mode>('none');
 
   window.playwrightSetMode = setMode;
   window.playwrightSetSources = setSources;
   window.playwrightSetPaused = setPaused;
   window.playwrightUpdateLogs = callLogs => {
-    const newLog = new Map<number, CallLog>(log);
+    const newLog = new Map<string, CallLog>(log);
     for (const callLog of callLogs) {
       callLog.reveal = !log.has(callLog.id);
       newLog.set(callLog.id, callLog);

src/web/recorder/recorder.tsx

@@ -34,7 +34,7 @@ declare global {
 export interface RecorderProps {
   sources: Source[],
   paused: boolean,
-  log: Map<number, CallLog>,
+  log: Map<string, CallLog>,
   mode: Mode,
   initialSelector?: string,
 }

src/web/traceViewer/ui/actionList.tsx

@@ -80,7 +80,7 @@ export const ActionList: React.FC<ActionListProps> = ({
           onMouseLeave={() => (highlightedAction === actionEntry) && onHighlighted(undefined)}
         >
           <div className={'action-error codicon codicon-issues'} hidden={!metadata.error} />
-          <div className='action-title'>{metadata.apiName}</div>
+          <div className='action-title'>{metadata.apiName || metadata.method}</div>
           {metadata.params.selector && <div className='action-selector' title={metadata.params.selector}>{metadata.params.selector}</div>}
           {metadata.method === 'goto' && metadata.params.url && <div className='action-url' title={metadata.params.url}>{metadata.params.url}</div>}
         </div>;

src/web/traceViewer/ui/sourceTab.tsx

@@ -68,7 +68,7 @@ export const SourceTab: React.FunctionComponent<{
     return value;
   }, [stackInfo, selectedFrame], '');
 
-  const targetLine = typeof stackInfo === 'string' ? 0 : stackInfo.frames[selectedFrame].line || 0;
+  const targetLine = typeof stackInfo === 'string' ? 0 : stackInfo.frames[selectedFrame]?.line || 0;
 
   const targetLineRef = React.createRef<HTMLDivElement>();
   React.useLayoutEffect(() => {

src/web/traceViewer/ui/workbench.tsx

@@ -44,6 +44,7 @@ export const Workbench: React.FunctionComponent<{
     const actions: ActionEntry[] = [];
     for (const page of context.pages)
       actions.push(...page.actions);
+    actions.sort((a, b) => a.timestamp - b.timestamp);
     return actions;
   }, [context]);