From ed9b42a92dde8c2288052e19177a634def5f08ae Mon Sep 17 00:00:00 2001 From: Dmitry Gozman Date: Tue, 28 Sep 2021 10:56:50 -0700 Subject: [PATCH] feat(test runner): collect test error from worker teardown (#9190) When the test fails (usually with timeout), we wait until all hooks are run and worker scope is teared down before reporting test end result. This allows us to collect any error details populated by teardown in addition to the "timed out" message. --- src/test/workerRunner.ts | 35 +++++++++++++------- tests/playwright-test/fixture-errors.spec.ts | 20 +++++++++++ tests/playwright-test/fixtures.spec.ts | 21 ++++++++++++ tests/playwright-test/playwright.spec.ts | 24 ++++++++++++++ 4 files changed, 88 insertions(+), 12 deletions(-) diff --git a/src/test/workerRunner.ts b/src/test/workerRunner.ts index b6c336d14d..cfc2d983db 100644 --- a/src/test/workerRunner.ts +++ b/src/test/workerRunner.ts @@ -74,6 +74,12 @@ export class WorkerRunner extends EventEmitter { async cleanup() { // 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 }); + } + + private async _teardownScopes() { // TODO: separate timeout for teardown? const result = await raceAgainstDeadline((async () => { await this._fixtureRunner.teardownScope('test'); @@ -81,8 +87,6 @@ export class WorkerRunner extends EventEmitter { })(), this._deadline()); if (result.timedOut && !this._fatalError) this._fatalError = { message: colors.red(`Timeout of ${this._project.config.timeout}ms exceeded while shutting down environment`) }; - if (this._fatalError) - this.emit('teardownError', { error: this._fatalError }); } unhandledError(error: Error | any) { @@ -144,12 +148,19 @@ export class WorkerRunner extends EventEmitter { this._fixtureRunner.setPool(anyPool); await this._runSuite(suite, []); } + if (this._failedTest) + await this._teardownScopes(); } catch (e) { // In theory, we should run above code without any errors. // However, in the case we screwed up, or loadTestFile failed in the worker // but not in the runner, let's do a fatal error. this.unhandledError(e); } finally { + if (this._failedTest) { + // Now that we did run all hooks and teared down scopes, we can + // report the failure, possibly with any error details revealed by teardown. + this.emit('testEnd', buildTestEndPayload(this._failedTest.testId, this._failedTest.testInfo)); + } this._reportDone(); runFinishedCallback(); } @@ -370,22 +381,15 @@ export class WorkerRunner extends EventEmitter { await deadlineRunner.result; } - this._currentDeadlineRunner = undefined; testInfo.duration = monotonicTime() - startTime; - if (reportEvents) - this.emit('testEnd', buildTestEndPayload(testId, testInfo)); - - const isFailure = testInfo.status !== 'skipped' && testInfo.status !== testInfo.expectedStatus; - const preserveOutput = this._loader.fullConfig().preserveOutput === 'always' || - (this._loader.fullConfig().preserveOutput === 'failures-only' && isFailure); - if (!preserveOutput) - await removeFolderAsync(testInfo.outputDir).catch(e => {}); - + this._currentDeadlineRunner = undefined; this._currentTest = null; setCurrentTestInfo(null); + const isFailure = testInfo.status !== 'skipped' && testInfo.status !== testInfo.expectedStatus; if (isFailure) { if (test._type === 'test') { + // Delay reporting testEnd result until after teardownScopes is done. this._failedTest = testData; } else if (!this._fatalError) { if (testInfo.status === 'timedOut') @@ -394,7 +398,14 @@ export class WorkerRunner extends EventEmitter { this._fatalError = testInfo.error; } this.stop(); + } else if (reportEvents) { + this.emit('testEnd', buildTestEndPayload(testId, testInfo)); } + + const preserveOutput = this._loader.fullConfig().preserveOutput === 'always' || + (this._loader.fullConfig().preserveOutput === 'failures-only' && isFailure); + if (!preserveOutput) + await removeFolderAsync(testInfo.outputDir).catch(e => {}); } private async _runBeforeHooks(test: TestCase, testInfo: TestInfoImpl) { diff --git a/tests/playwright-test/fixture-errors.spec.ts b/tests/playwright-test/fixture-errors.spec.ts index b5ba35548e..01accdbe9e 100644 --- a/tests/playwright-test/fixture-errors.spec.ts +++ b/tests/playwright-test/fixture-errors.spec.ts @@ -95,6 +95,26 @@ test('should handle worker tear down fixture error', async ({ runInlineTest }) = expect(result.exitCode).toBe(1); }); +test('should handle worker tear down fixture error after failed test', async ({ runInlineTest }) => { + const result = await runInlineTest({ + 'a.spec.ts': ` + const test = pwt.test.extend({ + failure: [async ({}, runTest) => { + await runTest(); + throw new Error('Worker failed'); + }, { scope: 'worker' }] + }); + + test('timeout', async ({failure}) => { + await new Promise(f => setTimeout(f, 2000)); + }); + ` + }, { timeout: 1000 }); + expect(result.exitCode).toBe(1); + expect(result.output).toContain('Timeout of 1000ms exceeded.'); + expect(result.output).toContain('Worker failed'); +}); + test('should throw when using non-defined super worker fixture', async ({ runInlineTest }) => { const result = await runInlineTest({ 'a.spec.ts': ` diff --git a/tests/playwright-test/fixtures.spec.ts b/tests/playwright-test/fixtures.spec.ts index 5248d00f68..bf8a409935 100644 --- a/tests/playwright-test/fixtures.spec.ts +++ b/tests/playwright-test/fixtures.spec.ts @@ -678,3 +678,24 @@ test('worker fixture should not receive TestInfo', async ({ runInlineTest }) => }); expect(result.exitCode).toBe(0); }); + +test('worker teardown errors reflected in timed-out tests', async ({ runInlineTest }) => { + const result = await runInlineTest({ + 'a.test.js': ` + const test = pwt.test.extend({ + foo: [async ({}, use) => { + let cb; + await use(new Promise((f, r) => cb = r)); + cb(new Error('Rejecting!')); + }, { scope: 'worker' }] + }); + test('timedout', async ({ foo }) => { + await foo; + }); + `, + }, { timeout: 1000 }); + expect(result.exitCode).toBe(1); + expect(result.failed).toBe(1); + expect(result.output).toContain('Timeout of 1000ms exceeded.'); + expect(result.output).toContain('Rejecting!'); +}); diff --git a/tests/playwright-test/playwright.spec.ts b/tests/playwright-test/playwright.spec.ts index bf9b70d675..2a8a5311cb 100644 --- a/tests/playwright-test/playwright.spec.ts +++ b/tests/playwright-test/playwright.spec.ts @@ -272,6 +272,30 @@ 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 error on timeout with shared page', async ({ runInlineTest }, testInfo) => { + const result = await runInlineTest({ + 'a.test.ts': ` + const { test } = pwt; + let page; + test.beforeAll(async ({ browser }) => { + page = await browser.newPage(); + }); + test('passed', async () => { + await page.setContent('
Click me
'); + }); + test('timedout', async () => { + await page.click('text=Missing'); + }); + `, + }, { workers: 1, timeout: 2000 }); + + expect(result.exitCode).toBe(1); + expect(result.passed).toBe(1); + expect(result.failed).toBe(1); + expect(result.output).toContain('waiting for selector "text=Missing"'); + expect(stripAscii(result.output)).toContain(`14 | await page.click('text=Missing');`); +}); + test('should not report waitForEventInfo as pending', async ({ runInlineTest }, testInfo) => { const result = await runInlineTest({ 'a.test.ts': `