feat(test-runner): introduce steps (microsoft#7952)

.gitignore

@@ -16,4 +16,4 @@ drivers/
 .gradle/
 nohup.out
 .trace
-.tmp
+.tmp

docs/src/test-reporter-api/class-reporter.md

@@ -138,6 +138,10 @@ Output chunk.
 
 Test that was running. Note that output may happen when to test is running, in which case this will be [void].
 
+### param: Reporter.onStdErr.result
+- `result` <[void]|[TestResult]>
+
+Result of the test run, this object gets populated while the test runs.
 
 
 ## method: Reporter.onStdOut
@@ -154,7 +158,48 @@ Output chunk.
 
 Test that was running. Note that output may happen when to test is running, in which case this will be [void].
 
+### param: Reporter.onStdOut.result
+- `result` <[void]|[TestResult]>
+
+Result of the test run, this object gets populated while the test runs.
+
+## method: Reporter.onStepBegin
+
+Called when a test step started in the worker process.
+
+### param: Reporter.onStepBegin.test
+- `test` <[TestCase]>
+
+Test that has been started.
+
+### param: Reporter.onStepBegin.result
+- `result` <[TestResult]>
+
+Result of the test run, this object gets populated while the test runs.
+
+### param: Reporter.onStepBegin.step
+- `result` <[TestStep]>
+
+Test step instance.
 
+## method: Reporter.onStepEnd
+
+Called when a test step finished in the worker process.
+
+### param: Reporter.onStepEnd.test
+- `test` <[TestCase]>
+
+Test that has been finished.
+
+### param: Reporter.onStepEnd.result
+- `result` <[TestResult]>
+
+Result of the test run.
+
+### param: Reporter.onStepEnd.step
+- `result` <[TestStep]>
+
+Test step instance.
 
 ## method: Reporter.onTestBegin
 
@@ -165,6 +210,10 @@ Called after a test has been started in the worker process.
 
 Test that has been started.
 
+### param: Reporter.onTestBegin.result
+- `result` <[TestResult]>
+
+Result of the test run, this object gets populated while the test runs.
 
 
 ## method: Reporter.onTestEnd

docs/src/test-reporter-api/class-testresult.md

@@ -49,6 +49,11 @@ Anything written to the standard error during the test run.
 
 Anything written to the standard output during the test run.
 
+## property: TestResult.steps
+- type: <[Array]<[TestStep]>>
+
+List of steps inside this test run.
+
 ## property: TestResult.workerIndex
 - type: <[int]>
 

docs/src/test-reporter-api/class-teststep.md

@@ -0,0 +1,32 @@
+# class: TestStep
+* langs: js
+
+Represents a step in the [TestRun].
+
+## property: TestStep.category
+- type: <[string]>
+
+Step category to differentiate steps with different origin and verbosity. Built-in categories are:
+* `hook` for fixtures and hooks initialization and teardown
+* `expect` for expect calls
+* `pw:api` for Playwright API calls.
+
+## property: TestStep.duration
+- type: <[float]>
+
+Running time in milliseconds.
+
+## property: TestStep.error
+- type: <[void]|[TestError]>
+
+An error thrown during the step execution, if any.
+
+## property: TestStep.startTime
+- type: <[Date]>
+
+Start time of this particular test step.
+
+## property: TestStep.title
+- type: <[string]>
+
+User-friendly test step title.

src/client/channelOwner.ts

@@ -23,8 +23,6 @@ import { isUnderTest } from '../utils/utils';
 import type { Connection } from './connection';
 import type { ClientSideInstrumentation, Logger } from './types';
 
-let lastCallSeq = 0;
-
 export abstract class ChannelOwner<T extends channels.Channel = channels.Channel, Initializer = {}> extends EventEmitter {
   protected _connection: Connection;
   private _parent: ChannelOwner | undefined;
@@ -97,19 +95,19 @@ export abstract class ChannelOwner<T extends channels.Channel = channels.Channel
     const stackTrace = captureStackTrace();
     const { apiName, frameTexts } = stackTrace;
     const channel = this._createChannel({}, stackTrace);
-    const seq = ++lastCallSeq;
+    let csiCallback: ((e?: Error) => void) | undefined;
     try {
       logApiCall(logger, `=> ${apiName} started`);
-      this._csi?.onApiCall({ phase: 'begin', seq, apiName, frames: stackTrace.frames });
+      csiCallback = this._csi?.onApiCall(apiName);
       const result = await func(channel as any, stackTrace);
-      this._csi?.onApiCall({ phase: 'end', seq });
+      csiCallback?.();
       logApiCall(logger, `<= ${apiName} succeeded`);
       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;
-      this._csi?.onApiCall({ phase: 'end', seq, error: e.stack });
+      csiCallback?.(e);
       logApiCall(logger, `<= ${apiName} failed`);
       throw e;
     }

src/client/types.ts

@@ -24,7 +24,7 @@ export interface Logger {
 }
 
 export interface ClientSideInstrumentation {
-  onApiCall(data: { phase: 'begin' | 'end', seq: number, apiName?: string, frames?: channels.StackFrame[], error?: string }): void;
+  onApiCall(name: string): (error?: Error) => void;
 }
 
 import { Size } from '../common/types';

src/test/dispatcher.ts

@@ -17,8 +17,8 @@
 import child_process from 'child_process';
 import path from 'path';
 import { EventEmitter } from 'events';
-import { RunPayload, TestBeginPayload, TestEndPayload, DonePayload, TestOutputPayload, WorkerInitParams, ProgressPayload } from './ipc';
-import type { TestResult, Reporter } from '../../types/testReporter';
+import { RunPayload, TestBeginPayload, TestEndPayload, DonePayload, TestOutputPayload, WorkerInitParams, StepBeginPayload, StepEndPayload } from './ipc';
+import type { TestResult, Reporter, TestStep } from '../../types/testReporter';
 import { TestCase } from './test';
 import { Loader } from './loader';
 
@@ -35,7 +35,7 @@ export class Dispatcher {
   private _freeWorkers: Worker[] = [];
   private _workerClaimers: (() => void)[] = [];
 
-  private _testById = new Map<string, { test: TestCase, result: TestResult }>();
+  private _testById = new Map<string, { test: TestCase, result: TestResult, steps: Map<string, TestStep> }>();
   private _queue: TestGroup[] = [];
   private _stopCallback = () => {};
   readonly _loader: Loader;
@@ -51,7 +51,8 @@ export class Dispatcher {
     for (const group of testGroups) {
       for (const test of group.tests) {
         const result = test._appendTestResult();
-        this._testById.set(test._id, { test, result });
+        // When changing this line, change the one in retry too.
+        this._testById.set(test._id, { test, result, steps: new Map() });
       }
     }
   }
@@ -136,7 +137,7 @@ export class Dispatcher {
             break;
           // There might be a single test that has started but has not finished yet.
           if (test._id !== lastStartedTestId)
-            this._reporter.onTestBegin?.(test);
+            this._reporter.onTestBegin?.(test, result);
           result.error = params.fatalError;
           result.status = first ? 'failed' : 'skipped';
           this._reportTestEnd(test, result);
@@ -155,6 +156,7 @@ export class Dispatcher {
         const pair = this._testById.get(testId)!;
         if (!this._isStopped && pair.test.expectedStatus === 'passed' && pair.test.results.length < pair.test.retries + 1) {
           pair.result = pair.test._appendTestResult();
+          pair.steps = new Map();
           remaining.unshift(pair.test);
         }
       }
@@ -215,7 +217,7 @@ export class Dispatcher {
       const { test, result: testRun  } = this._testById.get(params.testId)!;
       testRun.workerIndex = params.workerIndex;
       testRun.startTime = new Date(params.startWallTime);
-      this._reporter.onTestBegin?.(test);
+      this._reporter.onTestBegin?.(test, testRun);
     });
     worker.on('testEnd', (params: TestEndPayload) => {
       if (this._hasReachedMaxFailures())
@@ -235,23 +237,40 @@ export class Dispatcher {
       test.timeout = params.timeout;
       this._reportTestEnd(test, result);
     });
-    worker.on('progress', (params: ProgressPayload) => {
-      const { test } = this._testById.get(params.testId)!;
-      (this._reporter as any)._onTestProgress?.(test, params.name, params.data);
+    worker.on('stepBegin', (params: StepBeginPayload) => {
+      const { test, result, steps } = this._testById.get(params.testId)!;
+      const step: TestStep = {
+        title: params.title,
+        category: params.category,
+        startTime: new Date(params.wallTime),
+        duration: 0,
+      };
+      steps.set(params.stepId, step);
+      result.steps.push(step);
+      this._reporter.onStepBegin?.(test, result, step);
+    });
+    worker.on('stepEnd', (params: StepEndPayload) => {
+      const { test, result, steps } = this._testById.get(params.testId)!;
+      const step = steps.get(params.stepId)!;
+      step.duration = params.wallTime - step.startTime.getTime();
+      if (params.error)
+        step.error = params.error;
+      steps.delete(params.stepId);
+      this._reporter.onStepEnd?.(test, result, step);
     });
     worker.on('stdOut', (params: TestOutputPayload) => {
       const chunk = chunkFromParams(params);
       const pair = params.testId ? this._testById.get(params.testId) : undefined;
       if (pair)
         pair.result.stdout.push(chunk);
-      this._reporter.onStdOut?.(chunk, pair ? pair.test : undefined);
+      this._reporter.onStdOut?.(chunk, pair?.test, pair?.result);
     });
     worker.on('stdErr', (params: TestOutputPayload) => {
       const chunk = chunkFromParams(params);
       const pair = params.testId ? this._testById.get(params.testId) : undefined;
       if (pair)
         pair.result.stderr.push(chunk);
-      this._reporter.onStdErr?.(chunk, pair ? pair.test : undefined);
+      this._reporter.onStdErr?.(chunk, pair?.test, pair?.result);
     });
     worker.on('teardownError', ({error}) => {
       this._hasWorkerErrors = true;

src/test/expect.ts

@@ -39,7 +39,7 @@ import {
   toHaveValue
 } from './matchers/matchers';
 import { toMatchSnapshot } from './matchers/toMatchSnapshot';
-import type { Expect } from './types';
+import type { Expect, TestStatus } from './types';
 import matchers from 'expect/build/matchers';
 import { currentTestInfo } from './globals';
 
@@ -70,41 +70,37 @@ const customMatchers = {
   toMatchSnapshot,
 };
 
-let lastExpectSeq = 0;
-
 function wrap(matcherName: string, matcher: any) {
   return function(this: any, ...args: any[]) {
     const testInfo = currentTestInfo();
     if (!testInfo)
       return matcher.call(this, ...args);
 
-    const seq = ++lastExpectSeq;
-    testInfo._progress('expect', { phase: 'begin', seq, matcherName });
-    const endPayload: any = { phase: 'end', seq };
-    let isAsync = false;
+    const infix = this.isNot ? '.not' : '';
+    const completeStep = testInfo._addStep('expect', `expect${infix}.${matcherName}`);
+
+    const reportStepEnd = (result: any) => {
+      status = result.pass !== this.isNot ? 'passed' : 'failed';
+      let error: Error | undefined;
+      if (status === 'failed')
+        error = new Error(result.message());
+      completeStep?.(error);
+      return result;
+    };
+
+    const reportStepError = (error: Error) => {
+      completeStep?.(error);
+      throw error;
+    };
+
+    let status: TestStatus = 'passed';
     try {
       const result = matcher.call(this, ...args);
-      endPayload.pass = result.pass;
-      if (this.isNot)
-        endPayload.isNot = this.isNot;
-      if (result.pass === this.isNot && result.message)
-        endPayload.message = result.message();
-      if (result instanceof Promise) {
-        isAsync = true;
-        return result.catch(e => {
-          endPayload.error = e.stack;
-          throw e;
-        }).finally(() => {
-          testInfo._progress('expect', endPayload);
-        });
-      }
-      return result;
+      if (result instanceof Promise)
+        return result.then(reportStepEnd).catch(reportStepError);
+      return reportStepEnd(result);
     } catch (e) {
-      endPayload.error = e.stack;
-      throw e;
-    } finally {
-      if (!isAsync)
-        testInfo._progress('expect', endPayload);
+      reportStepError(e);
     }
   };
 }

src/test/index.ts

@@ -185,7 +185,9 @@ export const test = _baseTest.extend<PlaywrightTestArgs & PlaywrightTestOptions,
       };
       const context = await browser.newContext(combinedOptions);
       (context as any)._csi = {
-        onApiCall: (data: any) => (testInfo as any)._progress('pw:api', data),
+        onApiCall: (name: string) => {
+          return (testInfo as any)._addStep('pw:api', name);
+        },
       };
       context.setDefaultTimeout(actionTimeout || 0);
       context.setDefaultNavigationTimeout(navigationTimeout || actionTimeout || 0);

src/test/ipc.ts

@@ -46,10 +46,19 @@ export type TestEndPayload = {
   attachments: { name: string, path?: string, body?: string, contentType: string }[];
 };
 
-export type ProgressPayload = {
+export type StepBeginPayload = {
   testId: string;
-  name: string;
-  data: any;
+  stepId: string;
+  title: string;
+  category: string;
+  wallTime: number;  // milliseconds since unix epoch
+};
+
+export type StepEndPayload = {
+  testId: string;
+  stepId: string;
+  wallTime: number;  // milliseconds since unix epoch
+  error?: TestError;
 };
 
 export type TestEntry = {