feat(test runner): show errors from interrupted tests when available (#7874)

This shows the exact operation that is timing out (like click) when
user hits Ctrl+C.

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

@@ -35,7 +35,7 @@ Learn more about [test retries](./test-retries.md).
 Start time of this particular test run.
 
 ## property: TestResult.status
-- type: <[void]|[TestStatus]<"passed"|"failed"|"timedOut"|"skipped">>
+- type: <[TestStatus]<"passed"|"failed"|"timedOut"|"skipped">>
 
 The status of this test result. See also [`property: TestCase.expectedStatus`].
 

src/test/dispatcher.ts

@@ -18,7 +18,7 @@ import child_process from 'child_process';
 import path from 'path';
 import { EventEmitter } from 'events';
 import { RunPayload, TestBeginPayload, TestEndPayload, DonePayload, TestOutputPayload, WorkerInitParams } from './ipc';
-import type { TestResult, Reporter, TestStatus } from '../../types/testReporter';
+import type { TestResult, Reporter } from '../../types/testReporter';
 import { TestCase } from './test';
 import { Loader } from './loader';
 
@@ -148,16 +148,22 @@ export class Dispatcher {
 
       const failedTestIds = new Set<string>();
 
-      // In case of fatal error, report all remaining tests as failing with this error.
+      // In case of fatal error, report first remaining test as failing with this error,
+      // and all others as skipped.
       if (params.fatalError) {
+        let first = true;
         for (const { testId } of remaining) {
           const { test, result } = this._testById.get(testId)!;
+          if (this._hasReachedMaxFailures())
+            break;
           // There might be a single test that has started but has not finished yet.
           if (testId !== lastStartedTestId)
-            this._reportTestBegin(test);
+            this._reporter.onTestBegin?.(test);
           result.error = params.fatalError;
-          this._reportTestEnd(test, result, 'failed');
+          result.status = first ? 'failed' : 'skipped';
+          this._reportTestEnd(test, result);
           failedTestIds.add(testId);
+          first = false;
         }
         // Since we pretend that all remaining tests failed, there is nothing else to run,
         // except for possible retries.
@@ -187,7 +193,10 @@ export class Dispatcher {
     worker.on('done', onDone);
 
     const onExit = () => {
-      onDone({ fatalError: { value: 'Worker process exited unexpectedly' } });
+      if (worker.didSendStop)
+        onDone({});
+      else
+        onDone({ fatalError: { value: 'Worker process exited unexpectedly' } });
     };
     worker.on('exit', onExit);
 
@@ -226,12 +235,16 @@ export class Dispatcher {
   _createWorker(entry: DispatcherEntry) {
     const worker = new Worker(this);
     worker.on('testBegin', (params: TestBeginPayload) => {
+      if (this._hasReachedMaxFailures())
+        return;
       const { test, result: testRun  } = this._testById.get(params.testId)!;
       testRun.workerIndex = params.workerIndex;
       testRun.startTime = new Date(params.startWallTime);
-      this._reportTestBegin(test);
+      this._reporter.onTestBegin?.(test);
     });
     worker.on('testEnd', (params: TestEndPayload) => {
+      if (this._hasReachedMaxFailures())
+        return;
       const { test, result } = this._testById.get(params.testId)!;
       result.duration = params.duration;
       result.error = params.error;
@@ -241,10 +254,11 @@ export class Dispatcher {
         contentType: a.contentType,
         body: a.body ? Buffer.from(a.body, 'base64') : undefined
       }));
+      result.status = params.status;
       test.expectedStatus = params.expectedStatus;
       test.annotations = params.annotations;
       test.timeout = params.timeout;
-      this._reportTestEnd(test, result, params.status);
+      this._reportTestEnd(test, result);
     });
     worker.on('stdOut', (params: TestOutputPayload) => {
       const chunk = chunkFromParams(params);
@@ -284,23 +298,16 @@ export class Dispatcher {
     }
   }
 
-  private _reportTestBegin(test: TestCase) {
-    if (this._isStopped)
-      return;
+  private _hasReachedMaxFailures() {
     const maxFailures = this._loader.fullConfig().maxFailures;
-    if (!maxFailures || this._failureCount < maxFailures)
-      this._reporter.onTestBegin?.(test);
+    return maxFailures > 0 && this._failureCount >= maxFailures;
   }
 
-  private _reportTestEnd(test: TestCase, result: TestResult, status: TestStatus) {
-    if (this._isStopped)
-      return;
-    result.status = status;
+  private _reportTestEnd(test: TestCase, result: TestResult) {
     if (result.status !== 'skipped' && result.status !== test.expectedStatus)
       ++this._failureCount;
+    this._reporter.onTestEnd?.(test, result);
     const maxFailures = this._loader.fullConfig().maxFailures;
-    if (!maxFailures || this._failureCount <= maxFailures)
-      this._reporter.onTestEnd?.(test, result);
     if (maxFailures && this._failureCount === maxFailures)
       this.stop().catch(e => {});
   }
@@ -317,7 +324,7 @@ class Worker extends EventEmitter {
   runner: Dispatcher;
   hash = '';
   index: number;
-  private didSendStop = false;
+  didSendStop = false;
 
   constructor(runner: Dispatcher) {
     super();

src/test/reporters/base.ts

@@ -21,7 +21,7 @@ import fs from 'fs';
 import milliseconds from 'ms';
 import path from 'path';
 import StackUtils from 'stack-utils';
-import { FullConfig, TestStatus, TestCase, Suite, TestResult, TestError, Reporter, FullResult } from '../../../types/testReporter';
+import { FullConfig, TestCase, Suite, TestResult, TestError, Reporter, FullResult } from '../../../types/testReporter';
 
 const stackUtils = new StackUtils();
 
@@ -83,21 +83,27 @@ export class BaseReporter implements Reporter  {
   epilogue(full: boolean) {
     let skipped = 0;
     let expected = 0;
+    const skippedWithError: TestCase[] = [];
     const unexpected: TestCase[] = [];
     const flaky: TestCase[] = [];
 
     this.suite.allTests().forEach(test => {
       switch (test.outcome()) {
-        case 'skipped': ++skipped; break;
+        case 'skipped': {
+          ++skipped;
+          if (test.results.some(result => !!result.error))
+            skippedWithError.push(test);
+          break;
+        }
         case 'expected': ++expected; break;
         case 'unexpected': unexpected.push(test); break;
         case 'flaky': flaky.push(test); break;
       }
     });
 
-    if (full && unexpected.length) {
+    if (full && (unexpected.length || skippedWithError.length)) {
       console.log('');
-      this._printFailures(unexpected);
+      this._printFailures([...unexpected, ...skippedWithError]);
     }
 
     this._printSlowTests();
@@ -131,10 +137,6 @@ export class BaseReporter implements Reporter  {
     });
   }
 
-  hasResultWithStatus(test: TestCase, status: TestStatus): boolean {
-    return !!test.results.find(r => r.status === status);
-  }
-
   willRetry(test: TestCase, result: TestResult): boolean {
     return result.status !== 'passed' && result.status !== test.expectedStatus && test.results.length <= test.retries;
   }
@@ -144,9 +146,21 @@ export function formatFailure(config: FullConfig, test: TestCase, index?: number
   const tokens: string[] = [];
   tokens.push(formatTestHeader(config, test, '  ', index));
   for (const result of test.results) {
-    if (result.status === 'passed')
+    const resultTokens: string[] = [];
+    if (result.status === 'timedOut') {
+      resultTokens.push('');
+      resultTokens.push(indent(colors.red(`Timeout of ${test.timeout}ms exceeded.`), '    '));
+    }
+    if (result.error !== undefined)
+      resultTokens.push(indent(formatError(result.error, test.location.file), '    '));
+    if (!resultTokens.length)
       continue;
-    tokens.push(formatFailedResult(test, result));
+    const statusSuffix = result.status === 'passed' ? ' -- passed unexpectedly' : '';
+    if (result.retry) {
+      tokens.push('');
+      tokens.push(colors.gray(pad(`    Retry #${result.retry}${statusSuffix}`, '-')));
+    }
+    tokens.push(...resultTokens);
   }
   tokens.push('');
   return tokens.join('\n');
@@ -171,21 +185,6 @@ function formatTestHeader(config: FullConfig, test: TestCase, indent: string, in
   return colors.red(pad(header, '='));
 }
 
-function formatFailedResult(test: TestCase, result: TestResult): string {
-  const tokens: string[] = [];
-  if (result.retry)
-    tokens.push(colors.gray(pad(`\n    Retry #${result.retry}`, '-')));
-  if (result.status === 'timedOut') {
-    tokens.push('');
-    tokens.push(indent(colors.red(`Timeout of ${test.timeout}ms exceeded.`), '    '));
-    if (result.error !== undefined)
-      tokens.push(indent(formatError(result.error, test.location.file), '    '));
-  } else {
-    tokens.push(indent(formatError(result.error!, test.location.file), '    '));
-  }
-  return tokens.join('\n');
-}
-
 function formatError(error: TestError, file?: string) {
   const stack = error.stack;
   const tokens = [];

src/test/test.ts

@@ -141,20 +141,11 @@ export class TestCase extends Base implements reporterTypes.TestCase {
   }
 
   outcome(): 'skipped' | 'expected' | 'unexpected' | 'flaky' {
-    if (!this.results.length)
+    if (!this.results.length || this.results[0].status === 'skipped')
       return 'skipped';
     if (this.results.length === 1 && this.expectedStatus === this.results[0].status)
-      return this.expectedStatus === 'skipped' ? 'skipped' : 'expected';
-    let hasPassedResults = false;
-    for (const result of this.results) {
-      // TODO: we should not report tests that do not belong to the shard.
-      // Missing status is Ok when running in shards mode.
-      if (!result.status)
-        return 'skipped';
-      if (result.status === this.expectedStatus)
-        hasPassedResults = true;
-    }
-    if (hasPassedResults)
+      return 'expected';
+    if (this.results.some(result => result.status === this.expectedStatus))
       return 'flaky';
     return 'unexpected';
   }
@@ -180,6 +171,7 @@ export class TestCase extends Base implements reporterTypes.TestCase {
       stdout: [],
       stderr: [],
       attachments: [],
+      status: 'skipped',
     };
     this.results.push(result);
     return result;

src/test/workerRunner.ts

@@ -42,7 +42,7 @@ export class WorkerRunner extends EventEmitter {
   private _failedTestId: string | undefined;
   private _fatalError: TestError | undefined;
   private _entries = new Map<string, TestEntry>();
-  private _isStopped: any;
+  private _isStopped = false;
   _currentTest: { testId: string, testInfo: TestInfo } | null = null;
 
   constructor(params: WorkerInitParams) {
@@ -52,8 +52,10 @@ export class WorkerRunner extends EventEmitter {
   }
 
   stop() {
+    // TODO: mark test as 'interrupted' instead.
+    if (this._currentTest && this._currentTest.testInfo.status === 'passed')
+      this._currentTest.testInfo.status = 'skipped';
     this._isStopped = true;
-    this._setCurrentTest(null);
   }
 
   async cleanup() {
@@ -310,26 +312,25 @@ export class WorkerRunner extends EventEmitter {
     // Do not overwrite test failure upon hook timeout.
     if (result.timedOut && testInfo.status === 'passed')
       testInfo.status = 'timedOut';
-    if (this._isStopped)
-      return;
 
-    if (!result.timedOut) {
-      deadlineRunner = new DeadlineRunner(this._runAfterHooks(test, testInfo), deadline());
-      deadlineRunner.setDeadline(deadline());
-      const hooksResult = await deadlineRunner.result;
-      // Do not overwrite test failure upon hook timeout.
-      if (hooksResult.timedOut && testInfo.status === 'passed')
-        testInfo.status = 'timedOut';
-    } else {
-      // A timed-out test gets a full additional timeout to run after hooks.
-      const newDeadline = this._deadline();
-      deadlineRunner = new DeadlineRunner(this._runAfterHooks(test, testInfo), newDeadline);
-      await deadlineRunner.result;
+    if (!this._isStopped) {
+      // When stopped during the test run (usually either a user interruption or an unhandled error),
+      // we do not run cleanup because the worker will cleanup() anyway.
+      if (!result.timedOut) {
+        deadlineRunner = new DeadlineRunner(this._runAfterHooks(test, testInfo), deadline());
+        deadlineRunner.setDeadline(deadline());
+        const hooksResult = await deadlineRunner.result;
+        // Do not overwrite test failure upon hook timeout.
+        if (hooksResult.timedOut && testInfo.status === 'passed')
+          testInfo.status = 'timedOut';
+      } else {
+        // A timed-out test gets a full additional timeout to run after hooks.
+        const newDeadline = this._deadline();
+        deadlineRunner = new DeadlineRunner(this._runAfterHooks(test, testInfo), newDeadline);
+        await deadlineRunner.result;
+      }
     }
 
-    if (this._isStopped)
-      return;
-
     testInfo.duration = monotonicTime() - startTime;
     this.emit('testEnd', buildTestEndPayload(testId, testInfo));
 
@@ -339,11 +340,14 @@ export class WorkerRunner extends EventEmitter {
     if (!preserveOutput)
       await removeFolderAsync(testInfo.outputDir).catch(e => {});
 
+    this._setCurrentTest(null);
+
+    if (this._isStopped)
+      return;
     if (testInfo.status !== 'passed' && testInfo.status !== 'skipped') {
       this._failedTestId = testId;
       this._reportDoneAndStop();
     }
-    this._setCurrentTest(null);
   }
 
   private _setCurrentTest(currentTest: { testId: string, testInfo: TestInfo} | null) {

tests/playwright-test/playwright.spec.ts

@@ -185,6 +185,29 @@ test('should report error and pending operations on timeout', async ({ runInline
   expect(stripAscii(result.output)).toContain(`10 |           page.textContent('text=More missing'),`);
 });
 
+test('should report click error on sigint', async ({ runInlineTest }) => {
+  test.skip(process.platform === 'win32', 'No sending SIGINT on Windows');
+
+  const result = await runInlineTest({
+    'a.test.ts': `
+      const { test } = pwt;
+      test('timedout', async ({ page }) => {
+        await page.setContent('<div>Click me</div>');
+        const promise = page.click('text=Missing');
+        await new Promise(f => setTimeout(f, 100));
+        console.log('\\n%%SEND-SIGINT%%');
+        await promise;
+      });
+    `,
+  }, { workers: 1 }, {}, { sendSIGINTAfter: 1 });
+
+  expect(result.exitCode).toBe(130);
+  expect(result.passed).toBe(0);
+  expect(result.failed).toBe(0);
+  expect(result.skipped).toBe(1);
+  expect(stripAscii(result.output)).toContain(`8 |         const promise = page.click('text=Missing');`);
+});
+
 test('should work with screenshot: only-on-failure', async ({ runInlineTest }, testInfo) => {
   const result = await runInlineTest({
     'playwright.config.ts': `

tests/playwright-test/retry.spec.ts

@@ -134,7 +134,7 @@ test('should retry unhandled rejection', async ({ runInlineTest }) => {
         setTimeout(() => {
           throw new Error('Unhandled rejection in the test');
         });
-        await new Promise(f => setTimeout(f, 20));
+        await new Promise(f => setTimeout(f, 2000));
       });
     `
   }, { retries: 2 });

tests/playwright-test/runner.spec.ts

@@ -67,12 +67,13 @@ test('it should not hang and report results when worker process suddenly exits',
       test('passed1', () => {});
       test('passed2', () => {});
       test('failed1', () => { process.exit(0); });
-      test('failed2', () => {});
+      test('skipped', () => {});
     `
   });
   expect(result.exitCode).toBe(1);
   expect(result.passed).toBe(2);
-  expect(result.failed).toBe(2);
+  expect(result.failed).toBe(1);
+  expect(result.skipped).toBe(1);
   expect(result.output).toContain('Worker process exited unexpectedly');
 });
 
@@ -139,3 +140,29 @@ test('should use the first occurring error when an unhandled exception was throw
   expect(result.failed).toBe(1);
   expect(result.report.suites[0].specs[0].tests[0].results[0].error.message).toBe('first error');
 });
+
+test('worker interrupt should report errors', async ({ runInlineTest }) => {
+  test.skip(process.platform === 'win32', 'No sending SIGINT on Windows');
+
+  const result = await runInlineTest({
+    'a.spec.js': `
+      const test = pwt.test.extend({
+        throwOnTeardown: async ({}, use) => {
+          let reject;
+          await use(new Promise((f, r) => reject = r));
+          reject(new Error('INTERRUPT'));
+        },
+      });
+      test('interrupted', async ({ throwOnTeardown }) => {
+        console.log('\\n%%SEND-SIGINT%%');
+        await throwOnTeardown;
+      });
+    `,
+  }, {}, {}, { sendSIGINTAfter: 1 });
+  expect(result.exitCode).toBe(130);
+  expect(result.passed).toBe(0);
+  expect(result.failed).toBe(0);
+  expect(result.skipped).toBe(1);
+  expect(result.output).toContain('%%SEND-SIGINT%%');
+  expect(result.output).toContain('Error: INTERRUPT');
+});

types/testReporter.d.ts

@@ -194,7 +194,7 @@ export interface TestResult {
    * The status of this test result. See also
    * [testCase.expectedStatus](https://playwright.dev/docs/api/class-testcase#test-case-expected-status).
    */
-  status?: TestStatus;
+  status: TestStatus;
   /**
    * An error thrown during the test execution, if any.
    */

utils/generate_types/overrides-testReporter.d.ts

@@ -50,7 +50,7 @@ export interface TestResult {
   workerIndex: number;
   startTime: Date;
   duration: number;
-  status?: TestStatus;
+  status: TestStatus;
   error?: TestError;
   attachments: { name: string, path?: string, body?: Buffer, contentType: string }[];
   stdout: (string | Buffer)[];