chrome: don't nest pw:api steps (#8932)

src/client/channelOwner.ts

@@ -72,15 +72,22 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel
     };
   }
 
-  private _createChannel(base: Object, stackTrace: ParsedStackTrace | null): T {
+  private _createChannel(base: Object, stackTrace: ParsedStackTrace | null, csi?: ClientSideInstrumentation, callCookie?: { userObject: any }): T {
     const channel = new Proxy(base, {
       get: (obj: any, prop) => {
         if (prop === 'debugScopeState')
           return (params: any) => this._connection.sendMessageToServer(this, prop, params, stackTrace);
         if (typeof prop === 'string') {
           const validator = scheme[paramsName(this._type, prop)];
-          if (validator)
+          if (validator) {
-            return (params: any) => this._connection.sendMessageToServer(this, prop, validator(params, ''), stackTrace);
+            return (params: any) => {
+              if (callCookie && csi) {
+                callCookie.userObject = csi.onApiCallBegin(renderCallWithParams(stackTrace!.apiName, params)).userObject;
+                csi = undefined;
+              }
+              return this._connection.sendMessageToServer(this, prop, validator(params, ''), stackTrace);
+            };
+          }
         }
         return obj[prop];
       },
@@ -97,22 +104,25 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel
     let ancestorWithCSI: ChannelOwner<any> = this;
     while (!ancestorWithCSI._csi && ancestorWithCSI._parent)
       ancestorWithCSI = ancestorWithCSI._parent;
-    let csiCallback: ((e?: Error) => void) | undefined;
+
+    // Do not report nested async calls to _wrapApiCall.
+    const isNested = stackTrace.allFrames.filter(f => f.function?.includes('_wrapApiCall')).length > 1;
+    const csi = isNested ? undefined : ancestorWithCSI._csi;
+    const callCookie: { userObject: any } = { userObject: null };
 
     try {
-      logApiCall(logger, `=> ${apiName} started`);
+      logApiCall(logger, `=> ${apiName} started`, isNested);
-      csiCallback = ancestorWithCSI._csi?.onApiCall(stackTrace);
+      const channel = this._createChannel({}, stackTrace, csi, callCookie);
-      const channel = this._createChannel({}, stackTrace);
       const result = await func(channel as any, stackTrace);
-      csiCallback?.();
+      csi?.onApiCallEnd(callCookie);
-      logApiCall(logger, `<= ${apiName} succeeded`);
+      logApiCall(logger, `<= ${apiName} succeeded`, isNested);
       return result;
     } catch (e) {
       const innerError = ((process.env.PWDEBUGIMPL || isUnderTest()) && e.stack) ? '\n<inner error>\n' + e.stack : '';
       e.message = apiName + ': ' + e.message;
       e.stack = e.message + '\n' + frameTexts.join('\n') + innerError;
-      csiCallback?.(e);
+      csi?.onApiCallEnd(callCookie, e);
-      logApiCall(logger, `<= ${apiName} failed`);
+      logApiCall(logger, `<= ${apiName} failed`, isNested);
       throw e;
     }
   }
@@ -129,7 +139,9 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel
   }
 }
 
-function logApiCall(logger: Logger | undefined, message: string) {
+function logApiCall(logger: Logger | undefined, message: string, isNested: boolean) {
+  if (isNested)
+    return;
   if (logger && logger.isEnabled('api', 'info'))
     logger.log('api', 'info', message, [], { color: 'cyan' });
   debugLogger.log('api', message);
@@ -139,6 +151,19 @@ function paramsName(type: string, method: string) {
   return type + method[0].toUpperCase() + method.substring(1) + 'Params';
 }
 
+const paramsToRender = ['url', 'selector', 'text', 'key'];
+export function renderCallWithParams(apiName: string, params: any) {
+  const paramsArray = [];
+  if (params) {
+    for (const name of paramsToRender) {
+      if (params[name])
+        paramsArray.push(params[name]);
+    }
+  }
+  const paramsText = paramsArray.length ? '(' + paramsArray.join(', ') + ')' : '';
+  return apiName + paramsText;
+}
+
 const tChannel = (name: string): Validator => {
   return (arg: any, path: string) => {
     if (arg._object instanceof ChannelOwner && (name === '*' || arg._object._type === name))

src/client/connection.ts

@@ -83,7 +83,7 @@ export class Connection extends EventEmitter {
 
   async sendMessageToServer(object: ChannelOwner, method: string, params: any, maybeStackTrace: ParsedStackTrace | null): Promise<any> {
     const guid = object._guid;
-    const stackTrace = maybeStackTrace || { frameTexts: [], frames: [], apiName: '' };
+    const stackTrace: ParsedStackTrace = maybeStackTrace || { frameTexts: [], frames: [], apiName: '', allFrames: [] };
     const { frames, apiName } = stackTrace;
 
     const id = ++this._lastId;

src/client/page.ts

@@ -383,9 +383,7 @@ export class Page extends ChannelOwner<channels.PageChannel, channels.PageInitia
   }
 
   async waitForEvent(event: string, optionsOrPredicate: WaitForEventOptions = {}): Promise<any> {
-    return this._wrapApiCall(async (channel: channels.PageChannel) => {
+    return this._waitForEvent(event, optionsOrPredicate, `waiting for event "${event}"`);
-      return this._waitForEvent(event, optionsOrPredicate, `waiting for event "${event}"`);
-    });
   }
 
   private async _waitForEvent(event: string, optionsOrPredicate: WaitForEventOptions, logLine?: string): Promise<any> {

src/client/types.ts

@@ -17,7 +17,6 @@
 
 import * as channels from '../protocol/channels';
 import type { Size } from '../common/types';
-import type { ParsedStackTrace } from '../utils/stackTrace';
 export { Size, Point, Rect, Quad, URLMatch, TimeoutOptions, HeadersArray } from '../common/types';
 
 type LoggerSeverity = 'verbose' | 'info' | 'warning' | 'error';
@@ -27,7 +26,8 @@ export interface Logger {
 }
 
 export interface ClientSideInstrumentation {
-  onApiCall(stackTrace: ParsedStackTrace): ((error?: Error) => void) | undefined;
+  onApiCallBegin(apiCall: string): { userObject: any };
+  onApiCallEnd(userData: { userObject: any }, error?: Error): any;
 }
 
 export type StrictOptions = { strict?: boolean };

src/test/dispatcher.ts

@@ -313,7 +313,8 @@ export class Dispatcher {
       };
       steps.set(params.stepId, step);
       (parentStep || result).steps.push(step);
-      stepStack.add(step);
+      if (params.canHaveChildren)
+        stepStack.add(step);
       this._reporter.onStepBegin?.(test, result, step);
     });
     worker.on('stepEnd', (params: StepEndPayload) => {

src/test/expect.ts

@@ -75,7 +75,7 @@ function wrap(matcherName: string, matcher: any) {
 
     const INTERNAL_STACK_LENGTH = 3;
     const stackLines = new Error().stack!.split('\n').slice(INTERNAL_STACK_LENGTH + 1);
-    const step = testInfo._addStep('expect', `expect${this.isNot ? '.not' : ''}.${matcherName}`);
+    const step = testInfo._addStep('expect', `expect${this.isNot ? '.not' : ''}.${matcherName}`, true);
 
     const reportStepEnd = (result: any) => {
       const success = result.pass !== this.isNot;

src/test/index.ts

@@ -20,7 +20,6 @@ import type { LaunchOptions, BrowserContextOptions, Page, BrowserContext, Browse
 import type { TestType, PlaywrightTestArgs, PlaywrightTestOptions, PlaywrightWorkerArgs, PlaywrightWorkerOptions, TestInfo } from '../../types/test';
 import { rootTestType } from './testType';
 import { createGuid, removeFolders } from '../utils/utils';
-import { TestInfoImpl } from './types';
 export { expect } from './expect';
 export const _baseTest: TestType<{}, {}> = rootTestType.test;
 
@@ -203,13 +202,14 @@ export const test = _baseTest.extend<TestFixtures, WorkerAndFileFixtures>({
         await context.tracing.stop();
       }
       (context as any)._csi = {
-        onApiCall: (stackTrace: ParsedStackTrace) => {
+        onApiCallBegin: (apiCall: string) => {
-          const testInfoImpl = testInfo as TestInfoImpl;
+          const testInfoImpl = testInfo as any;
-          const existingStep = testInfoImpl._currentSteps().find(step => step.category === 'pw:api' || step.category === 'expect');
+          const step = testInfoImpl._addStep('pw:api', apiCall, false);
-          const newStep = existingStep ? undefined : testInfoImpl._addStep('pw:api', stackTrace.apiName);
+          return { userObject: step };
-          return (error?: Error) => {
+        },
-            newStep?.complete(error);
+        onApiCallEnd: (data: { userObject: any }, error?: Error) => {
-          };
+          const step = data.userObject;
+          step?.complete(error);
         },
       };
     };

src/test/ipc.ts

@@ -51,6 +51,7 @@ export type StepBeginPayload = {
   stepId: string;
   title: string;
   category: string;
+  canHaveChildren: boolean;
   wallTime: number;  // milliseconds since unix epoch
 };
 

src/test/testType.ts

@@ -186,7 +186,7 @@ export class TestTypeImpl {
     const testInfo = currentTestInfo();
     if (!testInfo)
       throw errorWithLocation(location, `test.step() can only be called from a test`);
-    const step = testInfo._addStep('test.step', title);
+    const step = testInfo._addStep('test.step', title, true);
     try {
       await body();
       step.complete();

src/test/types.ts

@@ -28,10 +28,10 @@ export type Annotations = { type: string, description?: string }[];
 export interface TestStepInternal {
   complete(error?: Error | TestError): void;
   category: string;
+  canHaveChildren: boolean;
 }
 
 export interface TestInfoImpl extends TestInfo {
   _testFinished: Promise<void>;
-  _addStep: (category: string, title: string) => TestStepInternal;
+  _addStep: (category: string, title: string, canHaveChildren: boolean) => TestStepInternal;
-  _currentSteps(): TestStepInternal[];
 }

src/test/workerRunner.ts

@@ -219,7 +219,6 @@ export class WorkerRunner extends EventEmitter {
 
     let testFinishedCallback = () => {};
     let lastStepId = 0;
-    const stepStack = new Set<TestStepInternal>();
     const testInfo: TestInfoImpl = {
       workerIndex: this._params.workerIndex,
       project: this._project.config,
@@ -268,18 +267,18 @@ export class WorkerRunner extends EventEmitter {
           deadlineRunner.updateDeadline(deadline());
       },
       _testFinished: new Promise(f => testFinishedCallback = f),
-      _addStep: (category: string, title: string) => {
+      _addStep: (category: string, title: string, canHaveChildren: boolean) => {
         const stepId = `${category}@${title}@${++lastStepId}`;
         let callbackHandled = false;
         const step: TestStepInternal = {
           category,
+          canHaveChildren,
           complete: (error?: Error | TestError) => {
             if (callbackHandled)
               return;
             callbackHandled = true;
             if (error instanceof Error)
               error = serializeError(error);
-            stepStack.delete(step);
             const payload: StepEndPayload = {
               testId,
               stepId,
@@ -290,11 +289,11 @@ export class WorkerRunner extends EventEmitter {
               this.emit('stepEnd', payload);
           }
         };
-        stepStack.add(step);
         const payload: StepBeginPayload = {
           testId,
           stepId,
           category,
+          canHaveChildren,
           title,
           wallTime: Date.now(),
         };
@@ -302,7 +301,6 @@ export class WorkerRunner extends EventEmitter {
           this.emit('stepBegin', payload);
         return step;
       },
-      _currentSteps: () => [...stepStack],
     };
 
     // Inherit test.setTimeout() from parent suites.
@@ -425,7 +423,7 @@ export class WorkerRunner extends EventEmitter {
   }
 
   private async _runTestWithBeforeHooks(test: TestCase, testInfo: TestInfoImpl) {
-    const step = testInfo._addStep('hook', 'Before Hooks');
+    const step = testInfo._addStep('hook', 'Before Hooks', true);
     if (test._type === 'test')
       await this._runBeforeHooks(test, testInfo);
 
@@ -459,7 +457,7 @@ export class WorkerRunner extends EventEmitter {
     let step: TestStepInternal | undefined;
     let teardownError: TestError | undefined;
     try {
-      step = testInfo._addStep('hook', 'After Hooks');
+      step = testInfo._addStep('hook', 'After Hooks', true);
       if (test._type === 'test')
         await this._runHooks(test.parent!, 'afterEach', testInfo);
     } catch (error) {

src/utils/stackTrace.ts

@@ -35,6 +35,7 @@ const CLIENT_LIB = path.join(ROOT_DIR, 'lib', 'client');
 const CLIENT_SRC = path.join(ROOT_DIR, 'src', 'client');
 
 export type ParsedStackTrace = {
+  allFrames: StackFrame[];
   frames: StackFrame[];
   frameTexts: string[];
   apiName: string;
@@ -78,6 +79,7 @@ export function captureStackTrace(): ParsedStackTrace {
   let apiName = '';
   // Deepest transition between non-client code calling into client code
   // is the api entry.
+  const allFrames = parsedFrames;
   for (let i = 0; i < parsedFrames.length - 1; i++) {
     if (parsedFrames[i].inClient && !parsedFrames[i + 1].inClient) {
       const frame = parsedFrames[i].frame;
@@ -88,6 +90,7 @@ export function captureStackTrace(): ParsedStackTrace {
   }
 
   return {
+    allFrames: allFrames.map(p => p.frame),
     frames: parsedFrames.map(p => p.frame),
     frameTexts: parsedFrames.map(p => p.frameText),
     apiName

src/web/htmlReport/htmlReport.tsx

@@ -80,7 +80,7 @@ const ProjectTreeItemView: React.FC<{
     <StatsView stats={project.stats}></StatsView>
   </div>
   } loadChildren={hasChildren ? () => {
-    return project.suites.filter(s => !(failingOnly && s.stats.ok)).map((s, i) => <SuiteTreeItemView key={i} suite={s} setTestId={setTestId} testId={testId} depth={1} showFileName={true} failingOnly={failingOnly}></SuiteTreeItemView>) || [];
+    return project.suites.filter(s => !(failingOnly && s.stats.ok)).map((s, i) => <SuiteTreeItemView key={i} suite={s} setTestId={setTestId} testId={testId} depth={1} failingOnly={failingOnly}></SuiteTreeItemView>) || [];
   } : undefined} depth={0} expandByDefault={true}></TreeItem>;
 };
 
@@ -90,17 +90,14 @@ const SuiteTreeItemView: React.FC<{
   setTestId: (id: TestId) => void;
   failingOnly: boolean;
   depth: number,
-  showFileName: boolean,
+}> = ({ suite, testId, setTestId, failingOnly, depth }) => {
-}> = ({ suite, testId, setTestId, showFileName, failingOnly, depth }) => {
-  const location = renderLocation(suite.location, showFileName);
   return <TreeItem title={<div className='hbox'>
     <div className='tree-text' title={suite.title}>{suite.title}</div>
     <div style={{ flex: 'auto' }}></div>
     <StatsView stats={suite.stats}></StatsView>
-    {!!suite.location?.line && location && <div style={{ flex: 'none', padding: '0 4px', color: '#666' }}>{location}</div>}
   </div>
   } loadChildren={() => {
-    const suiteChildren = suite.suites.filter(s => !(failingOnly && s.stats.ok)).map((s, i) => <SuiteTreeItemView key={i} suite={s} setTestId={setTestId} testId={testId} depth={depth + 1} showFileName={false} failingOnly={failingOnly}></SuiteTreeItemView>) || [];
+    const suiteChildren = suite.suites.filter(s => !(failingOnly && s.stats.ok)).map((s, i) => <SuiteTreeItemView key={i} suite={s} setTestId={setTestId} testId={testId} depth={depth + 1} failingOnly={failingOnly}></SuiteTreeItemView>) || [];
     const suiteCount = suite.suites.length;
     const testChildren = suite.tests.filter(t => !(failingOnly && t.ok)).map((t, i) => <TestTreeItemView key={i + suiteCount} test={t} setTestId={setTestId} testId={testId} depth={depth + 1}></TestTreeItemView>) || [];
     return [...suiteChildren, ...testChildren];

tests/config/browserTest.ts

@@ -141,11 +141,14 @@ export const playwrightFixtures: Fixtures<PlaywrightTestOptions & PlaywrightTest
       if (trace)
         await context.tracing.start({ screenshots: true, snapshots: true });
       (context as any)._csi = {
-        onApiCall: (stackTrace: any) => {
+        onApiCallBegin: (apiCall: string) => {
           const testInfoImpl = testInfo as any;
-          const existingStep = testInfoImpl._currentSteps().find(step => step.category === 'pw:api' || step.category === 'expect');
+          const step = testInfoImpl._addStep('pw:api', apiCall, false);
-          const newStep = existingStep ? undefined : testInfoImpl._addStep('pw:api', stackTrace.apiName);
+          return { userObject: step };
-          return (error?: Error) => newStep?.complete(error);
+        },
+        onApiCallEnd: (data: { userObject: any }, error?: Error) => {
+          const step = data.userObject;
+          step?.complete(error);
         },
       };
       return context;

tests/playwright-test/reporter.spec.ts

@@ -229,7 +229,9 @@ test('should report expect steps', async ({ runInlineTest }) => {
     `%% end {\"title\":\"browserContext.newPage\",\"category\":\"pw:api\"}`,
     `%% end {\"title\":\"Before Hooks\",\"category\":\"hook\",\"steps\":[{\"title\":\"browserContext.newPage\",\"category\":\"pw:api\"}]}`,
     `%% begin {\"title\":\"expect.not.toHaveTitle\",\"category\":\"expect\"}`,
-    `%% end {\"title\":\"expect.not.toHaveTitle\",\"category\":\"expect\"}`,
+    `%% begin {\"title\":\"page.title\",\"category\":\"pw:api\"}`,
+    `%% end {\"title\":\"page.title\",\"category\":\"pw:api\"}`,
+    `%% end {\"title\":\"expect.not.toHaveTitle\",\"category\":\"expect\",\"steps\":[{\"title\":\"page.title\",\"category\":\"pw:api\"}]}`,
     `%% begin {\"title\":\"After Hooks\",\"category\":\"hook\"}`,
     `%% begin {\"title\":\"browserContext.close\",\"category\":\"pw:api\"}`,
     `%% end {\"title\":\"browserContext.close\",\"category\":\"pw:api\"}`,
@@ -281,22 +283,22 @@ test('should report api steps', async ({ runInlineTest }) => {
     `%% end {\"title\":\"Before Hooks\",\"category\":\"hook\",\"steps\":[{\"title\":\"browserContext.newPage\",\"category\":\"pw:api\"}]}`,
     `%% begin {\"title\":\"page.setContent\",\"category\":\"pw:api\"}`,
     `%% end {\"title\":\"page.setContent\",\"category\":\"pw:api\"}`,
-    `%% begin {\"title\":\"page.click\",\"category\":\"pw:api\"}`,
+    `%% begin {\"title\":\"page.click(button)\",\"category\":\"pw:api\"}`,
-    `%% end {\"title\":\"page.click\",\"category\":\"pw:api\"}`,
+    `%% end {\"title\":\"page.click(button)\",\"category\":\"pw:api\"}`,
     `%% begin {\"title\":\"After Hooks\",\"category\":\"hook\"}`,
     `%% begin {\"title\":\"browserContext.close\",\"category\":\"pw:api\"}`,
     `%% end {\"title\":\"browserContext.close\",\"category\":\"pw:api\"}`,
     `%% end {\"title\":\"After Hooks\",\"category\":\"hook\",\"steps\":[{\"title\":\"browserContext.close\",\"category\":\"pw:api\"}]}`,
     `%% begin {\"title\":\"Before Hooks\",\"category\":\"hook\"}`,
     `%% end {\"title\":\"Before Hooks\",\"category\":\"hook\"}`,
-    `%% begin {\"title\":\"page.click\",\"category\":\"pw:api\"}`,
+    `%% begin {\"title\":\"page.click(button)\",\"category\":\"pw:api\"}`,
-    `%% end {\"title\":\"page.click\",\"category\":\"pw:api\"}`,
+    `%% end {\"title\":\"page.click(button)\",\"category\":\"pw:api\"}`,
     `%% begin {\"title\":\"After Hooks\",\"category\":\"hook\"}`,
     `%% end {\"title\":\"After Hooks\",\"category\":\"hook\"}`,
     `%% begin {\"title\":\"Before Hooks\",\"category\":\"hook\"}`,
     `%% end {\"title\":\"Before Hooks\",\"category\":\"hook\"}`,
-    `%% begin {\"title\":\"page.click\",\"category\":\"pw:api\"}`,
+    `%% begin {\"title\":\"page.click(button)\",\"category\":\"pw:api\"}`,
-    `%% end {\"title\":\"page.click\",\"category\":\"pw:api\"}`,
+    `%% end {\"title\":\"page.click(button)\",\"category\":\"pw:api\"}`,
     `%% begin {\"title\":\"After Hooks\",\"category\":\"hook\"}`,
     `%% end {\"title\":\"After Hooks\",\"category\":\"hook\"}`,
   ]);
@@ -328,8 +330,8 @@ test('should report api step failure', async ({ runInlineTest }) => {
     `%% end {\"title\":\"Before Hooks\",\"category\":\"hook\",\"steps\":[{\"title\":\"browserContext.newPage\",\"category\":\"pw:api\"}]}`,
     `%% begin {\"title\":\"page.setContent\",\"category\":\"pw:api\"}`,
     `%% end {\"title\":\"page.setContent\",\"category\":\"pw:api\"}`,
-    `%% begin {\"title\":\"page.click\",\"category\":\"pw:api\"}`,
+    `%% begin {\"title\":\"page.click(input)\",\"category\":\"pw:api\"}`,
-    `%% end {\"title\":\"page.click\",\"category\":\"pw:api\",\"error\":{\"message\":\"page.click: Timeout 1ms exceeded.\\n=========================== logs ===========================\\nwaiting for selector \\\"input\\\"\\n============================================================\",\"stack\":\"<stack>\"}}`,
+    `%% end {\"title\":\"page.click(input)\",\"category\":\"pw:api\",\"error\":{\"message\":\"page.click: Timeout 1ms exceeded.\\n=========================== logs ===========================\\nwaiting for selector \\\"input\\\"\\n============================================================\",\"stack\":\"<stack>\"}}`,
     `%% begin {\"title\":\"After Hooks\",\"category\":\"hook\"}`,
     `%% begin {\"title\":\"browserContext.close\",\"category\":\"pw:api\"}`,
     `%% end {\"title\":\"browserContext.close\",\"category\":\"pw:api\"}`,