From d214778548f10f86ba946d721ac00a89afab1c68 Mon Sep 17 00:00:00 2001 From: Dmitry Gozman Date: Fri, 8 Mar 2024 15:19:36 -0800 Subject: [PATCH] chore(test runner): move timeout handling to the top, stop inheriting runnable (#29857) --- .../playwright/src/worker/fixtureRunner.ts | 49 +++---- packages/playwright/src/worker/testInfo.ts | 70 ++++------ .../playwright/src/worker/timeoutManager.ts | 46 +++---- packages/playwright/src/worker/workerMain.ts | 130 ++++++++---------- tests/playwright-test/hooks.spec.ts | 2 +- .../playwright-test/playwright.trace.spec.ts | 5 + tests/playwright-test/reporter.spec.ts | 6 +- tests/playwright-test/test-step.spec.ts | 45 ++++++ tests/playwright-test/timeout.spec.ts | 35 +++++ tests/playwright-test/ui-mode-trace.spec.ts | 1 + 10 files changed, 213 insertions(+), 176 deletions(-) diff --git a/packages/playwright/src/worker/fixtureRunner.ts b/packages/playwright/src/worker/fixtureRunner.ts index 107bdb9c1f..f425f1cd3e 100644 --- a/packages/playwright/src/worker/fixtureRunner.ts +++ b/packages/playwright/src/worker/fixtureRunner.ts @@ -17,7 +17,7 @@ import { formatLocation, filterStackFile } from '../util'; import { ManualPromise } from 'playwright-core/lib/utils'; import type { TestInfoImpl } from './testInfo'; -import { TimeoutManagerError, type FixtureDescription } from './timeoutManager'; +import { TimeoutManagerError, type FixtureDescription, type RunnableDescription } from './timeoutManager'; import { fixtureParameterNames, type FixturePool, type FixtureRegistration, type FixtureScope } from '../common/fixtures'; import type { WorkerInfo } from '../../types/test'; import type { Location } from '../../types/testReporter'; @@ -32,8 +32,7 @@ class Fixture { private _selfTeardownComplete: Promise | undefined; private _setupDescription: FixtureDescription; private _teardownDescription: FixtureDescription; - private _shouldGenerateStep = false; - private _isInternalFixture = false; + private _stepInfo: { category: 'fixture', location?: Location } | undefined; _deps = new Set(); _usages = new Set(); @@ -41,22 +40,24 @@ class Fixture { this.runner = runner; this.registration = registration; this.value = null; + const shouldGenerateStep = !this.registration.hideStep && !this.registration.name.startsWith('_') && !this.registration.option; + const isInternalFixture = this.registration.location && filterStackFile(this.registration.location.file); const title = this.registration.customTitle || this.registration.name; + const location = isInternalFixture ? this.registration.location : undefined; + this._stepInfo = shouldGenerateStep ? { category: 'fixture', location } : undefined; this._setupDescription = { title, phase: 'setup', - location: registration.location, + location, slot: this.registration.timeout === undefined ? undefined : { timeout: this.registration.timeout, elapsed: 0, } }; this._teardownDescription = { ...this._setupDescription, phase: 'teardown' }; - this._shouldGenerateStep = !this.registration.hideStep && !this.registration.name.startsWith('_') && !this.registration.option; - this._isInternalFixture = this.registration.location && filterStackFile(this.registration.location.file); } - async setup(testInfo: TestInfoImpl) { + async setup(testInfo: TestInfoImpl, runnable: RunnableDescription) { this.runner.instanceForId.set(this.registration.id, this); if (typeof this.registration.fn !== 'function') { @@ -66,13 +67,10 @@ class Fixture { await testInfo._runAsStage({ title: `fixture: ${this.registration.name}`, - canTimeout: true, - location: this._isInternalFixture ? this.registration.location : undefined, - stepCategory: this._shouldGenerateStep ? 'fixture' : undefined, + runnable: { ...runnable, fixture: this._setupDescription }, + stepInfo: this._stepInfo, }, async () => { - testInfo._timeoutManager.setCurrentFixture(this._setupDescription); await this._setupInternal(testInfo); - testInfo._timeoutManager.setCurrentFixture(undefined); }); } @@ -126,16 +124,13 @@ class Fixture { await useFuncStarted; } - async teardown(testInfo: TestInfoImpl) { + async teardown(testInfo: TestInfoImpl, runnable: RunnableDescription) { await testInfo._runAsStage({ title: `fixture: ${this.registration.name}`, - canTimeout: true, - location: this._isInternalFixture ? this.registration.location : undefined, - stepCategory: this._shouldGenerateStep ? 'fixture' : undefined, + runnable: { ...runnable, fixture: this._teardownDescription }, + stepInfo: this._stepInfo, }, async () => { - testInfo._timeoutManager.setCurrentFixture(this._teardownDescription); await this._teardownInternal(); - testInfo._timeoutManager.setCurrentFixture(undefined); }); } @@ -202,7 +197,7 @@ export class FixtureRunner { collector.add(registration); } - async teardownScope(scope: FixtureScope, testInfo: TestInfoImpl) { + async teardownScope(scope: FixtureScope, testInfo: TestInfoImpl, runnable: RunnableDescription) { // Teardown fixtures in the reverse order. const fixtures = Array.from(this.instanceForId.values()).reverse(); const collector = new Set(); @@ -212,7 +207,7 @@ export class FixtureRunner { let firstError: Error | undefined; for (const fixture of collector) { try { - await fixture.teardown(testInfo); + await fixture.teardown(testInfo, runnable); } catch (error) { if (error instanceof TimeoutManagerError) throw error; @@ -231,7 +226,7 @@ export class FixtureRunner { } } - async resolveParametersForFunction(fn: Function, testInfo: TestInfoImpl, autoFixtures: 'worker' | 'test' | 'all-hooks-only'): Promise { + async resolveParametersForFunction(fn: Function, testInfo: TestInfoImpl, autoFixtures: 'worker' | 'test' | 'all-hooks-only', runnable: RunnableDescription): Promise { const collector = new Set(); // Collect automatic fixtures. @@ -256,7 +251,7 @@ export class FixtureRunner { // Setup fixtures. for (const registration of collector) - await this._setupFixtureForRegistration(registration, testInfo); + await this._setupFixtureForRegistration(registration, testInfo, runnable); // Create params object. const params: { [key: string]: any } = {}; @@ -270,18 +265,18 @@ export class FixtureRunner { return params; } - async resolveParametersAndRunFunction(fn: Function, testInfo: TestInfoImpl, autoFixtures: 'worker' | 'test' | 'all-hooks-only') { - const params = await this.resolveParametersForFunction(fn, testInfo, autoFixtures); + async resolveParametersAndRunFunction(fn: Function, testInfo: TestInfoImpl, autoFixtures: 'worker' | 'test' | 'all-hooks-only', runnable: RunnableDescription) { + const params = await this.resolveParametersForFunction(fn, testInfo, autoFixtures, runnable); if (params === null) { // Do not run the function when fixture setup has already failed. return null; } - await testInfo._runAsStage({ title: 'run function', canTimeout: true }, async () => { + await testInfo._runAsStage({ title: 'run function', runnable }, async () => { await fn(params, testInfo); }); } - private async _setupFixtureForRegistration(registration: FixtureRegistration, testInfo: TestInfoImpl): Promise { + private async _setupFixtureForRegistration(registration: FixtureRegistration, testInfo: TestInfoImpl, runnable: RunnableDescription): Promise { if (registration.scope === 'test') this.testScopeClean = false; @@ -290,7 +285,7 @@ export class FixtureRunner { return fixture; fixture = new Fixture(this, registration); - await fixture.setup(testInfo); + await fixture.setup(testInfo, runnable); return fixture; } diff --git a/packages/playwright/src/worker/testInfo.ts b/packages/playwright/src/worker/testInfo.ts index 4678812759..372f01d93f 100644 --- a/packages/playwright/src/worker/testInfo.ts +++ b/packages/playwright/src/worker/testInfo.ts @@ -21,7 +21,7 @@ import type { TestInfoError, TestInfo, TestStatus, FullProject, FullConfig } fro import type { AttachmentPayload, StepBeginPayload, StepEndPayload, WorkerInitParams } from '../common/ipc'; import type { TestCase } from '../common/test'; import { TimeoutManager, TimeoutManagerError } from './timeoutManager'; -import type { RunnableDescription, RunnableType, TimeSlot } from './timeoutManager'; +import type { RunnableDescription } from './timeoutManager'; import type { Annotation, FullConfigInternal, FullProjectInternal } from '../common/config'; import type { Location } from '../../types/testReporter'; import { debugTest, filteredStackTrace, formatLocation, getContainedPath, normalizeAndSaveAttachment, serializeError, trimLongString } from '../util'; @@ -50,12 +50,8 @@ export interface TestStepInternal { export type TestStage = { title: string; - location?: Location; - stepCategory?: 'hook' | 'fixture'; - runnableType?: RunnableType; - runnableSlot?: TimeSlot; - canTimeout?: boolean; - allowSkip?: boolean; + stepInfo?: { category: 'hook' | 'fixture', location?: Location }; + runnable?: RunnableDescription; step?: TestStepInternal; }; @@ -69,7 +65,6 @@ export class TestInfoImpl implements TestInfo { private _hasHardError: boolean = false; readonly _tracing: TestTracing; - _didTimeout = false; _wasInterrupted = false; _lastStepId = 0; private readonly _requireFile: string; @@ -79,6 +74,7 @@ export class TestInfoImpl implements TestInfo { _onDidFinishTestFunction: (() => Promise) | undefined; private readonly _stages: TestStage[] = []; _hasNonRetriableError = false; + _allowSkips = false; // ------------ TestInfo fields ------------ readonly testId: string; @@ -354,13 +350,13 @@ export class TestInfoImpl implements TestInfo { // Do not overwrite any previous hard errors. // Some (but not all) scenarios include: // - expect() that fails after uncaught exception. - // - fail after the timeout, e.g. due to fixture teardown. + // - fail in fixture teardown after the test failure. if (isHardError && this._hasHardError) return; if (isHardError) this._hasHardError = true; if (this.status === 'passed' || this.status === 'skipped') - this.status = 'failed'; + this.status = error instanceof TimeoutManagerError ? 'timedOut' : 'failed'; const serialized = serializeError(error); const step = (error as any)[stepSymbol] as TestStepInternal | undefined; if (step && step.boxedStack) @@ -370,43 +366,29 @@ export class TestInfoImpl implements TestInfo { } async _runAsStage(stage: TestStage, cb: () => Promise) { - // Inherit some properties from parent. - const parent = this._stages[this._stages.length - 1]; - stage.allowSkip = stage.allowSkip ?? parent?.allowSkip ?? false; - if (debugTest.enabled) { - const location = stage.location ? ` at "${formatLocation(stage.location)}"` : ``; + const location = stage.runnable?.location ? ` at "${formatLocation(stage.runnable.location)}"` : ``; debugTest(`started stage "${stage.title}"${location}`); } - stage.step = stage.stepCategory ? this._addStep({ title: stage.title, category: stage.stepCategory, location: stage.location, wallTime: Date.now(), isStage: true }) : undefined; + stage.step = stage.stepInfo ? this._addStep({ ...stage.stepInfo, title: stage.title, wallTime: Date.now(), isStage: true }) : undefined; this._stages.push(stage); - let runnable: RunnableDescription | undefined; - if (stage.canTimeout) { - // Choose the deepest runnable configuration. - runnable = { type: 'test' }; - for (const s of this._stages) { - if (s.runnableType) { - runnable.type = s.runnableType; - runnable.location = s.location; - } - if (s.runnableSlot) - runnable.slot = s.runnableSlot; - } - } - try { - await this._timeoutManager.withRunnable(runnable, async () => { - // Note: separate try/catch is here to report errors after timeout. - // This way we get a nice "locator.click" error after the test times out and closes the page. + await this._timeoutManager.withRunnable(stage.runnable, async () => { try { await cb(); } catch (e) { - if (stage.allowSkip && (e instanceof SkipError)) { + if (this._allowSkips && (e instanceof SkipError)) { if (this.status === 'passed') this.status = 'skipped'; } else if (!(e instanceof TimeoutManagerError)) { - // Do not consider timeout errors in child stages as a regular "hard error". + // Note: we handle timeout errors at the top level, so ignore them here. + // Unfortunately, we cannot ignore user errors here. Consider the following scenario: + // - locator.click times out + // - all stages containing the test function finish with TimeoutManagerError + // - test finishes, the page is closed and this triggers locator.click error + // - we would like to present the locator.click error to the user + // - therefore, we need a try/catch inside the "run with timeout" block and capture the error this._failWithError(e, true /* isHardError */, true /* retriable */); } throw e; @@ -414,17 +396,6 @@ export class TestInfoImpl implements TestInfo { }); stage.step?.complete({}); } catch (error) { - // When interrupting, we arrive here with a TimeoutManagerError, but we should not - // consider it a timeout. - if (!this._wasInterrupted && !this._didTimeout && (error instanceof TimeoutManagerError)) { - this._didTimeout = true; - const serialized = serializeError(error); - this.errors.push(serialized); - this._tracing.appendForError(serialized); - // Do not overwrite existing failure upon hook/teardown timeout. - if (this.status === 'passed' || this.status === 'skipped') - this.status = 'timedOut'; - } stage.step?.complete({ error }); throw error; } finally { @@ -435,6 +406,13 @@ export class TestInfoImpl implements TestInfo { } } + _handlePossibleTimeoutError(error: Error) { + // When interrupting, we arrive here with a TimeoutManagerError, but we should not + // consider it a timeout. + if (!this._wasInterrupted && (error instanceof TimeoutManagerError)) + this._failWithError(error, false /* isHardError */, true /* retriable */); + } + _isFailure() { return this.status !== 'skipped' && this.status !== this.expectedStatus; } diff --git a/packages/playwright/src/worker/timeoutManager.ts b/packages/playwright/src/worker/timeoutManager.ts index d90ee06547..f253e2e0a4 100644 --- a/packages/playwright/src/worker/timeoutManager.ts +++ b/packages/playwright/src/worker/timeoutManager.ts @@ -23,32 +23,30 @@ export type TimeSlot = { elapsed: number; }; -export type RunnableType = 'test' | 'beforeAll' | 'afterAll' | 'beforeEach' | 'afterEach' | 'afterHooks' | 'slow' | 'skip' | 'fail' | 'fixme' | 'teardown'; +type RunnableType = 'test' | 'beforeAll' | 'afterAll' | 'beforeEach' | 'afterEach' | 'slow' | 'skip' | 'fail' | 'fixme' | 'teardown'; export type RunnableDescription = { type: RunnableType; location?: Location; slot?: TimeSlot; // Falls back to test slot. + fixture?: FixtureDescription; }; export type FixtureDescription = { title: string; phase: 'setup' | 'teardown'; location?: Location; - slot?: TimeSlot; // Falls back to current runnable slot. + slot?: TimeSlot; // Falls back to the runnable slot. }; export class TimeoutManager { private _defaultSlot: TimeSlot; - private _defaultRunnable: RunnableDescription; private _runnable: RunnableDescription; - private _fixture: FixtureDescription | undefined; private _timeoutRunner: TimeoutRunner; constructor(timeout: number) { this._defaultSlot = { timeout, elapsed: 0 }; - this._defaultRunnable = { type: 'test', slot: this._defaultSlot }; - this._runnable = this._defaultRunnable; + this._runnable = { type: 'test' }; this._timeoutRunner = new TimeoutRunner(timeout); } @@ -59,11 +57,7 @@ export class TimeoutManager { async withRunnable(runnable: RunnableDescription | undefined, cb: () => Promise): Promise { if (!runnable) return await cb(); - const existingRunnable = this._runnable; - const effectiveRunnable = { ...runnable }; - if (!effectiveRunnable.slot) - effectiveRunnable.slot = this._runnable.slot; - this._updateRunnables(effectiveRunnable, undefined); + this._updateRunnable(runnable); try { return await this._timeoutRunner.run(cb); } catch (error) { @@ -71,14 +65,10 @@ export class TimeoutManager { throw error; throw this._createTimeoutError(); } finally { - this._updateRunnables(existingRunnable, undefined); + this._updateRunnable({ type: 'test' }); } } - setCurrentFixture(fixture: FixtureDescription | undefined) { - this._updateRunnables(this._runnable, fixture); - } - defaultSlotTimings() { const slot = this._currentSlot(); slot.elapsed = this._timeoutRunner.elapsed(); @@ -100,7 +90,7 @@ export class TimeoutManager { } currentRunnableType() { - return this._runnable.type; + return this._runnable?.type || 'test'; } currentSlotDeadline() { @@ -108,15 +98,14 @@ export class TimeoutManager { } private _currentSlot() { - return this._fixture?.slot || this._runnable.slot || this._defaultSlot; + return this._runnable.fixture?.slot || this._runnable.slot || this._defaultSlot; } - private _updateRunnables(runnable: RunnableDescription, fixture: FixtureDescription | undefined) { + private _updateRunnable(runnable: RunnableDescription) { let slot = this._currentSlot(); slot.elapsed = this._timeoutRunner.elapsed(); this._runnable = runnable; - this._fixture = fixture; slot = this._currentSlot(); this._timeoutRunner.updateTimeout(slot.timeout, slot.elapsed); @@ -125,15 +114,14 @@ export class TimeoutManager { private _createTimeoutError(): Error { let message = ''; const timeout = this._currentSlot().timeout; - switch (this._runnable.type) { - case 'afterHooks': + switch (this._runnable.type || 'test') { case 'test': { - if (this._fixture) { - if (this._fixture.phase === 'setup') { - message = `Test timeout of ${timeout}ms exceeded while setting up "${this._fixture.title}".`; + if (this._runnable.fixture) { + if (this._runnable.fixture.phase === 'setup') { + message = `Test timeout of ${timeout}ms exceeded while setting up "${this._runnable.fixture.title}".`; } else { message = [ - `Test finished within timeout of ${timeout}ms, but tearing down "${this._fixture.title}" ran out of time.`, + `Test finished within timeout of ${timeout}ms, but tearing down "${this._runnable.fixture.title}" ran out of time.`, `Please allow more time for the test, since teardown is attributed towards the test timeout budget.`, ].join('\n'); } @@ -151,8 +139,8 @@ export class TimeoutManager { message = `"${this._runnable.type}" hook timeout of ${timeout}ms exceeded.`; break; case 'teardown': { - if (this._fixture) - message = `Worker teardown timeout of ${timeout}ms exceeded while ${this._fixture.phase === 'setup' ? 'setting up' : 'tearing down'} "${this._fixture.title}".`; + if (this._runnable.fixture) + message = `Worker teardown timeout of ${timeout}ms exceeded while ${this._runnable.fixture.phase === 'setup' ? 'setting up' : 'tearing down'} "${this._runnable.fixture.title}".`; else message = `Worker teardown timeout of ${timeout}ms exceeded.`; break; @@ -164,7 +152,7 @@ export class TimeoutManager { message = `"${this._runnable.type}" modifier timeout of ${timeout}ms exceeded.`; break; } - const fixtureWithSlot = this._fixture?.slot ? this._fixture : undefined; + const fixtureWithSlot = this._runnable.fixture?.slot ? this._runnable.fixture : undefined; if (fixtureWithSlot) message = `Fixture "${fixtureWithSlot.title}" timeout of ${timeout}ms exceeded during ${fixtureWithSlot.phase}.`; message = colors.red(message); diff --git a/packages/playwright/src/worker/workerMain.ts b/packages/playwright/src/worker/workerMain.ts index 5cd95d77e2..8865dd2120 100644 --- a/packages/playwright/src/worker/workerMain.ts +++ b/packages/playwright/src/worker/workerMain.ts @@ -31,7 +31,7 @@ import { PoolBuilder } from '../common/poolBuilder'; import type { TestInfoError } from '../../types/test'; import type { Location } from '../../types/testReporter'; import { inheritFixutreNames } from '../common/fixtures'; -import { TimeoutManagerError } from './timeoutManager'; +import { type TimeSlot, TimeoutManagerError } from './timeoutManager'; export class WorkerMain extends ProcessRunner { private _params: WorkerInitParams; @@ -145,15 +145,10 @@ export class WorkerMain extends ProcessRunner { } private async _teardownScopes() { - // TODO: separate timeout for teardown? const fakeTestInfo = new TestInfoImpl(this._config, this._project, this._params, undefined, 0, () => {}, () => {}, () => {}); - await fakeTestInfo._runAsStage({ title: 'teardown scopes', runnableType: 'teardown' }, async () => { - try { - await this._fixtureRunner.teardownScope('test', fakeTestInfo); - } finally { - await this._fixtureRunner.teardownScope('worker', fakeTestInfo); - } - }); + const runnable = { type: 'teardown' } as const; + await this._fixtureRunner.teardownScope('test', fakeTestInfo, runnable).catch(error => fakeTestInfo._handlePossibleTimeoutError(error)); + await this._fixtureRunner.teardownScope('worker', fakeTestInfo, runnable).catch(error => fakeTestInfo._handlePossibleTimeoutError(error)); this._fatalErrors.push(...fakeTestInfo.errors); } @@ -310,8 +305,9 @@ export class WorkerMain extends ProcessRunner { this._lastRunningTests.shift(); let shouldRunAfterEachHooks = false; - await testInfo._runAsStage({ title: 'setup and test', runnableType: 'test', allowSkip: true }, async () => { - await testInfo._runAsStage({ title: 'start tracing', canTimeout: true }, async () => { + testInfo._allowSkips = true; + await testInfo._runAsStage({ title: 'setup and test' }, async () => { + await testInfo._runAsStage({ title: 'start tracing', runnable: { type: 'test' } }, async () => { // Ideally, "trace" would be an config-level option belonging to the // test runner instead of a fixture belonging to Playwright. // However, for backwards compatibility, we have to read it from a fixture today. @@ -336,7 +332,7 @@ export class WorkerMain extends ProcessRunner { await removeFolders([testInfo.outputDir]); let testFunctionParams: object | null = null; - await testInfo._runAsStage({ title: 'Before Hooks', stepCategory: 'hook' }, async () => { + await testInfo._runAsStage({ title: 'Before Hooks', stepInfo: { category: 'hook' } }, async () => { // Run "beforeAll" hooks, unless already run during previous tests. for (const suite of suites) await this._runBeforeAllHooksForSuite(suite, testInfo); @@ -346,7 +342,7 @@ export class WorkerMain extends ProcessRunner { await this._runEachHooksForSuites(suites, 'beforeEach', testInfo); // Setup fixtures required by the test. - testFunctionParams = await this._fixtureRunner.resolveParametersForFunction(test.fn, testInfo, 'test'); + testFunctionParams = await this._fixtureRunner.resolveParametersForFunction(test.fn, testInfo, 'test', { type: 'test' }); }); if (testFunctionParams === null) { @@ -354,58 +350,54 @@ export class WorkerMain extends ProcessRunner { return; } - await testInfo._runAsStage({ title: 'test function', canTimeout: true }, async () => { + await testInfo._runAsStage({ title: 'test function', runnable: { type: 'test' } }, async () => { // Now run the test itself. const fn = test.fn; // Extract a variable to get a better stack trace ("myTest" vs "TestCase.myTest [as fn]"). await fn(testFunctionParams, testInfo); }); - }).catch(() => {}); // Ignore top-level error, we still have to run after hooks. + }).catch(error => testInfo._handlePossibleTimeoutError(error)); // Update duration, so it is available in fixture teardown and afterEach hooks. testInfo.duration = testInfo._timeoutManager.defaultSlotTimings().elapsed | 0; + // No skips in after hooks. + testInfo._allowSkips = true; + // After hooks get an additional timeout. const afterHooksTimeout = calculateMaxTimeout(this._project.project.timeout, testInfo.timeout); const afterHooksSlot = { timeout: afterHooksTimeout, elapsed: 0 }; - await testInfo._runAsStage({ - title: 'After Hooks', - stepCategory: 'hook', - runnableType: 'afterHooks', - runnableSlot: afterHooksSlot, - }, async () => { + await testInfo._runAsStage({ title: 'After Hooks', stepInfo: { category: 'hook' } }, async () => { let firstAfterHooksError: Error | undefined; - let didTimeoutInRegularCleanup = false; + let didTimeoutInAfterHooks = false; try { // Run "immediately upon test function finish" callback. - await testInfo._runAsStage({ title: 'on-test-function-finish', canTimeout: true }, async () => testInfo._onDidFinishTestFunction?.()); + await testInfo._runAsStage({ title: 'on-test-function-finish', runnable: { type: 'test', slot: afterHooksSlot } }, async () => testInfo._onDidFinishTestFunction?.()); } catch (error) { if (error instanceof TimeoutManagerError) - didTimeoutInRegularCleanup = true; + didTimeoutInAfterHooks = true; firstAfterHooksError = firstAfterHooksError ?? error; } try { // Run "afterEach" hooks, unless we failed at beforeAll stage. - if (!didTimeoutInRegularCleanup && shouldRunAfterEachHooks) - await this._runEachHooksForSuites(reversedSuites, 'afterEach', testInfo); + if (!didTimeoutInAfterHooks && shouldRunAfterEachHooks) + await this._runEachHooksForSuites(reversedSuites, 'afterEach', testInfo, afterHooksSlot); } catch (error) { if (error instanceof TimeoutManagerError) - didTimeoutInRegularCleanup = true; + didTimeoutInAfterHooks = true; firstAfterHooksError = firstAfterHooksError ?? error; } try { - if (!didTimeoutInRegularCleanup) { + if (!didTimeoutInAfterHooks) { // Teardown test-scoped fixtures. Attribute to 'test' so that users understand // they should probably increase the test timeout to fix this issue. - await testInfo._runAsStage({ title: 'teardown test scope', runnableType: 'test' }, async () => { - await this._fixtureRunner.teardownScope('test', testInfo); - }); + await this._fixtureRunner.teardownScope('test', testInfo, { type: 'test', slot: afterHooksSlot }); } } catch (error) { if (error instanceof TimeoutManagerError) - didTimeoutInRegularCleanup = true; + didTimeoutInAfterHooks = true; firstAfterHooksError = firstAfterHooksError ?? error; } @@ -422,51 +414,54 @@ export class WorkerMain extends ProcessRunner { } } } + if (firstAfterHooksError) + throw firstAfterHooksError; + }).catch(error => testInfo._handlePossibleTimeoutError(error)); - if (testInfo._isFailure()) - this._isStopped = true; + if (testInfo._isFailure()) + this._isStopped = true; - if (this._isStopped) { - // Run all remaining "afterAll" hooks and teardown all fixtures when worker is shutting down. - // Mark as "cleaned up" early to avoid running cleanup twice. - this._didRunFullCleanup = true; + if (this._isStopped) { + // Run all remaining "afterAll" hooks and teardown all fixtures when worker is shutting down. + // Mark as "cleaned up" early to avoid running cleanup twice. + this._didRunFullCleanup = true; + + await testInfo._runAsStage({ title: 'Worker Cleanup', stepInfo: { category: 'hook' } }, async () => { + let firstWorkerCleanupError: Error | undefined; // Give it more time for the full cleanup. const teardownSlot = { timeout: this._project.project.timeout, elapsed: 0 }; try { // Attribute to 'test' so that users understand they should probably increate the test timeout to fix this issue. - await testInfo._runAsStage({ title: 'teardown test scope', runnableType: 'test', runnableSlot: teardownSlot }, async () => { - await this._fixtureRunner.teardownScope('test', testInfo); - }); + await this._fixtureRunner.teardownScope('test', testInfo, { type: 'test', slot: teardownSlot }); } catch (error) { - firstAfterHooksError = firstAfterHooksError ?? error; + firstWorkerCleanupError = firstWorkerCleanupError ?? error; } for (const suite of reversedSuites) { try { await this._runAfterAllHooksForSuite(suite, testInfo); } catch (error) { - firstAfterHooksError = firstAfterHooksError ?? error; + firstWorkerCleanupError = firstWorkerCleanupError ?? error; } } try { // Attribute to 'teardown' because worker fixtures are not perceived as a part of a test. - await testInfo._runAsStage({ title: 'teardown worker scope', runnableType: 'teardown', runnableSlot: teardownSlot }, async () => { - await this._fixtureRunner.teardownScope('worker', testInfo); - }); + await this._fixtureRunner.teardownScope('worker', testInfo, { type: 'teardown', slot: teardownSlot }); } catch (error) { - firstAfterHooksError = firstAfterHooksError ?? error; + firstWorkerCleanupError = firstWorkerCleanupError ?? error; } - } - if (firstAfterHooksError) - throw firstAfterHooksError; - }).catch(() => {}); // Ignore top-level error. + if (firstWorkerCleanupError) + throw firstWorkerCleanupError; + }).catch(error => testInfo._handlePossibleTimeoutError(error)); + } - await testInfo._runAsStage({ title: 'stop tracing' }, async () => { + const tracingSlot = { timeout: this._project.project.timeout, elapsed: 0 }; + await testInfo._runAsStage({ title: 'stop tracing', runnable: { type: 'test', slot: tracingSlot } }, async () => { await testInfo._tracing.stopIfNeeded(); - }).catch(() => {}); // Ignore top-level error. + }).catch(error => testInfo._handlePossibleTimeoutError(error)); testInfo.duration = (testInfo._timeoutManager.defaultSlotTimings().elapsed + afterHooksSlot.elapsed) | 0; @@ -517,18 +512,13 @@ export class WorkerMain extends ProcessRunner { let firstError: Error | undefined; for (const hook of this._collectHooksAndModifiers(suite, type, testInfo)) { try { - // Separate time slot for each beforeAll/afterAll hook. - const timeSlot = { timeout: this._project.project.timeout, elapsed: 0 }; - await testInfo._runAsStage({ - title: hook.title, - runnableType: hook.type, - runnableSlot: timeSlot, - stepCategory: 'hook', - location: hook.location, - }, async () => { + await testInfo._runAsStage({ title: hook.title, stepInfo: { category: 'hook', location: hook.location } }, async () => { + // Separate time slot for each beforeAll/afterAll hook. + const timeSlot = { timeout: this._project.project.timeout, elapsed: 0 }; + const runnable = { type: hook.type, slot: timeSlot, location: hook.location }; const existingAnnotations = new Set(testInfo.annotations); try { - await this._fixtureRunner.resolveParametersAndRunFunction(hook.fn, testInfo, 'all-hooks-only'); + await this._fixtureRunner.resolveParametersAndRunFunction(hook.fn, testInfo, 'all-hooks-only', runnable); } finally { if (extraAnnotations) { // Inherit all annotations defined in the beforeAll/modifer to all tests in the suite. @@ -537,7 +527,7 @@ export class WorkerMain extends ProcessRunner { } // Each beforeAll/afterAll hook has its own scope for test fixtures. Attribute to the same runnable and timeSlot. // Note: we must teardown even after hook fails, because we'll run more hooks. - await this._fixtureRunner.teardownScope('test', testInfo); + await this._fixtureRunner.teardownScope('test', testInfo, runnable); } }); } catch (error) { @@ -564,19 +554,15 @@ export class WorkerMain extends ProcessRunner { await this._runAllHooksForSuite(suite, testInfo, 'afterAll'); } - private async _runEachHooksForSuites(suites: Suite[], type: 'beforeEach' | 'afterEach', testInfo: TestInfoImpl) { + private async _runEachHooksForSuites(suites: Suite[], type: 'beforeEach' | 'afterEach', testInfo: TestInfoImpl, slot?: TimeSlot) { // Always run all the hooks, unless one of the times out, and capture the first error. let firstError: Error | undefined; const hooks = suites.map(suite => this._collectHooksAndModifiers(suite, type, testInfo)).flat(); for (const hook of hooks) { try { - await testInfo._runAsStage({ - title: hook.title, - runnableType: hook.type, - location: hook.location, - stepCategory: 'hook', - }, async () => { - await this._fixtureRunner.resolveParametersAndRunFunction(hook.fn, testInfo, 'test'); + await testInfo._runAsStage({ title: hook.title, stepInfo: { category: 'hook', location: hook.location } }, async () => { + const runnable = { type: hook.type, location: hook.location, slot }; + await this._fixtureRunner.resolveParametersAndRunFunction(hook.fn, testInfo, 'test', runnable); }); } catch (error) { if (error instanceof TimeoutManagerError) diff --git a/tests/playwright-test/hooks.spec.ts b/tests/playwright-test/hooks.spec.ts index dcc497f6dc..4d8999ba3f 100644 --- a/tests/playwright-test/hooks.spec.ts +++ b/tests/playwright-test/hooks.spec.ts @@ -526,7 +526,7 @@ test('afterAll timeout should be reported, run other afterAll hooks, and continu test.afterAll(async () => { console.log('\\n%%afterAll2'); }); - test('does not run', () => { + test('run in a different worker', () => { console.log('\\n%%test2'); }); `, diff --git a/tests/playwright-test/playwright.trace.spec.ts b/tests/playwright-test/playwright.trace.spec.ts index 95450bf483..dee65c9a52 100644 --- a/tests/playwright-test/playwright.trace.spec.ts +++ b/tests/playwright-test/playwright.trace.spec.ts @@ -129,6 +129,7 @@ test('should record api trace', async ({ runInlineTest, server }, testInfo) => { ' fixture: context', ' fixture: request', ' apiRequestContext.dispose', + 'Worker Cleanup', ' fixture: browser', ]); }); @@ -332,6 +333,7 @@ test('should not override trace file in afterAll', async ({ runInlineTest, serve ' apiRequestContext.get', ' fixture: request', ' apiRequestContext.dispose', + 'Worker Cleanup', ' fixture: browser', ]); expect(trace1.errors).toEqual([`'oh no!'`]); @@ -667,6 +669,7 @@ test('should show non-expect error in trace', async ({ runInlineTest }, testInfo 'After Hooks', ' fixture: page', ' fixture: context', + 'Worker Cleanup', ' fixture: browser', ]); expect(trace.errors).toEqual(['ReferenceError: undefinedVariable1 is not defined']); @@ -985,6 +988,7 @@ test('should record nested steps, even after timeout', async ({ runInlineTest }, ' barPage teardown', ' step in barPage teardown', ' page.close', + 'Worker Cleanup', ' fixture: browser', ]); }); @@ -1029,6 +1033,7 @@ test('should attribute worker fixture teardown to the right test', async ({ runI expect(trace2.actionTree).toEqual([ 'Before Hooks', 'After Hooks', + 'Worker Cleanup', ' fixture: foo', ' step in foo teardown', ]); diff --git a/tests/playwright-test/reporter.spec.ts b/tests/playwright-test/reporter.spec.ts index aaa24f7fbd..3c0f81e1f0 100644 --- a/tests/playwright-test/reporter.spec.ts +++ b/tests/playwright-test/reporter.spec.ts @@ -277,6 +277,8 @@ for (const useIntermediateMergeReport of [false, true] as const) { `end {\"title\":\"expect.toBeTruthy\",\"category\":\"expect\",\"error\":{\"message\":\"Error: \\u001b[2mexpect(\\u001b[22m\\u001b[31mreceived\\u001b[39m\\u001b[2m).\\u001b[22mtoBeTruthy\\u001b[2m()\\u001b[22m\\n\\nReceived: \\u001b[31mfalse\\u001b[39m\",\"stack\":\"\",\"location\":\"\",\"snippet\":\"\"}}`, `begin {\"title\":\"After Hooks\",\"category\":\"hook\"}`, `end {\"title\":\"After Hooks\",\"category\":\"hook\"}`, + `begin {\"title\":\"Worker Cleanup\",\"category\":\"hook\"}`, + `end {\"title\":\"Worker Cleanup\",\"category\":\"hook\"}`, `begin {\"title\":\"Before Hooks\",\"category\":\"hook\"}`, `end {\"title\":\"Before Hooks\",\"category\":\"hook\"}`, `begin {\"title\":\"expect.not.toBeTruthy\",\"category\":\"expect\"}`, @@ -460,9 +462,11 @@ for (const useIntermediateMergeReport of [false, true] as const) { `end {\"title\":\"fixture: page\",\"category\":\"fixture\"}`, `begin {\"title\":\"fixture: context\",\"category\":\"fixture\"}`, `end {\"title\":\"fixture: context\",\"category\":\"fixture\"}`, + `end {\"title\":\"After Hooks\",\"category\":\"hook\",\"steps\":[{\"title\":\"fixture: page\",\"category\":\"fixture\"},{\"title\":\"fixture: context\",\"category\":\"fixture\"}]}`, + `begin {\"title\":\"Worker Cleanup\",\"category\":\"hook\"}`, `begin {\"title\":\"fixture: browser\",\"category\":\"fixture\"}`, `end {\"title\":\"fixture: browser\",\"category\":\"fixture\"}`, - `end {\"title\":\"After Hooks\",\"category\":\"hook\",\"steps\":[{\"title\":\"fixture: page\",\"category\":\"fixture\"},{\"title\":\"fixture: context\",\"category\":\"fixture\"},{\"title\":\"fixture: browser\",\"category\":\"fixture\"}]}`, + `end {\"title\":\"Worker Cleanup\",\"category\":\"hook\",\"steps\":[{\"title\":\"fixture: browser\",\"category\":\"fixture\"}]}`, ]); }); diff --git a/tests/playwright-test/test-step.spec.ts b/tests/playwright-test/test-step.spec.ts index c00521e9ae..4aa07c6a52 100644 --- a/tests/playwright-test/test-step.spec.ts +++ b/tests/playwright-test/test-step.spec.ts @@ -261,6 +261,10 @@ test('should report before hooks step error', async ({ runInlineTest }) => { category: 'hook', title: 'After Hooks', }, + { + category: 'hook', + title: 'Worker Cleanup', + }, { error: expect.any(Object) } @@ -345,6 +349,12 @@ test('should not report nested after hooks', async ({ runInlineTest }) => { category: 'fixture', title: 'fixture: context', }, + ], + }, + { + category: 'hook', + title: 'Worker Cleanup', + steps: [ { category: 'fixture', title: 'fixture: browser', @@ -577,6 +587,10 @@ test('should report custom expect steps', async ({ runInlineTest }) => { category: 'hook', title: 'After Hooks', }, + { + category: 'hook', + title: 'Worker Cleanup', + }, { error: expect.any(Object) } @@ -658,6 +672,7 @@ test('should mark step as failed when soft expect fails', async ({ runInlineTest location: { file: 'a.test.ts', line: expect.any(Number), column: expect.any(Number) } }, { title: 'After Hooks', category: 'hook' }, + { title: 'Worker Cleanup', category: 'hook' }, { error: expect.any(Object) } ]); }); @@ -972,6 +987,12 @@ test('should not mark page.close as failed when page.click fails', async ({ runI }, ], }, + ], + }, + { + category: 'hook', + title: 'Worker Cleanup', + steps: [ { category: 'fixture', title: 'fixture: browser', @@ -1168,6 +1189,10 @@ test('should show final toPass error', async ({ runInlineTest }) => { title: 'After Hooks', category: 'hook', }, + { + title: 'Worker Cleanup', + category: 'hook', + }, { error: { message: expect.stringContaining('Error: expect(received).toBe(expected)'), @@ -1255,6 +1280,10 @@ test('should propagate nested soft errors', async ({ runInlineTest }) => { category: 'hook', title: 'After Hooks', }, + { + category: 'hook', + title: 'Worker Cleanup', + }, { error: { message: expect.stringContaining('Error: expect(received).toBe(expected)'), @@ -1348,6 +1377,10 @@ test('should not propagate nested hard errors', async ({ runInlineTest }) => { category: 'hook', title: 'After Hooks', }, + { + category: 'hook', + title: 'Worker Cleanup', + }, { error: { message: expect.stringContaining('Error: expect(received).toBe(expected)'), @@ -1404,6 +1437,10 @@ test('should step w/o box', async ({ runInlineTest }) => { category: 'hook', title: 'After Hooks', }, + { + category: 'hook', + title: 'Worker Cleanup', + }, { error: { message: expect.stringContaining('Error: expect(received).toBe(expected)'), @@ -1453,6 +1490,10 @@ test('should step w/ box', async ({ runInlineTest }) => { category: 'hook', title: 'After Hooks', }, + { + category: 'hook', + title: 'Worker Cleanup', + }, { error: { message: expect.stringContaining('expect(received).toBe(expected)'), @@ -1502,6 +1543,10 @@ test('should soft step w/ box', async ({ runInlineTest }) => { category: 'hook', title: 'After Hooks', }, + { + category: 'hook', + title: 'Worker Cleanup', + }, { error: { message: expect.stringContaining('Error: expect(received).toBe(expected)'), diff --git a/tests/playwright-test/timeout.spec.ts b/tests/playwright-test/timeout.spec.ts index bed9429ad3..0ffa2164ce 100644 --- a/tests/playwright-test/timeout.spec.ts +++ b/tests/playwright-test/timeout.spec.ts @@ -479,3 +479,38 @@ test('beforeEach timeout should prevent others from running', async ({ runInline expect(result.failed).toBe(1); expect(result.outputLines).toEqual(['beforeEach1', 'afterEach']); }); + +test('should report up to 3 timeout errors', async ({ runInlineTest }) => { + const result = await runInlineTest({ + 'a.spec.ts': ` + import { test as base } from '@playwright/test'; + + const test = base.extend<{}, { autoWorker: void }>({ + autoWorker: [ + async ({}, use) => { + await use(); + await new Promise(() => {}); + }, + { scope: 'worker', auto: true }, + ], + }) + + test('test1', async () => { + await new Promise(() => {}); + }); + + test.afterEach(async () => { + await new Promise(() => {}); + }); + + test.afterAll(async () => { + await new Promise(() => {}); + }); + ` + }, { timeout: 1000 }); + expect(result.exitCode).toBe(1); + expect(result.failed).toBe(1); + expect(result.output).toContain('Test timeout of 1000ms exceeded.'); + expect(result.output).toContain('Test timeout of 1000ms exceeded while running "afterEach" hook.'); + expect(result.output).toContain('Worker teardown timeout of 1000ms exceeded while tearing down "autoWorker".'); +}); diff --git a/tests/playwright-test/ui-mode-trace.spec.ts b/tests/playwright-test/ui-mode-trace.spec.ts index 215afe1d2b..194e89afba 100644 --- a/tests/playwright-test/ui-mode-trace.spec.ts +++ b/tests/playwright-test/ui-mode-trace.spec.ts @@ -96,6 +96,7 @@ test('should merge screenshot assertions', async ({ runUITest }, testInfo) => { /expect.toHaveScreenshot[\d.]+m?s/, /attach "trace-test-1-actual.png/, /After Hooks[\d.]+m?s/, + /Worker Cleanup[\d.]+m?s/, ]); });