chore(test runner): make timeout a separate error in TestInfo.errors (#12315)

This way we control the timeout error message from the runner,
so that later on we can differentiate between test timeout, fixture
timeout and hook timeout.

packages/playwright-test/src/dispatcher.ts

@@ -17,7 +17,7 @@
 import child_process from 'child_process';
 import path from 'path';
 import { EventEmitter } from 'events';
-import { RunPayload, TestBeginPayload, TestEndPayload, DonePayload, TestOutputPayload, WorkerInitParams, StepBeginPayload, StepEndPayload, SerializedLoaderData } from './ipc';
+import { RunPayload, TestBeginPayload, TestEndPayload, DonePayload, TestOutputPayload, WorkerInitParams, StepBeginPayload, StepEndPayload, SerializedLoaderData, TeardownErrorsPayload } from './ipc';
 import type { TestResult, Reporter, TestStep } from '../types/testReporter';
 import { Suite, TestCase } from './test';
 import { Loader } from './loader';
@@ -290,7 +290,7 @@ export class Dispatcher {
       // - there are no remaining
       // - we are here not because something failed
       // - no unrecoverable worker error
-      if (!remaining.length && !failedTestIds.size && !params.fatalError) {
+      if (!remaining.length && !failedTestIds.size && !params.fatalErrors.length) {
         if (this._isWorkerRedundant(worker))
           worker.stop();
         doneWithJob();
@@ -302,12 +302,12 @@ export class Dispatcher {
 
       // In case of fatal error, report first remaining test as failing with this error,
       // and all others as skipped.
-      if (params.fatalError) {
+      if (params.fatalErrors.length) {
         // Perhaps we were running a hook - report it as failed.
         if (runningHookId) {
           const data = this._testById.get(runningHookId)!;
           const { result } = data.resultByWorkerIndex.get(worker.workerIndex)!;
-          result.errors = [params.fatalError];
+          result.errors = [...params.fatalErrors];
           result.error = result.errors[0];
           result.status = 'failed';
           this._reporter.onTestEnd?.(data.test, result);
@@ -328,7 +328,7 @@ export class Dispatcher {
             if (test._type === 'test')
               this._reporter.onTestBegin?.(test, result);
           }
-          result.errors = [params.fatalError];
+          result.errors = [...params.fatalErrors];
           result.error = result.errors[0];
           result.status = first ? 'failed' : 'skipped';
           this._reportTestEnd(test, result);
@@ -339,7 +339,8 @@ export class Dispatcher {
           // We had a fatal error after all tests have passed - most likely in the afterAll hook.
           // Let's just fail the test run.
           this._hasWorkerErrors = true;
-          this._reporter.onError?.(params.fatalError);
+          for (const error of params.fatalErrors)
+            this._reporter.onError?.(error);
         }
         // Since we pretend that all remaining tests failed, there is nothing else to run,
         // except for possible retries.
@@ -407,7 +408,7 @@ export class Dispatcher {
     worker.on('done', onDone);
 
     const onExit = (expectedly: boolean) => {
-      onDone(expectedly ? {} : { fatalError: { value: 'Worker process exited unexpectedly' } });
+      onDone({ fatalErrors: expectedly ? [] : [{ value: 'Worker process exited unexpectedly' }] });
     };
     worker.on('exit', onExit);
 
@@ -439,9 +440,10 @@ export class Dispatcher {
       result?.stderr.push(chunk);
       this._reporter.onStdErr?.(chunk, test, result);
     });
-    worker.on('teardownError', ({ error }) => {
+    worker.on('teardownErrors', (params: TeardownErrorsPayload) => {
       this._hasWorkerErrors = true;
-      this._reporter.onError?.(error);
+      for (const error of params.fatalErrors)
+        this._reporter.onError?.(error);
     });
     return worker;
   }

packages/playwright-test/src/index.ts

@@ -21,7 +21,6 @@ import type { TestType, PlaywrightTestArgs, PlaywrightTestOptions, PlaywrightWor
 import { rootTestType } from './testType';
 import { createGuid, removeFolders, debugMode } from 'playwright-core/lib/utils/utils';
 import { GridClient } from 'playwright-core/lib/grid/gridClient';
-import { prependToTestError } from './util';
 export { expect } from './expect';
 export const _baseTest: TestType<{}, {}> = rootTestType.test;
 import * as outOfProcess from 'playwright-core/lib/outofprocess';
@@ -429,7 +428,7 @@ export const test = _baseTest.extend<TestFixtures, WorkerFixtures>({
       const pendingCalls = anyContext ? formatPendingCalls((anyContext as any)._connection.pendingProtocolCalls()) : '';
       await Promise.all(leftoverContexts.filter(c => createdContexts.has(c)).map(c => c.close()));
       if (pendingCalls)
-        testInfo.error = prependToTestError(testInfo.error, pendingCalls);
+        testInfo.errors.push({ message: pendingCalls });
     }
   }, { auto: true }],
 
@@ -484,7 +483,7 @@ export const test = _baseTest.extend<TestFixtures, WorkerFixtures>({
     }));
 
     if (prependToError)
-      testInfo.error = prependToTestError(testInfo.error, prependToError);
+      testInfo.errors.push({ message: prependToError });
   },
 
   context: async ({ _contextFactory }, use) => {
@@ -511,7 +510,7 @@ function formatPendingCalls(calls: ParsedStackTrace[]) {
   return 'Pending operations:\n' + calls.map(call => {
     const frame = call.frames && call.frames[0] ? ' at ' + formatStackFrame(call.frames[0]) : '';
     return `  - ${call.apiName}${frame}\n`;
-  }).join('') + '\n';
+  }).join('');
 }
 
 function formatStackFrame(frame: StackFrame) {

packages/playwright-test/src/ipc.ts

@@ -75,7 +75,7 @@ export type RunPayload = {
 };
 
 export type DonePayload = {
-  fatalError?: TestError;
+  fatalErrors: TestError[];
 };
 
 export type TestOutputPayload = {
@@ -83,3 +83,7 @@ export type TestOutputPayload = {
   text?: string;
   buffer?: string;
 };
+
+export type TeardownErrorsPayload = {
+  fatalErrors: TestError[];
+};

packages/playwright-test/src/reporters/base.ts

@@ -303,11 +303,7 @@ export function formatFailure(config: FullConfig, test: TestCase, options: {inde
 export function formatResultFailure(config: FullConfig, test: TestCase, result: TestResult, initialIndent: string, highlightCode: boolean): ErrorDetails[] {
   const errorDetails: ErrorDetails[] = [];
 
-  if (result.status === 'timedOut') {
-    errorDetails.push({
-      message: indent(colors.red(`Timeout of ${test.timeout}ms exceeded.`), initialIndent),
-    });
-  } else if (result.status === 'passed' && test.expectedStatus === 'failed') {
+  if (result.status === 'passed' && test.expectedStatus === 'failed') {
     errorDetails.push({
       message: indent(colors.red(`Expected to fail, but passed.`), initialIndent),
     });

packages/playwright-test/src/testInfo.ts

@@ -14,6 +14,7 @@
  * limitations under the License.
  */
 
+import colors from 'colors/safe';
 import fs from 'fs';
 import * as mime from 'mime';
 import path from 'path';
@@ -25,7 +26,7 @@ import { Loader } from './loader';
 import { ProjectImpl } from './project';
 import { TestCase } from './test';
 import { Annotations, TestStepInternal } from './types';
-import { addSuffixToFilePath, getContainedPath, monotonicTime, sanitizeForFilePath, serializeError, trimLongString } from './util';
+import { addSuffixToFilePath, formatLocation, getContainedPath, monotonicTime, sanitizeForFilePath, serializeError, trimLongString } from './util';
 
 export class TestInfoImpl implements TestInfo {
   private _projectImpl: ProjectImpl;
@@ -167,8 +168,16 @@ export class TestInfoImpl implements TestInfo {
       if (!(error instanceof TimeoutRunnerError))
         throw error;
       // Do not overwrite existing failure upon hook/teardown timeout.
-      if (this.status === 'passed')
+      if (this.status === 'passed') {
         this.status = 'timedOut';
+        if (this._test._type === 'test') {
+          this.errors.push({ message: colors.red(`Timeout of ${this.timeout}ms exceeded.`) });
+        } else {
+          // Include location for the hook to distinguish between multiple hooks.
+          const message = colors.red(`Timeout of ${this.timeout}ms exceeded in ${this._test._type} hook.`);
+          this.errors.push({ message: message, stack: message + `\n    at ${formatLocation(this._test.location)}.` });
+        }
+      }
     }
     this.duration = monotonicTime() - this._startTime;
   }

packages/playwright-test/src/util.ts

@@ -205,24 +205,3 @@ export function getContainedPath(parentPath: string, subPath: string = ''): stri
 }
 
 export const debugTest = debug('pw:test');
-
-export function prependToTestError(testError: TestError | undefined, message: string, location?: Location): TestError {
-  if (!testError) {
-    if (!location)
-      return { value: message };
-    let stack = `    at ${location.file}:${location.line}:${location.column}`;
-    if (!message.endsWith('\n'))
-      stack = '\n' + stack;
-    return { message: message, stack: message + stack };
-  }
-  if (testError.message) {
-    const stack = testError.stack ? message + testError.stack : testError.stack;
-    message = message + testError.message;
-    return {
-      value: testError.value,
-      message,
-      stack,
-    };
-  }
-  return testError;
-}

packages/playwright-test/src/worker.ts

@@ -16,7 +16,7 @@
 
 import { Console } from 'console';
 import * as util from 'util';
-import { RunPayload, TestOutputPayload, WorkerInitParams } from './ipc';
+import { RunPayload, TeardownErrorsPayload, TestOutputPayload, WorkerInitParams } from './ipc';
 import { startProfiling, stopProfiling } from './profiler';
 import { serializeError } from './util';
 import { WorkerRunner } from './workerRunner';
@@ -74,7 +74,7 @@ process.on('message', async message => {
     workerIndex = initParams.workerIndex;
     startProfiling();
     workerRunner = new WorkerRunner(initParams);
-    for (const event of ['testBegin', 'testEnd', 'stepBegin', 'stepEnd', 'done', 'teardownError'])
+    for (const event of ['testBegin', 'testEnd', 'stepBegin', 'stepEnd', 'done', 'teardownErrors'])
       workerRunner.on(event, sendMessageToParent.bind(null, event));
     return;
   }
@@ -103,7 +103,8 @@ async function gracefullyCloseAndExit() {
     if (workerIndex !== undefined)
       await stopProfiling(workerIndex);
   } catch (e) {
-    process.send!({ method: 'teardownError', params: { error: serializeError(e) } });
+    const payload: TeardownErrorsPayload = { fatalErrors: [serializeError(e)] };
+    process.send!({ method: 'teardownErrors', params: payload });
   }
   process.exit(0);
 }

packages/playwright-test/src/workerRunner.ts

@@ -18,8 +18,8 @@ import rimraf from 'rimraf';
 import util from 'util';
 import colors from 'colors/safe';
 import { EventEmitter } from 'events';
-import { serializeError, prependToTestError, formatLocation } from './util';
-import { TestBeginPayload, TestEndPayload, RunPayload, TestEntry, DonePayload, WorkerInitParams, StepBeginPayload, StepEndPayload } from './ipc';
+import { serializeError, formatLocation } from './util';
+import { TestBeginPayload, TestEndPayload, RunPayload, TestEntry, DonePayload, WorkerInitParams, StepBeginPayload, StepEndPayload, TeardownErrorsPayload } from './ipc';
 import { setCurrentTestInfo } from './globals';
 import { Loader } from './loader';
 import { Modifier, Suite, TestCase } from './test';
@@ -39,7 +39,7 @@ export class WorkerRunner extends EventEmitter {
   private _fixtureRunner: FixtureRunner;
 
   private _failedTest: TestInfoImpl | undefined;
-  private _fatalError: TestError | undefined;
+  private _fatalErrors: TestError[] = [];
   private _entries = new Map<string, TestEntry>();
   private _isStopped = false;
   private _runFinished = Promise.resolve();
@@ -69,8 +69,10 @@ export class WorkerRunner extends EventEmitter {
     // We have to load the project to get the right deadline below.
     await this._loadIfNeeded();
     await this._teardownScopes();
-    if (this._fatalError)
-      this.emit('teardownError', { error: this._fatalError });
+    if (this._fatalErrors.length) {
+      const payload: TeardownErrorsPayload = { fatalErrors: this._fatalErrors };
+      this.emit('teardownErrors', payload);
+    }
   }
 
   private async _teardownScopes() {
@@ -79,8 +81,8 @@ export class WorkerRunner extends EventEmitter {
       await this._fixtureRunner.teardownScope('test');
       await this._fixtureRunner.teardownScope('worker');
     }, this._project.config.timeout);
-    if (result.timedOut && !this._fatalError)
-      this._fatalError = { message: colors.red(`Timeout of ${this._project.config.timeout}ms exceeded while shutting down environment`) };
+    if (result.timedOut)
+      this._fatalErrors.push({ message: colors.red(`Timeout of ${this._project.config.timeout}ms exceeded while shutting down environment`) });
   }
 
   unhandledError(error: Error | any) {
@@ -102,8 +104,8 @@ export class WorkerRunner extends EventEmitter {
       this._currentTest._failWithError(serializeError(error), true /* isHardError */);
     } else {
       // No current test - fatal error.
-      if (!this._fatalError)
-        this._fatalError = serializeError(error);
+      if (!this._fatalErrors.length)
+        this._fatalErrors.push(serializeError(error));
     }
     this.stop();
   }
@@ -180,8 +182,7 @@ export class WorkerRunner extends EventEmitter {
       // TODO: separate timeout for beforeAll modifiers?
       const result = await raceAgainstTimeout(() => this._fixtureRunner.resolveParametersAndRunFunction(beforeAllModifier.fn, this._workerInfo, undefined), this._project.config.timeout);
       if (result.timedOut) {
-        if (!this._fatalError)
-          this._fatalError = serializeError(new Error(`Timeout of ${this._project.config.timeout}ms exceeded while running ${beforeAllModifier.type} modifier\n    at ${formatLocation(beforeAllModifier.location)}`));
+        this._fatalErrors.push(serializeError(new Error(`Timeout of ${this._project.config.timeout}ms exceeded while running ${beforeAllModifier.type} modifier\n    at ${formatLocation(beforeAllModifier.location)}`)));
         this.stop();
       } else if (!!result.result) {
         annotations.push({ type: beforeAllModifier.type, description: beforeAllModifier.description });
@@ -303,11 +304,7 @@ export class WorkerRunner extends EventEmitter {
       this._failedTest = testInfo;
       if (test._type !== 'test') {
         // beforeAll/afterAll hook failure skips any remaining tests in the worker.
-        if (!this._fatalError)
-          this._fatalError = testInfo.error;
-        // Keep any error we have, and add "timeout" message.
-        if (testInfo.status === 'timedOut')
-          this._fatalError = prependToTestError(this._fatalError, colors.red(`Timeout of ${testInfo.timeout}ms exceeded in ${test._type} hook.\n`), test.location);
+        this._fatalErrors.push(...testInfo.errors);
       }
       this.stop();
     } else {
@@ -389,9 +386,9 @@ export class WorkerRunner extends EventEmitter {
   }
 
   private _reportDone() {
-    const donePayload: DonePayload = { fatalError: this._fatalError };
+    const donePayload: DonePayload = { fatalErrors: this._fatalErrors };
     this.emit('done', donePayload);
-    this._fatalError = undefined;
+    this._fatalErrors = [];
     this._failedTest = undefined;
   }
 }

tests/playwright-test/hooks.spec.ts

@@ -499,7 +499,7 @@ test('afterAll timeout should be reported', async ({ runInlineTest }, testInfo)
     '%%afterAll',
   ]);
   expect(result.output).toContain('Timeout of 1000ms exceeded in afterAll hook.');
-  expect(result.output).toContain(`at ${testInfo.outputPath('a.test.js')}:6:12`);
+  expect(result.output).toContain(`at a.test.js:6:12`);
 });
 
 test('beforeAll and afterAll timeouts at the same time should be reported', async ({ runInlineTest }) => {