fix: match client step and server action by explicit stepId

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;
 };

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>;

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

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,

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,

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: {},

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,

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,
  };
 }

packages/playwright-core/src/utils/stackTrace.ts

@@ -140,5 +140,5 @@ Call log:
 
 export type ExpectZone = {
  title: string;
- wallTime: number;
+ stepId: string;
 };

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();

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;

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();

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({

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',

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;

packages/protocol/src/channels.ts

@@ -149,7 +149,7 @@ export type Metadata = {
  },
  apiName?: string,
  internal?: boolean,
- wallTime?: number,
+ stepId?: string,
 };
 
 export type ClientSideCallMetadata = {

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

packages/trace-viewer/src/entries.ts

@@ -72,6 +72,6 @@ export function createEmptyContext(): ContextEntry {
  events: [],
  errors: [],
  stdio: [],
- hasSource: false
+ hasSource: false,
  };
 }

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'>

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 = '';

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;

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;