diff --git a/packages/playwright/src/worker/fixtureRunner.ts b/packages/playwright/src/worker/fixtureRunner.ts index 555f86ab57..51bd517dde 100644 --- a/packages/playwright/src/worker/fixtureRunner.ts +++ b/packages/playwright/src/worker/fixtureRunner.ts @@ -35,7 +35,7 @@ class Fixture { private _selfTeardownComplete: Promise | undefined; private _setupDescription: FixtureDescription; private _teardownDescription: FixtureDescription; - private _stepInfo: { category: 'fixture', location?: Location } | undefined; + private _stepInfo: { title: string, category: 'fixture', location?: Location } | undefined; _deps = new Set(); _usages = new Set(); @@ -47,7 +47,7 @@ class Fixture { const isUserFixture = this.registration.location && filterStackFile(this.registration.location.file); const title = this.registration.customTitle || this.registration.name; const location = isUserFixture ? this.registration.location : undefined; - this._stepInfo = shouldGenerateStep ? { category: 'fixture', location } : undefined; + this._stepInfo = shouldGenerateStep ? { title: `fixture: ${title}`, category: 'fixture', location } : undefined; this._setupDescription = { title, phase: 'setup', @@ -68,13 +68,11 @@ class Fixture { return; } - await testInfo._runAsStage({ - title: `fixture: ${this.registration.customTitle ?? this.registration.name}`, - runnable: { ...runnable, fixture: this._setupDescription }, - stepInfo: this._stepInfo, - }, async () => { - await this._setupInternal(testInfo); - }); + const run = () => testInfo._runWithTimeout({ ...runnable, fixture: this._setupDescription }, () => this._setupInternal(testInfo)); + if (this._stepInfo) + await testInfo._runAsStep(this._stepInfo, run); + else + await run(); } private async _setupInternal(testInfo: TestInfoImpl) { @@ -133,13 +131,11 @@ class Fixture { // Do not even start the teardown for a fixture that does not have any // time remaining in the time slot. This avoids cascading timeouts. if (!testInfo._timeoutManager.isTimeExhaustedFor(fixtureRunnable)) { - await testInfo._runAsStage({ - title: `fixture: ${this.registration.customTitle ?? this.registration.name}`, - runnable: fixtureRunnable, - stepInfo: this._stepInfo, - }, async () => { - await this._teardownInternal(); - }); + const run = () => testInfo._runWithTimeout(fixtureRunnable, () => this._teardownInternal()); + if (this._stepInfo) + await testInfo._runAsStep(this._stepInfo, run); + else + await run(); } } finally { // To preserve fixtures integrity, forcefully cleanup fixtures @@ -268,9 +264,7 @@ export class FixtureRunner { // Do not run the function when fixture setup has already failed. return null; } - await testInfo._runAsStage({ title: 'run function', runnable }, async () => { - await fn(params, testInfo); - }); + await testInfo._runWithTimeout(runnable, () => fn(params, testInfo)); } private async _setupFixtureForRegistration(registration: FixtureRegistration, testInfo: TestInfoImpl, runnable: RunnableDescription): Promise { diff --git a/packages/playwright/src/worker/testInfo.ts b/packages/playwright/src/worker/testInfo.ts index 5bac56776d..2a0557d0b8 100644 --- a/packages/playwright/src/worker/testInfo.ts +++ b/packages/playwright/src/worker/testInfo.ts @@ -20,7 +20,7 @@ import path from 'path'; import { captureRawStack, monotonicTime, sanitizeForFilePath, stringifyStackFrames, currentZone } from 'playwright-core/lib/utils'; import { TimeoutManager, TimeoutManagerError, kMaxDeadline } from './timeoutManager'; -import { debugTest, filteredStackTrace, formatLocation, getContainedPath, normalizeAndSaveAttachment, trimLongString, windowsFilesystemFriendlyLength } from '../util'; +import { filteredStackTrace, getContainedPath, normalizeAndSaveAttachment, trimLongString, windowsFilesystemFriendlyLength } from '../util'; import { TestTracing } from './testTracing'; import { testInfoError } from './util'; import { FloatingPromiseScope } from './floatingPromiseScope'; @@ -50,16 +50,8 @@ export interface TestStepInternal { error?: TestInfoErrorImpl; infectParentStepsWithError?: boolean; box?: boolean; - isStage?: boolean; } -export type TestStage = { - title: string; - stepInfo?: { category: 'hook' | 'fixture', location?: Location }; - runnable?: RunnableDescription; - step?: TestStepInternal; -}; - export class TestInfoImpl implements TestInfo { private _onStepBegin: (payload: StepBeginPayload) => void; private _onStepEnd: (payload: StepEndPayload) => void; @@ -235,28 +227,27 @@ export class TestInfoImpl implements TestInfo { } } - private _findLastStageStep(steps: TestStepInternal[]): TestStepInternal | undefined { - // Find the deepest step that is marked as isStage and has not finished yet. + private _findLastPredefinedStep(steps: TestStepInternal[]): TestStepInternal | undefined { + // Find the deepest predefined step that has not finished yet. for (let i = steps.length - 1; i >= 0; i--) { - const child = this._findLastStageStep(steps[i].steps); + const child = this._findLastPredefinedStep(steps[i].steps); if (child) return child; - if (steps[i].isStage && !steps[i].endWallTime) + if ((steps[i].category === 'hook' || steps[i].category === 'fixture') && !steps[i].endWallTime) return steps[i]; } } private _parentStep() { - return currentZone().data('stepZone') - ?? this._findLastStageStep(this._steps); // If no parent step on stack, assume the current stage as parent. + return currentZone().data('stepZone') ?? this._findLastPredefinedStep(this._steps); } _addStep(data: Omit, parentStep?: TestStepInternal): TestStepInternal { const stepId = `${data.category}@${++this._lastStepId}`; - if (data.isStage) { - // Predefined stages form a fixed hierarchy - use the current one as parent. - parentStep = this._findLastStageStep(this._steps); + if (data.category === 'hook' || data.category === 'fixture') { + // Predefined steps form a fixed hierarchy - use the current one as parent. + parentStep = this._findLastPredefinedStep(this._steps); } else { if (!parentStep) parentStep = this._parentStep(); @@ -355,21 +346,23 @@ export class TestInfoImpl implements TestInfo { this._tracing.appendForError(serialized); } - async _runAsStage(stage: TestStage, cb: () => Promise) { - if (debugTest.enabled) { - const location = stage.runnable?.location ? ` at "${formatLocation(stage.runnable.location)}"` : ``; - debugTest(`started stage "${stage.title}"${location}`); - } - stage.step = stage.stepInfo ? this._addStep({ ...stage.stepInfo, title: stage.title, isStage: true }) : undefined; - + async _runAsStep(stepInfo: { title: string, category: 'hook' | 'fixture', location?: Location }, cb: () => Promise) { + const step = this._addStep(stepInfo); try { - await this._timeoutManager.withRunnable(stage.runnable, async () => { + await cb(); + step.complete({}); + } catch (error) { + step.complete({ error }); + throw error; + } + } + + async _runWithTimeout(runnable: RunnableDescription, cb: () => Promise) { + try { + await this._timeoutManager.withRunnable(runnable, async () => { try { await cb(); } catch (e) { - // Only handle errors directly thrown by the user code. - if (!stage.runnable) - throw e; if (this._allowSkips && (e instanceof SkipError)) { if (this.status === 'passed') this.status = 'skipped'; @@ -377,7 +370,7 @@ export class TestInfoImpl implements TestInfo { // Unfortunately, we have to handle user errors and timeout errors differently. // Consider the following scenario: // - locator.click times out - // - all stages containing the test function finish with TimeoutManagerError + // - all steps 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 @@ -386,16 +379,12 @@ export class TestInfoImpl implements TestInfo { throw e; } }); - stage.step?.complete({}); } catch (error) { // When interrupting, we arrive here with a TimeoutManagerError, but we should not // consider it a timeout. - if (!this._wasInterrupted && (error instanceof TimeoutManagerError) && stage.runnable) + if (!this._wasInterrupted && (error instanceof TimeoutManagerError)) this._failWithError(error); - stage.step?.complete({ error }); throw error; - } finally { - debugTest(`finished stage "${stage.title}"`); } } @@ -430,7 +419,7 @@ export class TestInfoImpl implements TestInfo { } else { // trace viewer has no means of representing attachments outside of a step, so we create an artificial action const callId = `attach@${++this._lastStepId}`; - this._tracing.appendBeforeActionForStep(callId, this._findLastStageStep(this._steps)?.stepId, 'attach', `attach "${attachment.name}"`, undefined, []); + this._tracing.appendBeforeActionForStep(callId, this._findLastPredefinedStep(this._steps)?.stepId, 'attach', `attach "${attachment.name}"`, undefined, []); this._tracing.appendAfterActionForStep(callId, undefined, [attachment]); } diff --git a/packages/playwright/src/worker/timeoutManager.ts b/packages/playwright/src/worker/timeoutManager.ts index 65e97c9f36..c003342d15 100644 --- a/packages/playwright/src/worker/timeoutManager.ts +++ b/packages/playwright/src/worker/timeoutManager.ts @@ -17,6 +17,8 @@ import { ManualPromise, monotonicTime } from 'playwright-core/lib/utils'; import { colors } from 'playwright-core/lib/utils'; +import { debugTest, formatLocation } from '../util'; + import type { Location } from '../../types/testReporter'; export type TimeSlot = { @@ -76,9 +78,7 @@ export class TimeoutManager { return slot.timeout > 0 && (slot.elapsed >= slot.timeout - 1); } - async withRunnable(runnable: RunnableDescription | undefined, cb: () => Promise): Promise { - if (!runnable) - return await cb(); + async withRunnable(runnable: RunnableDescription, cb: () => Promise): Promise { if (this._running) throw new Error(`Internal error: duplicate runnable`); const running = this._running = { @@ -89,7 +89,13 @@ export class TimeoutManager { timer: undefined, timeoutPromise: new ManualPromise(), }; + let debugTitle = ''; try { + if (debugTest.enabled) { + debugTitle = runnable.fixture ? `${runnable.fixture.phase} "${runnable.fixture.title}"` : runnable.type; + const location = runnable.location ? ` at "${formatLocation(runnable.location)}"` : ``; + debugTest(`started ${debugTitle}${location}`); + } this._updateTimeout(running); return await Promise.race([ cb(), @@ -101,6 +107,8 @@ export class TimeoutManager { running.timer = undefined; running.slot.elapsed += monotonicTime() - running.start; this._running = undefined; + if (debugTest.enabled) + debugTest(`finished ${debugTitle}`); } } diff --git a/packages/playwright/src/worker/workerMain.ts b/packages/playwright/src/worker/workerMain.ts index 8ff6d31fd0..91abde8a2e 100644 --- a/packages/playwright/src/worker/workerMain.ts +++ b/packages/playwright/src/worker/workerMain.ts @@ -115,12 +115,12 @@ export class WorkerMain extends ProcessRunner { const fakeTestInfo = new TestInfoImpl(this._config, this._project, this._params, undefined, 0, () => {}, () => {}, () => {}); const runnable = { type: 'teardown' } as const; // We have to load the project to get the right deadline below. - await fakeTestInfo._runAsStage({ title: 'worker cleanup', runnable }, () => this._loadIfNeeded()).catch(() => {}); + await fakeTestInfo._runWithTimeout(runnable, () => this._loadIfNeeded()).catch(() => {}); await this._fixtureRunner.teardownScope('test', fakeTestInfo, runnable).catch(() => {}); await this._fixtureRunner.teardownScope('worker', fakeTestInfo, runnable).catch(() => {}); // Close any other browsers launched in this process. This includes anything launched // manually in the test/hooks and internal browsers like Playwright Inspector. - await fakeTestInfo._runAsStage({ title: 'worker cleanup', runnable }, () => gracefullyCloseAll()).catch(() => {}); + await fakeTestInfo._runWithTimeout(runnable, () => gracefullyCloseAll()).catch(() => {}); this._fatalErrors.push(...fakeTestInfo.errors); } catch (e) { this._fatalErrors.push(testInfoError(e)); @@ -330,8 +330,8 @@ export class WorkerMain extends ProcessRunner { testInfo._floatingPromiseScope.clear(); }; - await testInfo._runAsStage({ title: 'setup and test' }, async () => { - await testInfo._runAsStage({ title: 'start tracing', runnable: { type: 'test' } }, async () => { + await (async () => { + await testInfo._runWithTimeout({ 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. @@ -356,7 +356,7 @@ export class WorkerMain extends ProcessRunner { await removeFolders([testInfo.outputDir]); let testFunctionParams: object | null = null; - await testInfo._runAsStage({ title: 'Before Hooks', stepInfo: { category: 'hook' } }, async () => { + await testInfo._runAsStep({ title: 'Before Hooks', category: 'hook' }, async () => { // Run "beforeAll" hooks, unless already run during previous tests. for (const suite of suites) await this._runBeforeAllHooksForSuite(suite, testInfo); @@ -376,13 +376,13 @@ export class WorkerMain extends ProcessRunner { return; } - await testInfo._runAsStage({ title: 'test function', runnable: { type: 'test' } }, async () => { + await testInfo._runWithTimeout({ 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); checkForFloatingPromises('the test'); }); - }).catch(() => {}); // Ignore the top-level error, it is already inside TestInfo.errors. + })().catch(() => {}); // Ignore the top-level error, it is already inside TestInfo.errors. // Update duration, so it is available in fixture teardown and afterEach hooks. testInfo.duration = testInfo._timeoutManager.defaultSlot().elapsed | 0; @@ -393,12 +393,12 @@ export class WorkerMain extends ProcessRunner { // 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', stepInfo: { category: 'hook' } }, async () => { + await testInfo._runAsStep({ title: 'After Hooks', category: 'hook' }, async () => { let firstAfterHooksError: Error | undefined; try { // Run "immediately upon test function finish" callback. - await testInfo._runAsStage({ title: 'on-test-function-finish', runnable: { type: 'test', slot: afterHooksSlot } }, async () => testInfo._onDidFinishTestFunction?.()); + await testInfo._runWithTimeout({ type: 'test', slot: afterHooksSlot }, async () => testInfo._onDidFinishTestFunction?.()); } catch (error) { firstAfterHooksError = firstAfterHooksError ?? error; } @@ -448,7 +448,7 @@ export class WorkerMain extends ProcessRunner { // Mark as "cleaned up" early to avoid running cleanup twice. this._didRunFullCleanup = true; - await testInfo._runAsStage({ title: 'Worker Cleanup', stepInfo: { category: 'hook' } }, async () => { + await testInfo._runAsStep({ title: 'Worker Cleanup', category: 'hook' }, async () => { let firstWorkerCleanupError: Error | undefined; // Give it more time for the full cleanup. @@ -481,7 +481,7 @@ export class WorkerMain extends ProcessRunner { } const tracingSlot = { timeout: this._project.project.timeout, elapsed: 0 }; - await testInfo._runAsStage({ title: 'stop tracing', runnable: { type: 'test', slot: tracingSlot } }, async () => { + await testInfo._runWithTimeout({ type: 'test', slot: tracingSlot }, async () => { await testInfo._tracing.stopIfNeeded(); }).catch(() => {}); // Ignore the top-level error, it is already inside TestInfo.errors. @@ -534,7 +534,7 @@ export class WorkerMain extends ProcessRunner { let firstError: Error | undefined; for (const hook of this._collectHooksAndModifiers(suite, type, testInfo)) { try { - await testInfo._runAsStage({ title: hook.title, stepInfo: { category: 'hook', location: hook.location } }, async () => { + await testInfo._runAsStep({ title: hook.title, 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 }; @@ -587,7 +587,7 @@ export class WorkerMain extends ProcessRunner { continue; } try { - await testInfo._runAsStage({ title: hook.title, stepInfo: { category: 'hook', location: hook.location } }, async () => { + await testInfo._runAsStep({ title: hook.title, category: 'hook', location: hook.location }, async () => { await this._fixtureRunner.resolveParametersAndRunFunction(hook.fn, testInfo, 'test', runnable); }); } catch (error) {