From 0ed328f6de906eb00309f14f64c88b573839eeed Mon Sep 17 00:00:00 2001 From: Pavel Feldman Date: Fri, 23 Apr 2021 09:28:18 -0700 Subject: [PATCH] chore(tracing): include events in the trace (#6285) --- src/dispatchers/dispatcher.ts | 34 +++++++++--- src/server/frames.ts | 5 +- src/server/instrumentation.ts | 13 +++-- src/server/progress.ts | 4 -- .../supplements/recorder/recorderTypes.ts | 2 +- src/server/supplements/recorderSupplement.ts | 4 +- src/server/trace/common/traceEvents.ts | 2 +- src/server/trace/recorder/tracer.ts | 53 +++++++++++++------ src/server/trace/viewer/traceModel.ts | 25 +-------- src/web/recorder/callLog.tsx | 2 +- src/web/recorder/main.tsx | 4 +- src/web/recorder/recorder.tsx | 2 +- src/web/traceViewer/ui/actionList.tsx | 2 +- src/web/traceViewer/ui/sourceTab.tsx | 2 +- src/web/traceViewer/ui/workbench.tsx | 1 + 15 files changed, 86 insertions(+), 69 deletions(-) diff --git a/src/dispatchers/dispatcher.ts b/src/dispatchers/dispatcher.ts index a586f3009c..481486f596 100644 --- a/src/dispatchers/dispatcher.ts +++ b/src/dispatchers/dispatcher.ts @@ -77,7 +77,7 @@ export class Dispatcher 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 = {}) { @@ -87,7 +87,8 @@ export class Dispatcher 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 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(); - sendMessageToClient(guid: string, method: string, params: any) { - this.onmessage({ guid, method, params: this._replaceDispatchersWithGuids(params) }); + sendMessageToClient(guid: string, type: string, method: string, params: any, sdkObject?: SdkObject) { + 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; diff --git a/src/server/frames.ts b/src/server/frames.ts index d132e679be..f5becb57c7 100644 --- a/src/server/frames.ts +++ b/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. diff --git a/src/server/instrumentation.ts b/src/server/instrumentation.ts index 5c4df3c3a9..5074abeb46 100644 --- a/src/server/instrumentation.ts +++ b/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; onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata, element: ElementHandle): Promise; - onAfterInputAction(sdkObject: SdkObject, metadata: CallMetadata): Promise; onCallLog(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void; onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise; + + onEvent(sdkObject: SdkObject, metadata: CallMetadata): void; } export interface InstrumentationListener { @@ -83,9 +86,10 @@ export interface InstrumentationListener { onBeforeCall?(sdkObject: SdkObject, metadata: CallMetadata): Promise; onBeforeInputAction?(sdkObject: SdkObject, metadata: CallMetadata, element: ElementHandle): Promise; - onAfterInputAction?(sdkObject: SdkObject, metadata: CallMetadata): Promise; onCallLog?(logName: string, message: string, sdkObject: SdkObject, metadata: CallMetadata): void; onAfterCall?(sdkObject: SdkObject, metadata: CallMetadata): Promise; + + 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: [] }; } diff --git a/src/server/progress.ts b/src/server/progress.ts index 12ad76b1a7..0e7e9cfb33 100644 --- a/src/server/progress.ts +++ b/src/server/progress.ts @@ -27,7 +27,6 @@ export interface Progress { cleanupWhenAborted(cleanup: () => any): void; throwIfAborted(): void; beforeInputAction(element: ElementHandle): Promise; - afterInputAction(): Promise; 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 }; diff --git a/src/server/supplements/recorder/recorderTypes.ts b/src/server/supplements/recorder/recorderTypes.ts index 372e16916a..038b058aa3 100644 --- a/src/server/supplements/recorder/recorderTypes.ts +++ b/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; diff --git a/src/server/supplements/recorderSupplement.ts b/src/server/supplements/recorderSupplement.ts index 1c5d47900b..c9d416ba4b 100644 --- a/src/server/supplements/recorderSupplement.ts +++ b/src/server/supplements/recorderSupplement.ts @@ -56,9 +56,9 @@ export class RecorderSupplement { private _recorderSources: Source[]; private _userSources = new Map(); 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(); - private _allMetadatas = new Map(); + private _allMetadatas = new Map(); private _contextDebugger: ContextDebugger; static show(context: BrowserContext, params: channels.BrowserContextRecorderSupplementEnableParams = {}): Promise { diff --git a/src/server/trace/common/traceEvents.ts b/src/server/trace/common/traceEvents.ts index 78e452ade4..3207c8fa99 100644 --- a/src/server/trace/common/traceEvents.ts +++ b/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 }[], diff --git a/src/server/trace/recorder/tracer.ts b/src/server/trace/recorder/tracer.ts index eedf5be152..7199abd959 100644 --- a/src/server/trace/recorder/tracer.ts +++ b/src/server/trace/recorder/tracer.ts @@ -54,26 +54,20 @@ export class Tracer implements InstrumentationListener { } async onBeforeInputAction(sdkObject: SdkObject, metadata: CallMetadata, element: ElementHandle): Promise { - 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 { - this._contextTracers.get(sdkObject.attribution.context!)?._captureSnapshot('before', sdkObject, metadata, element); + async onBeforeCall(sdkObject: SdkObject, metadata: CallMetadata): Promise { + this._contextTracers.get(sdkObject.attribution.context!)?.onBeforeCall(sdkObject, metadata); } async onAfterCall(sdkObject: SdkObject, metadata: CallMetadata): Promise { - this._contextTracers.get(sdkObject.attribution.context!)?._captureSnapshot('after', sdkObject, metadata); this._contextTracers.get(sdkObject.attribution.context!)?.onAfterCall(sdkObject, metadata); } -} -const snapshotsSymbol = Symbol('snapshots'); - -// 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]; + async onEvent(sdkObject: SdkObject, metadata: CallMetadata): Promise { + this._contextTracers.get(sdkObject.attribution.context!)?.onEvent(sdkObject, metadata); + } } class ContextTracer { @@ -82,6 +76,7 @@ class ContextTracer { private _snapshotter: PersistentSnapshotter; private _eventListeners: RegisteredListener[]; private _disposed = false; + private _pendingCalls = new Map(); 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 { + _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 { + 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', diff --git a/src/server/trace/viewer/traceModel.ts b/src/server/trace/viewer/traceModel.ts index 305b0c8f29..7d58be7564 100644 --- a/src/server/trace/viewer/traceModel.ts +++ b/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 = { diff --git a/src/web/recorder/callLog.tsx b/src/web/recorder/callLog.tsx index e3955f52f9..bb5d07685f 100644 --- a/src/web/recorder/callLog.tsx +++ b/src/web/recorder/callLog.tsx @@ -29,7 +29,7 @@ export const CallLogView: React.FC = ({ onHover, }) => { const messagesEndRef = React.createRef(); - const [expandOverrides, setExpandOverrides] = React.useState>(new Map()); + const [expandOverrides, setExpandOverrides] = React.useState>(new Map()); React.useLayoutEffect(() => { if (log.find(callLog => callLog.reveal)) messagesEndRef.current?.scrollIntoView({ block: 'center', inline: 'nearest' }); diff --git a/src/web/recorder/main.tsx b/src/web/recorder/main.tsx index f8b66f72fa..05ab7b7328 100644 --- a/src/web/recorder/main.tsx +++ b/src/web/recorder/main.tsx @@ -33,14 +33,14 @@ export const Main: React.FC = ({ }) => { const [sources, setSources] = React.useState([]); const [paused, setPaused] = React.useState(false); - const [log, setLog] = React.useState(new Map()); + const [log, setLog] = React.useState(new Map()); const [mode, setMode] = React.useState('none'); window.playwrightSetMode = setMode; window.playwrightSetSources = setSources; window.playwrightSetPaused = setPaused; window.playwrightUpdateLogs = callLogs => { - const newLog = new Map(log); + const newLog = new Map(log); for (const callLog of callLogs) { callLog.reveal = !log.has(callLog.id); newLog.set(callLog.id, callLog); diff --git a/src/web/recorder/recorder.tsx b/src/web/recorder/recorder.tsx index 83f2d2299f..efc22558b0 100644 --- a/src/web/recorder/recorder.tsx +++ b/src/web/recorder/recorder.tsx @@ -34,7 +34,7 @@ declare global { export interface RecorderProps { sources: Source[], paused: boolean, - log: Map, + log: Map, mode: Mode, initialSelector?: string, } diff --git a/src/web/traceViewer/ui/actionList.tsx b/src/web/traceViewer/ui/actionList.tsx index f4c7ec330c..c61de47c9f 100644 --- a/src/web/traceViewer/ui/actionList.tsx +++ b/src/web/traceViewer/ui/actionList.tsx @@ -80,7 +80,7 @@ export const ActionList: React.FC = ({ onMouseLeave={() => (highlightedAction === actionEntry) && onHighlighted(undefined)} > ; diff --git a/src/web/traceViewer/ui/sourceTab.tsx b/src/web/traceViewer/ui/sourceTab.tsx index 12aebe05ea..cf766e1b10 100644 --- a/src/web/traceViewer/ui/sourceTab.tsx +++ b/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(); React.useLayoutEffect(() => { diff --git a/src/web/traceViewer/ui/workbench.tsx b/src/web/traceViewer/ui/workbench.tsx index ae452aaddb..a0958ffd61 100644 --- a/src/web/traceViewer/ui/workbench.tsx +++ b/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]);