fix: match client step and server action by explicit stepId (#30641)

Matching bu `apiName@wallTime` fails when two actions start at the same time, e.g. two parallel api requests. Moreover, it results in trace actions that have parent set to themselves, which in turn causes infinite loop in the trace viewer. To avoid this problems we write stepId explicitly to the library trace and use those step ids to find corresponding test runner steps. The stepId is passed via zone in case of expect, because the protocol step is quite deep in the call chain after or explicitly in case of API call steps created by the test runner instrumentation.
microsoft · May 14, 2024 · fb319e6 · fb319e6
1 parent 9ce41fa
commit fb319e6
Show file tree

Hide file tree

Showing 23 changed files with 88 additions and 47 deletions.
diff --git a/packages/playwright-core/src/client/channelOwner.ts b/packages/playwright-core/src/client/channelOwner.ts
@@ -143,11 +143,15 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel
           if (validator) {
             return async (params: any) => {
               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<T extends channels.Channel = channels.Channel
 
     // Enclosing zone could have provided the apiName and wallTime.
     const expectZone = zones.zoneData<ExpectZone>('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<T extends channels.Channel = channels.Channel
 
     try {
       logApiCall(logger, `=> ${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
@@ -22,7 +22,7 @@ export interface ClientInstrumentation {
   addListener(listener: ClientInstrumentationListener): void;
   removeListener(listener: ClientInstrumentationListener): void;
   removeAllListeners(): void;
-  onApiCallBegin(apiCall: string, params: Record<string, any>, frames: StackFrame[], wallTime: number, userData: any): void;
+  onApiCallBegin(apiCall: string, params: Record<string, any>, frames: StackFrame[], userData: any, out: { stepId?: string }): void;
   onApiCallEnd(userData: any, error?: Error): void;
   onDidCreateBrowserContext(context: BrowserContext): Promise<void>;
   onDidCreateRequestContext(context: APIRequestContext): Promise<void>;
@@ -32,7 +32,7 @@ export interface ClientInstrumentation {
 }
 
 export interface ClientInstrumentationListener {
-  onApiCallBegin?(apiName: string, params: Record<string, any>, frames: StackFrame[], wallTime: number, userData: any): void;
+  onApiCallBegin?(apiName: string, params: Record<string, any>, frames: StackFrame[], userData: any, out: { stepId?: string }): void;
   onApiCallEnd?(userData: any, error?: Error): void;
   onDidCreateBrowserContext?(context: BrowserContext): Promise<void>;
   onDidCreateRequestContext?(context: APIRequestContext): Promise<void>;

diff --git 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<any> {
+  async sendMessageToServer(object: ChannelOwner, method: string, params: any, apiName: string | undefined, frames: channels.StackFrame[], stepId?: string): Promise<any> {
     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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -247,7 +247,7 @@ const playwrightFixtures: Fixtures<TestFixtures, WorkerFixtures> = ({
     const artifactsRecorder = new ArtifactsRecorder(playwright, tracing().artifactsDir(), screenshot);
     await artifactsRecorder.willStartTest(testInfo as TestInfoImpl);
     const csiListener: ClientInstrumentationListener = {
-      onApiCallBegin: (apiName: string, params: Record<string, any>, frames: StackFrame[], wallTime: number, userData: any) => {
+      onApiCallBegin: (apiName: string, params: Record<string, any>, 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<TestFixtures, WorkerFixtures> = ({
           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
@@ -259,7 +259,6 @@ class ExpectMetaInfoProxyHandler implements ProxyHandler<any> {
 
       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<any> {
         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<any> {
         // so they behave like a retriable step.
         const result = (matcherName === 'toPass' || this._info.isPoll) ?
           zones.run('stepZone', step, callback) :
-          zones.run<ExpectZone, any>('expectZone', { title, wallTime }, callback);
+          zones.run<ExpectZone, any>('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
@@ -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
@@ -234,12 +234,11 @@ export class TestTracing {
     });
   }
 
-  appendBeforeActionForStep(callId: string, parentId: string | undefined, apiName: string, params: Record<string, any> | undefined, wallTime: number, stack: StackFrame[]) {
+  appendBeforeActionForStep(callId: string, parentId: string | undefined, apiName: string, params: Record<string, any> | 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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 <div className='call-tab'>

diff --git 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
@@ -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<string, string>();
   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<string, ActionTraceEventInContext>) {
+function monotonicTimeDeltaBetweenLibraryAndRunner(nonPrimaryContexts: ContextEntry[], libraryActions: Map<string, ActionTraceEventInContext>, 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
@@ -62,7 +62,7 @@ export type BeforeActionTraceEvent = {
   class: string;
   method: string;
   params: Record<string, any>;
-  wallTime: number;
+  stepId?: string;
   beforeSnapshot?: string;
   stack?: StackFrame[];
   pageId?: string;