diff --git a/packages/playwright-core/src/client/channelOwner.ts b/packages/playwright-core/src/client/channelOwner.ts index 8670ebbea2..4ebe32595c 100644 --- a/packages/playwright-core/src/client/channelOwner.ts +++ b/packages/playwright-core/src/client/channelOwner.ts @@ -143,11 +143,15 @@ export abstract class ChannelOwner { return await this._wrapApiCall(async apiZone => { - const { apiName, frames, csi, callCookie, wallTime } = apiZone.reported ? { apiName: undefined, csi: undefined, callCookie: undefined, frames: [], wallTime: undefined } : apiZone; + const { apiName, frames, csi, callCookie, stepId } = apiZone.reported ? { apiName: undefined, csi: undefined, callCookie: undefined, frames: [], stepId: undefined } : apiZone; apiZone.reported = true; - if (csi && apiName) - csi.onApiCallBegin(apiName, params, frames, wallTime, callCookie); - return await this._connection.sendMessageToServer(this, prop, validator(params, '', { tChannelImpl: tChannelImplToWire, binary: this._connection.rawBuffers() ? 'buffer' : 'toBase64' }), apiName, frames, wallTime); + let currentStepId = stepId; + if (csi && apiName) { + const out: { stepId?: string } = {}; + csi.onApiCallBegin(apiName, params, frames, callCookie, out); + currentStepId = out.stepId; + } + return await this._connection.sendMessageToServer(this, prop, validator(params, '', { tChannelImpl: tChannelImplToWire, binary: this._connection.rawBuffers() ? 'buffer' : 'toBase64' }), apiName, frames, currentStepId); }); }; } @@ -175,7 +179,7 @@ export abstract class ChannelOwner('expectZone'); - const wallTime = expectZone ? expectZone.wallTime : Date.now(); + const stepId = expectZone?.stepId; if (!isInternal && expectZone) apiName = expectZone.title; @@ -186,7 +190,7 @@ export abstract class ChannelOwner ${apiName} started`, isInternal); - const apiZone: ApiZone = { apiName, frames, isInternal, reported: false, csi, callCookie, wallTime }; + const apiZone: ApiZone = { apiName, frames, isInternal, reported: false, csi, callCookie, stepId }; const result = await zones.run('apiZone', apiZone, async () => await func(apiZone)); csi?.onApiCallEnd(callCookie); logApiCall(logger, `<= ${apiName} succeeded`, isInternal); @@ -243,5 +247,5 @@ type ApiZone = { reported: boolean; csi: ClientInstrumentation | undefined; callCookie: any; - wallTime: number; + stepId?: string; }; diff --git a/packages/playwright-core/src/client/clientInstrumentation.ts b/packages/playwright-core/src/client/clientInstrumentation.ts index 2b5dd00970..dd73299420 100644 --- a/packages/playwright-core/src/client/clientInstrumentation.ts +++ b/packages/playwright-core/src/client/clientInstrumentation.ts @@ -22,7 +22,7 @@ export interface ClientInstrumentation { addListener(listener: ClientInstrumentationListener): void; removeListener(listener: ClientInstrumentationListener): void; removeAllListeners(): void; - onApiCallBegin(apiCall: string, params: Record, frames: StackFrame[], wallTime: number, userData: any): void; + onApiCallBegin(apiCall: string, params: Record, frames: StackFrame[], userData: any, out: { stepId?: string }): void; onApiCallEnd(userData: any, error?: Error): void; onDidCreateBrowserContext(context: BrowserContext): Promise; onDidCreateRequestContext(context: APIRequestContext): Promise; @@ -32,7 +32,7 @@ export interface ClientInstrumentation { } export interface ClientInstrumentationListener { - onApiCallBegin?(apiName: string, params: Record, frames: StackFrame[], wallTime: number, userData: any): void; + onApiCallBegin?(apiName: string, params: Record, frames: StackFrame[], userData: any, out: { stepId?: string }): void; onApiCallEnd?(userData: any, error?: Error): void; onDidCreateBrowserContext?(context: BrowserContext): Promise; onDidCreateRequestContext?(context: APIRequestContext): Promise; diff --git a/packages/playwright-core/src/client/connection.ts b/packages/playwright-core/src/client/connection.ts index 611a8c9f6a..294b5d9f6e 100644 --- a/packages/playwright-core/src/client/connection.ts +++ b/packages/playwright-core/src/client/connection.ts @@ -118,7 +118,7 @@ export class Connection extends EventEmitter { this._tracingCount--; } - async sendMessageToServer(object: ChannelOwner, method: string, params: any, apiName: string | undefined, frames: channels.StackFrame[], wallTime: number | undefined): Promise { + async sendMessageToServer(object: ChannelOwner, method: string, params: any, apiName: string | undefined, frames: channels.StackFrame[], stepId?: string): Promise { if (this._closedError) throw this._closedError; if (object._wasCollected) @@ -133,7 +133,7 @@ export class Connection extends EventEmitter { debugLogger.log('channel', 'SEND> ' + JSON.stringify(message)); } const location = frames[0] ? { file: frames[0].file, line: frames[0].line, column: frames[0].column } : undefined; - const metadata: channels.Metadata = { wallTime, apiName, location, internal: !apiName }; + const metadata: channels.Metadata = { apiName, location, internal: !apiName, stepId }; if (this._tracingCount && frames && type !== 'LocalUtils') this._localUtils?._channel.addStackToTracingNoReply({ callData: { stack: frames, id } }).catch(() => {}); // We need to exit zones before calling into the server, otherwise diff --git a/packages/playwright-core/src/protocol/validator.ts b/packages/playwright-core/src/protocol/validator.ts index 83cfc633ab..1cc57fb5a7 100644 --- a/packages/playwright-core/src/protocol/validator.ts +++ b/packages/playwright-core/src/protocol/validator.ts @@ -34,7 +34,7 @@ scheme.Metadata = tObject({ })), apiName: tOptional(tString), internal: tOptional(tBoolean), - wallTime: tOptional(tNumber), + stepId: tOptional(tString), }); scheme.ClientSideCallMetadata = tObject({ id: tNumber, diff --git a/packages/playwright-core/src/server/dispatchers/dispatcher.ts b/packages/playwright-core/src/server/dispatchers/dispatcher.ts index 837a634e09..e14960b495 100644 --- a/packages/playwright-core/src/server/dispatchers/dispatcher.ts +++ b/packages/playwright-core/src/server/dispatchers/dispatcher.ts @@ -286,10 +286,10 @@ export class DispatcherConnection { const sdkObject = dispatcher._object instanceof SdkObject ? dispatcher._object : undefined; const callMetadata: CallMetadata = { id: `call@${id}`, - wallTime: validMetadata.wallTime || Date.now(), location: validMetadata.location, apiName: validMetadata.apiName, internal: validMetadata.internal, + stepId: validMetadata.stepId, objectId: sdkObject?.guid, pageId: sdkObject?.attribution?.page?.guid, frameId: sdkObject?.attribution?.frame?.guid, diff --git a/packages/playwright-core/src/server/instrumentation.ts b/packages/playwright-core/src/server/instrumentation.ts index 5d212279e3..fbaa3345d6 100644 --- a/packages/playwright-core/src/server/instrumentation.ts +++ b/packages/playwright-core/src/server/instrumentation.ts @@ -106,7 +106,6 @@ export function serverSideCallMetadata(): CallMetadata { id: '', startTime: 0, endTime: 0, - wallTime: Date.now(), type: 'Internal', method: '', params: {}, diff --git a/packages/playwright-core/src/server/recorder.ts b/packages/playwright-core/src/server/recorder.ts index d5f84ba625..3a770741ae 100644 --- a/packages/playwright-core/src/server/recorder.ts +++ b/packages/playwright-core/src/server/recorder.ts @@ -605,7 +605,6 @@ class ContextRecorder extends EventEmitter { frameId: frame.guid, startTime: monotonicTime(), endTime: 0, - wallTime: Date.now(), type: 'Frame', method: action, params, diff --git a/packages/playwright-core/src/server/trace/recorder/tracing.ts b/packages/playwright-core/src/server/trace/recorder/tracing.ts index 2639aff91d..85c783118d 100644 --- a/packages/playwright-core/src/server/trace/recorder/tracing.ts +++ b/packages/playwright-core/src/server/trace/recorder/tracing.ts @@ -542,7 +542,7 @@ function createBeforeActionTraceEvent(metadata: CallMetadata): trace.BeforeActio class: metadata.type, method: metadata.method, params: metadata.params, - wallTime: metadata.wallTime, + stepId: metadata.stepId, pageId: metadata.pageId, }; } diff --git a/packages/playwright-core/src/utils/stackTrace.ts b/packages/playwright-core/src/utils/stackTrace.ts index 2864d1ec81..77e1365b3f 100644 --- a/packages/playwright-core/src/utils/stackTrace.ts +++ b/packages/playwright-core/src/utils/stackTrace.ts @@ -140,5 +140,5 @@ Call log: export type ExpectZone = { title: string; - wallTime: number; + stepId: string; }; diff --git a/packages/playwright/src/common/testType.ts b/packages/playwright/src/common/testType.ts index 35e2a4668c..5c7850a3df 100644 --- a/packages/playwright/src/common/testType.ts +++ b/packages/playwright/src/common/testType.ts @@ -263,7 +263,7 @@ export class TestTypeImpl { const testInfo = currentTestInfo(); if (!testInfo) throw new Error(`test.step() can only be called from a test`); - const step = testInfo._addStep({ wallTime: Date.now(), category: 'test.step', title, box: options.box }); + const step = testInfo._addStep({ category: 'test.step', title, box: options.box }); return await zones.run('stepZone', step, async () => { try { const result = await body(); diff --git a/packages/playwright/src/index.ts b/packages/playwright/src/index.ts index 6cf690ad50..9b8b4bc55b 100644 --- a/packages/playwright/src/index.ts +++ b/packages/playwright/src/index.ts @@ -247,7 +247,7 @@ const playwrightFixtures: Fixtures = ({ const artifactsRecorder = new ArtifactsRecorder(playwright, tracing().artifactsDir(), screenshot); await artifactsRecorder.willStartTest(testInfo as TestInfoImpl); const csiListener: ClientInstrumentationListener = { - onApiCallBegin: (apiName: string, params: Record, frames: StackFrame[], wallTime: number, userData: any) => { + onApiCallBegin: (apiName: string, params: Record, frames: StackFrame[], userData: any, out: { stepId?: string }) => { const testInfo = currentTestInfo(); if (!testInfo || apiName.includes('setTestIdAttribute')) return { userObject: null }; @@ -257,9 +257,9 @@ const playwrightFixtures: Fixtures = ({ title: renderApiCall(apiName, params), apiName, params, - wallTime, }); userData.userObject = step; + out.stepId = step.stepId; }, onApiCallEnd: (userData: any, error?: Error) => { const step = userData.userObject; diff --git a/packages/playwright/src/matchers/expect.ts b/packages/playwright/src/matchers/expect.ts index 5d51a20b5e..0d5d226039 100644 --- a/packages/playwright/src/matchers/expect.ts +++ b/packages/playwright/src/matchers/expect.ts @@ -259,7 +259,6 @@ class ExpectMetaInfoProxyHandler implements ProxyHandler { const defaultTitle = `expect${this._info.isPoll ? '.poll' : ''}${this._info.isSoft ? '.soft' : ''}${this._info.isNot ? '.not' : ''}.${matcherName}${argsSuffix}`; const title = customMessage || defaultTitle; - const wallTime = Date.now(); // This looks like it is unnecessary, but it isn't - we need to filter // out all the frames that belong to the test runner from caught runtime errors. @@ -270,7 +269,6 @@ class ExpectMetaInfoProxyHandler implements ProxyHandler { category: 'expect', title: trimLongString(title, 1024), params: args[0] ? { expected: args[0] } : undefined, - wallTime, infectParentStepsWithError: this._info.isSoft, }; @@ -295,7 +293,7 @@ class ExpectMetaInfoProxyHandler implements ProxyHandler { // so they behave like a retriable step. const result = (matcherName === 'toPass' || this._info.isPoll) ? zones.run('stepZone', step, callback) : - zones.run('expectZone', { title, wallTime }, callback); + zones.run('expectZone', { title, stepId: step.stepId }, callback); if (result instanceof Promise) return result.then(finalizer).catch(reportStepError); finalizer(); diff --git a/packages/playwright/src/worker/testInfo.ts b/packages/playwright/src/worker/testInfo.ts index 6e55f68dac..1e9e1f9c46 100644 --- a/packages/playwright/src/worker/testInfo.ts +++ b/packages/playwright/src/worker/testInfo.ts @@ -33,8 +33,7 @@ export interface TestStepInternal { complete(result: { error?: Error, attachments?: Attachment[] }): void; stepId: string; title: string; - category: 'hook' | 'fixture' | 'test.step' | string; - wallTime: number; + category: 'hook' | 'fixture' | 'test.step' | 'expect' | string; location?: Location; boxedStack?: StackFrame[]; steps: TestStepInternal[]; @@ -322,11 +321,11 @@ export class TestInfoImpl implements TestInfo { parentStepId: parentStep ? parentStep.stepId : undefined, title: data.title, category: data.category, - wallTime: data.wallTime, + wallTime: Date.now(), location: data.location, }; this._onStepBegin(payload); - this._tracing.appendBeforeActionForStep(stepId, parentStep?.stepId, data.apiName || data.title, data.params, data.wallTime, data.location ? [data.location] : []); + this._tracing.appendBeforeActionForStep(stepId, parentStep?.stepId, data.apiName || data.title, data.params, data.location ? [data.location] : []); return step; } @@ -355,7 +354,7 @@ export class TestInfoImpl implements TestInfo { const location = stage.runnable?.location ? ` at "${formatLocation(stage.runnable.location)}"` : ``; debugTest(`started stage "${stage.title}"${location}`); } - stage.step = stage.stepInfo ? this._addStep({ ...stage.stepInfo, title: stage.title, wallTime: Date.now(), isStage: true }) : undefined; + stage.step = stage.stepInfo ? this._addStep({ ...stage.stepInfo, title: stage.title, isStage: true }) : undefined; this._stages.push(stage); try { @@ -420,7 +419,6 @@ export class TestInfoImpl implements TestInfo { const step = this._addStep({ title: `attach "${name}"`, category: 'attach', - wallTime: Date.now(), }); this._attachmentsPush(attachment); this._onAttach({ diff --git a/packages/playwright/src/worker/testTracing.ts b/packages/playwright/src/worker/testTracing.ts index 5462564c49..87eeca3ebb 100644 --- a/packages/playwright/src/worker/testTracing.ts +++ b/packages/playwright/src/worker/testTracing.ts @@ -234,12 +234,11 @@ export class TestTracing { }); } - appendBeforeActionForStep(callId: string, parentId: string | undefined, apiName: string, params: Record | undefined, wallTime: number, stack: StackFrame[]) { + appendBeforeActionForStep(callId: string, parentId: string | undefined, apiName: string, params: Record | undefined, stack: StackFrame[]) { this._appendTraceEvent({ type: 'before', callId, parentId, - wallTime, startTime: monotonicTime(), class: 'Test', method: 'step', diff --git a/packages/protocol/src/callMetadata.ts b/packages/protocol/src/callMetadata.ts index b011e9bf61..36e8b828c0 100644 --- a/packages/protocol/src/callMetadata.ts +++ b/packages/protocol/src/callMetadata.ts @@ -32,8 +32,8 @@ export type CallMetadata = { // Service-side is making a call to itself, this metadata does not go // through the dispatcher, so is always excluded from inspector / tracing. isServerSide?: boolean; - // Client wall time. - wallTime: number; + // Test runner step id. + stepId?: string; location?: { file: string, line?: number, column?: number }; log: string[]; error?: SerializedError; diff --git a/packages/protocol/src/channels.ts b/packages/protocol/src/channels.ts index d80152d8f0..986fb3a8dd 100644 --- a/packages/protocol/src/channels.ts +++ b/packages/protocol/src/channels.ts @@ -149,7 +149,7 @@ export type Metadata = { }, apiName?: string, internal?: boolean, - wallTime?: number, + stepId?: string, }; export type ClientSideCallMetadata = { diff --git a/packages/protocol/src/protocol.yml b/packages/protocol/src/protocol.yml index 8f1fb99cf3..14c6e73052 100644 --- a/packages/protocol/src/protocol.yml +++ b/packages/protocol/src/protocol.yml @@ -33,8 +33,8 @@ Metadata: column: number? apiName: string? internal: boolean? - # The number of milliseconds elapsed since midnight, January 1, 1970 UTC. - wallTime: number? + # Test runner step id. + stepId: string? ClientSideCallMetadata: type: object diff --git a/packages/trace-viewer/src/entries.ts b/packages/trace-viewer/src/entries.ts index a53fd0314b..bca5751ab2 100644 --- a/packages/trace-viewer/src/entries.ts +++ b/packages/trace-viewer/src/entries.ts @@ -72,6 +72,6 @@ export function createEmptyContext(): ContextEntry { events: [], errors: [], stdio: [], - hasSource: false + hasSource: false, }; } diff --git a/packages/trace-viewer/src/ui/callTab.tsx b/packages/trace-viewer/src/ui/callTab.tsx index 463ba5056c..b7cd7a8581 100644 --- a/packages/trace-viewer/src/ui/callTab.tsx +++ b/packages/trace-viewer/src/ui/callTab.tsx @@ -23,9 +23,10 @@ import { CopyToClipboard } from './copyToClipboard'; import { asLocator } from '@isomorphic/locatorGenerators'; import type { Language } from '@isomorphic/locatorGenerators'; import { PlaceholderPanel } from './placeholderPanel'; +import type { ActionTraceEventInContext } from './modelUtil'; export const CallTab: React.FunctionComponent<{ - action: ActionTraceEvent | undefined, + action: ActionTraceEventInContext | undefined, sdkLanguage: Language | undefined, }> = ({ action, sdkLanguage }) => { if (!action) @@ -34,7 +35,8 @@ export const CallTab: React.FunctionComponent<{ // Strip down the waitForEventInfo data, we never need it. delete params.info; const paramKeys = Object.keys(params); - const wallTime = action.wallTime ? new Date(action.wallTime).toLocaleString() : null; + const timeMillis = action.startTime + (action.context.wallTime - action.context.startTime); + const wallTime = new Date(timeMillis).toLocaleString(); const duration = action.endTime ? msToString(action.endTime - action.startTime) : 'Timed Out'; return
diff --git a/packages/trace-viewer/src/ui/logTab.tsx b/packages/trace-viewer/src/ui/logTab.tsx index 9e4995984f..be0469ab91 100644 --- a/packages/trace-viewer/src/ui/logTab.tsx +++ b/packages/trace-viewer/src/ui/logTab.tsx @@ -31,7 +31,7 @@ export const LogTab: React.FunctionComponent<{ if (!action || !action.log.length) return []; const log = action.log; - const wallTimeOffset = action.wallTime - action.startTime; + const wallTimeOffset = action.context.wallTime - action.context.startTime; const entries: { message: string, time: string }[] = []; for (let i = 0; i < log.length; ++i) { let time = ''; diff --git a/packages/trace-viewer/src/ui/modelUtil.ts b/packages/trace-viewer/src/ui/modelUtil.ts index 8a24c89430..6385f577c8 100644 --- a/packages/trace-viewer/src/ui/modelUtil.ts +++ b/packages/trace-viewer/src/ui/modelUtil.ts @@ -215,23 +215,33 @@ function mergeActionsAndUpdateTimingSameTrace(contexts: ContextEntry[]) { const libraryContexts = contexts.filter(context => context.origin === 'library'); const testRunnerContexts = contexts.filter(context => context.origin === 'testRunner'); + // Library actions are replaced with corresponding test runner steps. Matching with + // the test runner steps enables us to find parent steps. + // - In the newer versions the actions are matched by explicit step id stored in the + // library context actions. + // - In the older versions the step id is not stored and the match is perfomed based on + // action name and wallTime. + const matchByStepId = libraryContexts.some(c => c.actions.some(a => !!a.stepId)); + for (const context of libraryContexts) { - for (const action of context.actions) - map.set(`${action.apiName}@${action.wallTime}`, { ...action, context }); + for (const action of context.actions) { + const key = matchByStepId ? action.stepId! : `${action.apiName}@${(action as any).wallTime}`; + map.set(key, { ...action, context }); + } } // Protocol call aka library contexts have startTime/endTime as server-side times. // Step aka test runner contexts have startTime/endTime as client-side times. // Adjust startTime/endTime on the library contexts to align them with the test // runner steps. - const delta = monotonicTimeDeltaBetweenLibraryAndRunner(testRunnerContexts, map); + const delta = monotonicTimeDeltaBetweenLibraryAndRunner(testRunnerContexts, map, matchByStepId); if (delta) adjustMonotonicTime(libraryContexts, delta); const nonPrimaryIdToPrimaryId = new Map(); for (const context of testRunnerContexts) { for (const action of context.actions) { - const key = `${action.apiName}@${action.wallTime}`; + const key = matchByStepId ? action.callId : `${action.apiName}@${(action as any).wallTime}`; const existing = map.get(key); if (existing) { nonPrimaryIdToPrimaryId.set(action.callId, existing.callId); @@ -276,7 +286,7 @@ function adjustMonotonicTime(contexts: ContextEntry[], monotonicTimeDelta: numbe } } -function monotonicTimeDeltaBetweenLibraryAndRunner(nonPrimaryContexts: ContextEntry[], libraryActions: Map) { +function monotonicTimeDeltaBetweenLibraryAndRunner(nonPrimaryContexts: ContextEntry[], libraryActions: Map, matchByStepId: boolean) { // We cannot rely on wall time or monotonic time to be the in sync // between library and test runner contexts. So we find first action // that is present in both runner and library contexts and use it @@ -286,7 +296,7 @@ function monotonicTimeDeltaBetweenLibraryAndRunner(nonPrimaryContexts: ContextEn for (const action of context.actions) { if (!action.startTime) continue; - const key = `${action.apiName}@${action.wallTime}`; + const key = matchByStepId ? action.stepId! : `${action.apiName}@${(action as any).wallTime}`; const libraryAction = libraryActions.get(key); if (libraryAction) return action.startTime - libraryAction.startTime; diff --git a/packages/trace/src/trace.ts b/packages/trace/src/trace.ts index 7387f612aa..ebd3466fd8 100644 --- a/packages/trace/src/trace.ts +++ b/packages/trace/src/trace.ts @@ -62,7 +62,7 @@ export type BeforeActionTraceEvent = { class: string; method: string; params: Record; - wallTime: number; + stepId?: string; beforeSnapshot?: string; stack?: StackFrame[]; pageId?: string; diff --git a/tests/playwright-test/reporter-html.spec.ts b/tests/playwright-test/reporter-html.spec.ts index 9d0c6e84fc..47f67a7bb9 100644 --- a/tests/playwright-test/reporter-html.spec.ts +++ b/tests/playwright-test/reporter-html.spec.ts @@ -582,6 +582,38 @@ for (const useIntermediateMergeReport of [false] as const) { await expect(page.locator('.source-line-running')).toContainText('request.get'); }); + test('trace should not hang when showing parallel api requests', async ({ runInlineTest, page, server, showReport }) => { + const result = await runInlineTest({ + 'playwright.config.js': ` + module.exports = { use: { trace: 'on' } }; + `, + 'a.test.js': ` + import { test, expect, request } from '@playwright/test'; + test('log two contexts', async function({ }) { + const api1 = await request.newContext(); + const api2 = await request.newContext(); + await Promise.all([ + api1.get('${server.EMPTY_PAGE}'), + api1.get('${server.CROSS_PROCESS_PREFIX}/empty.html'), + api2.get('${server.EMPTY_PAGE}'), + api2.get('${server.CROSS_PROCESS_PREFIX}/empty.html'), + ]); + }); + `, + }, { reporter: 'html' }, { PW_TEST_HTML_REPORT_OPEN: 'never' }); + expect(result.exitCode).toBe(0); + expect(result.passed).toBe(1); + + await showReport(); + await page.getByRole('link', { name: 'View trace' }).click(); + + // Trace viewer should not hang here when displaying parallal requests. + await expect(page.getByTestId('actions-tree')).toContainText('apiRequestContext.get'); + await page.getByText('apiRequestContext.get').nth(2).click(); + await page.getByText('apiRequestContext.get').nth(1).click(); + await page.getByText('apiRequestContext.get').nth(0).click(); + }); + test('should warn user when viewing via file:// protocol', async ({ runInlineTest, page, showReport }, testInfo) => { const result = await runInlineTest({ 'playwright.config.js': `