From 6d27d2c029cb9a5a847b00c25ffd053534d11d16 Mon Sep 17 00:00:00 2001 From: Dmitry Gozman Date: Fri, 10 Mar 2023 13:45:47 -0800 Subject: [PATCH] fix(test runner): improved fixture teardown timeout error message (#21572) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The new message looks like this: ``` Test finished within timeout of 500ms, but tearing down "playwright configuration" ran out of time. Please allow more time for the test, since teardown is attributed towards the test timeout budget.ยท ``` References #21259. --- .../src/worker/fixtureRunner.ts | 6 ++--- .../src/worker/timeoutManager.ts | 23 +++++++++++++++---- tests/playwright-test/fixture-errors.spec.ts | 6 ++--- tests/playwright-test/timeout.spec.ts | 8 +++---- 4 files changed, 28 insertions(+), 15 deletions(-) diff --git a/packages/playwright-test/src/worker/fixtureRunner.ts b/packages/playwright-test/src/worker/fixtureRunner.ts index 42b3203674..240768adda 100644 --- a/packages/playwright-test/src/worker/fixtureRunner.ts +++ b/packages/playwright-test/src/worker/fixtureRunner.ts @@ -40,7 +40,8 @@ class Fixture { this.value = null; const title = this.registration.customTitle || this.registration.name; this._runnableDescription = { - title: this.registration.timeout !== undefined ? `Fixture "${title}"` : `setting up "${title}"`, + title, + phase: 'setup', location: registration.location, slot: this.registration.timeout === undefined ? undefined : { timeout: this.registration.timeout, @@ -113,8 +114,7 @@ class Fixture { } private _setTeardownDescription(timeoutManager: TimeoutManager) { - const title = this.registration.customTitle || this.registration.name; - this._runnableDescription.title = this.registration.timeout !== undefined ? `Fixture "${title}"` : `tearing down "${title}"`; + this._runnableDescription.phase = 'teardown'; timeoutManager.setCurrentFixture(this._runnableDescription); } diff --git a/packages/playwright-test/src/worker/timeoutManager.ts b/packages/playwright-test/src/worker/timeoutManager.ts index 66e8dbcc2e..8ec290857c 100644 --- a/packages/playwright-test/src/worker/timeoutManager.ts +++ b/packages/playwright-test/src/worker/timeoutManager.ts @@ -31,6 +31,7 @@ type RunnableDescription = { export type FixtureDescription = { title: string; + phase: 'setup' | 'teardown'; location?: Location; slot?: TimeSlot; // Falls back to current runnable slot. }; @@ -113,8 +114,18 @@ export class TimeoutManager { const timeout = this._currentSlot().timeout; switch (this._runnable.type) { case 'test': { - const fixtureSuffix = this._fixture ? ` while ${this._fixture.title}` : ''; - message = `Test timeout of ${timeout}ms exceeded${fixtureSuffix}.`; + if (this._fixture) { + if (this._fixture.phase === 'setup') { + message = `Test timeout of ${timeout}ms exceeded while setting up "${this._fixture.title}".`; + } else { + message = [ + `Test finished within timeout of ${timeout}ms, but tearing down "${this._fixture.title}" ran out of time.`, + `Please allow more time for the test, since teardown is attributed towards the test timeout budget.`, + ].join('\n'); + } + } else { + message = `Test timeout of ${timeout}ms exceeded.`; + } break; } case 'afterEach': @@ -126,8 +137,10 @@ export class TimeoutManager { message = `"${this._runnable.type}" hook timeout of ${timeout}ms exceeded.`; break; case 'teardown': { - const fixtureSuffix = this._fixture ? ` while ${this._fixture.title}` : ''; - message = `Worker teardown timeout of ${timeout}ms exceeded${fixtureSuffix}.`; + if (this._fixture) + message = `Worker teardown timeout of ${timeout}ms exceeded while ${this._fixture.phase === 'setup' ? 'setting up' : 'tearing down'} "${this._fixture.title}".`; + else + message = `Worker teardown timeout of ${timeout}ms exceeded.`; break; } case 'skip': @@ -139,7 +152,7 @@ export class TimeoutManager { } const fixtureWithSlot = this._fixture?.slot ? this._fixture : undefined; if (fixtureWithSlot) - message = `${fixtureWithSlot.title} timeout of ${timeout}ms exceeded.`; + message = `Fixture "${fixtureWithSlot.title}" timeout of ${timeout}ms exceeded during ${fixtureWithSlot.phase}.`; message = colors.red(message); const location = (fixtureWithSlot || this._runnable).location; return { diff --git a/tests/playwright-test/fixture-errors.spec.ts b/tests/playwright-test/fixture-errors.spec.ts index b29e952bb2..9dd7c11b1d 100644 --- a/tests/playwright-test/fixture-errors.spec.ts +++ b/tests/playwright-test/fixture-errors.spec.ts @@ -37,7 +37,7 @@ test('should handle fixture timeout', async ({ runInlineTest }) => { ` }, { timeout: 500 }); expect(result.exitCode).toBe(1); - expect(result.output).toContain('Test timeout of 500ms exceeded while tearing down "timeout".'); + expect(result.output).toContain('Test finished within timeout of 500ms, but tearing down "timeout" ran out of time.'); expect(result.failed).toBe(2); }); @@ -427,7 +427,7 @@ test('should give enough time for fixture teardown', async ({ runInlineTest }) = }); expect(result.exitCode).toBe(1); expect(result.failed).toBe(1); - expect(result.output).toContain('Test timeout of 1000ms exceeded while tearing down "fixture".'); + expect(result.output).toContain('Test finished within timeout of 1000ms, but tearing down "fixture" ran out of time.'); expect(result.outputLines).toEqual([ 'teardown start', 'teardown finished', @@ -493,7 +493,7 @@ test('should not report fixture teardown timeout twice', async ({ runInlineTest }, { reporter: 'list', timeout: 1000 }); expect(result.exitCode).toBe(1); expect(result.failed).toBe(1); - expect(result.output).toContain('Test timeout of 1000ms exceeded while tearing down "fixture".'); + expect(result.output).toContain('Test finished within timeout of 1000ms, but tearing down "fixture" ran out of time.'); expect(result.output).not.toContain('base.extend'); // Should not point to the location. // TODO: this should be "not.toContain" actually. expect(result.output).toContain('Worker teardown timeout of 1000ms exceeded while tearing down "fixture".'); diff --git a/tests/playwright-test/timeout.spec.ts b/tests/playwright-test/timeout.spec.ts index 9628cfe90b..74659bbb0c 100644 --- a/tests/playwright-test/timeout.spec.ts +++ b/tests/playwright-test/timeout.spec.ts @@ -200,8 +200,8 @@ test('should respect fixture timeout', async ({ runInlineTest }) => { expect(result.exitCode).toBe(1); expect(result.passed).toBe(1); expect(result.failed).toBe(2); - expect(result.output).toContain('Fixture "custom title" timeout of 500ms exceeded.'); - expect(result.output).toContain('Fixture "slowTeardown" timeout of 400ms exceeded.'); + expect(result.output).toContain('Fixture "custom title" timeout of 500ms exceeded during setup.'); + expect(result.output).toContain('Fixture "slowTeardown" timeout of 400ms exceeded during teardown.'); expect(result.output).toContain('> 3 | const test = base.extend({'); }); @@ -241,8 +241,8 @@ test('should respect test.setTimeout in the worker fixture', async ({ runInlineT expect(result.exitCode).toBe(1); expect(result.passed).toBe(2); expect(result.failed).toBe(1); - expect(result.output).toContain('Fixture "slowSetup" timeout of 500ms exceeded.'); - expect(result.output).toContain('Fixture "custom title" timeout of 400ms exceeded.'); + expect(result.output).toContain('Fixture "slowSetup" timeout of 500ms exceeded during setup.'); + expect(result.output).toContain('Fixture "custom title" timeout of 400ms exceeded during teardown.'); }); test('fixture time in beforeAll hook should not affect test', async ({ runInlineTest }) => {