From 3f0485486dc78f4dbeabd76e786ca9ea490dead9 Mon Sep 17 00:00:00 2001 From: Dmitry Gozman Date: Wed, 28 Jul 2021 15:43:37 -0700 Subject: [PATCH] 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. --- .../src/test-reporter-api/class-testresult.md | 2 +- src/test/dispatcher.ts | 45 ++++++++++------- src/test/reporters/base.ts | 49 +++++++++---------- src/test/test.ts | 16 ++---- src/test/workerRunner.ts | 44 +++++++++-------- tests/playwright-test/playwright.spec.ts | 23 +++++++++ tests/playwright-test/retry.spec.ts | 2 +- tests/playwright-test/runner.spec.ts | 31 +++++++++++- types/testReporter.d.ts | 2 +- .../overrides-testReporter.d.ts | 2 +- 10 files changed, 134 insertions(+), 82 deletions(-) diff --git a/docs/src/test-reporter-api/class-testresult.md b/docs/src/test-reporter-api/class-testresult.md index 966727f458..50473f2b5b 100644 --- a/docs/src/test-reporter-api/class-testresult.md +++ b/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`]. diff --git a/src/test/dispatcher.ts b/src/test/dispatcher.ts index 069303664d..4823716547 100644 --- a/src/test/dispatcher.ts +++ b/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(); - // 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(); diff --git a/src/test/reporters/base.ts b/src/test/reporters/base.ts index 19e2234501..18e328c050 100644 --- a/src/test/reporters/base.ts +++ b/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 = []; diff --git a/src/test/test.ts b/src/test/test.ts index 1746a0b079..f1f9e40918 100644 --- a/src/test/test.ts +++ b/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; diff --git a/src/test/workerRunner.ts b/src/test/workerRunner.ts index ee520c1edc..3f043266f1 100644 --- a/src/test/workerRunner.ts +++ b/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(); - 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) { diff --git a/tests/playwright-test/playwright.spec.ts b/tests/playwright-test/playwright.spec.ts index 699f95afea..74a0803f16 100644 --- a/tests/playwright-test/playwright.spec.ts +++ b/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('
Click me
'); + 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': ` diff --git a/tests/playwright-test/retry.spec.ts b/tests/playwright-test/retry.spec.ts index e1371447f1..e79ae29c05 100644 --- a/tests/playwright-test/retry.spec.ts +++ b/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 }); diff --git a/tests/playwright-test/runner.spec.ts b/tests/playwright-test/runner.spec.ts index 21e59672c9..49d9965ba4 100644 --- a/tests/playwright-test/runner.spec.ts +++ b/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'); +}); diff --git a/types/testReporter.d.ts b/types/testReporter.d.ts index 1ea829ef99..40ef70c7b6 100644 --- a/types/testReporter.d.ts +++ b/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. */ diff --git a/utils/generate_types/overrides-testReporter.d.ts b/utils/generate_types/overrides-testReporter.d.ts index 372935d66d..1d070cedab 100644 --- a/utils/generate_types/overrides-testReporter.d.ts +++ b/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)[];