diff --git a/packages/playwright/src/common/fixtures.ts b/packages/playwright/src/common/fixtures.ts index 6b50947ab5..3bcacc3f75 100644 --- a/packages/playwright/src/common/fixtures.ts +++ b/packages/playwright/src/common/fixtures.ts @@ -40,7 +40,7 @@ export type FixtureRegistration = { // Custom title to be used instead of the name, internal-only. customTitle?: string; // Fixture with a separate timeout does not count towards the test time. - timeout?: number; + timeout?: number | 'trace'; // Names of the dependencies, comes from the declaration "({ foo, bar }) => {...}" deps: string[]; // Unique id, to differentiate between fixtures with the same name. @@ -103,7 +103,7 @@ export class FixturePool { for (const entry of Object.entries(fixtures)) { const name = entry[0]; let value = entry[1]; - let options: { auto: FixtureAuto, scope: FixtureScope, option: boolean, timeout: number | undefined, customTitle?: string, box?: boolean } | undefined; + let options: { auto: FixtureAuto, scope: FixtureScope, option: boolean, timeout: number | 'trace' | undefined, customTitle?: string, box?: boolean } | undefined; if (isFixtureTuple(value)) { options = { auto: value[1].auto ?? false, diff --git a/packages/playwright/src/index.ts b/packages/playwright/src/index.ts index 9a159c984a..53477a00ea 100644 --- a/packages/playwright/src/index.ts +++ b/packages/playwright/src/index.ts @@ -297,7 +297,7 @@ const playwrightFixtures: Fixtures = ({ clientInstrumentation.removeListener(csiListener); await artifactsRecorder.didFinishTest(); - }, { auto: 'all-hooks-included', title: 'trace recording', box: true } as any], + }, { auto: 'all-hooks-included', title: 'trace recording', box: true, timeout: 'trace' } as any], _contextFactory: [async ({ browser, video, _reuseContext, _combinedContextOptions /** mitigate dep-via-auto lack of traceability */ }, use, testInfo) => { const testInfoImpl = testInfo as TestInfoImpl; diff --git a/packages/playwright/src/worker/fixtureRunner.ts b/packages/playwright/src/worker/fixtureRunner.ts index 0d94f40631..f0b50b2784 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, type RunnableDescription } from './timeoutManager'; +import { type TimeSlot, 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'; @@ -49,10 +49,8 @@ class Fixture { title, phase: 'setup', location, - slot: this.registration.timeout === undefined ? undefined : { - timeout: this.registration.timeout, - elapsed: 0, - } + slot: this.registration.timeout === 'trace' ? this.runner.traceSlot : + (this.registration.timeout === undefined ? undefined : { timeout: this.registration.timeout, elapsed: 0 }), }; this._teardownDescription = { ...this._setupDescription, phase: 'teardown' }; } @@ -125,38 +123,41 @@ class Fixture { } async teardown(testInfo: TestInfoImpl, runnable: RunnableDescription) { - await testInfo._runAsStage({ - title: `fixture: ${this.registration.name}`, - runnable: { ...runnable, fixture: this._teardownDescription }, - stepInfo: this._stepInfo, - }, async () => { - await this._teardownInternal(); - }); + try { + const fixtureRunnable = { ...runnable, fixture: this._teardownDescription }; + // 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.name}`, + runnable: fixtureRunnable, + stepInfo: this._stepInfo, + }, async () => { + await this._teardownInternal(); + }); + } + } finally { + // To preserve fixtures integrity, forcefully cleanup fixtures + // that cannnot teardown due to a timeout or an error. + for (const dep of this._deps) + dep._usages.delete(this); + this.runner.instanceForId.delete(this.registration.id); + } } private async _teardownInternal() { if (typeof this.registration.fn !== 'function') return; - try { - if (this._usages.size !== 0) { - // TODO: replace with assert. - console.error('Internal error: fixture integrity at', this._teardownDescription.title); // eslint-disable-line no-console - this._usages.clear(); - } - if (this._useFuncFinished) { - this._useFuncFinished.resolve(); - this._useFuncFinished = undefined; - await this._selfTeardownComplete; - } - } finally { - this._cleanupInstance(); + if (this._usages.size !== 0) { + // TODO: replace with assert. + console.error('Internal error: fixture integrity at', this._teardownDescription.title); // eslint-disable-line no-console + this._usages.clear(); + } + if (this._useFuncFinished) { + this._useFuncFinished.resolve(); + this._useFuncFinished = undefined; + await this._selfTeardownComplete; } - } - - _cleanupInstance() { - for (const dep of this._deps) - dep._usages.delete(this); - this.runner.instanceForId.delete(this.registration.id); } _collectFixturesInTeardownOrder(scope: FixtureScope, collector: Set) { @@ -172,6 +173,7 @@ export class FixtureRunner { private testScopeClean = true; pool: FixturePool | undefined; instanceForId = new Map(); + traceSlot?: TimeSlot; setPool(pool: FixturePool) { if (!this.testScopeClean) @@ -203,27 +205,18 @@ export class FixtureRunner { const collector = new Set(); for (const fixture of fixtures) fixture._collectFixturesInTeardownOrder(scope, collector); - try { - let firstError: Error | undefined; - for (const fixture of collector) { - try { - await fixture.teardown(testInfo, runnable); - } catch (error) { - if (error instanceof TimeoutManagerError) - throw error; - firstError = firstError ?? error; - } + let firstError: Error | undefined; + for (const fixture of collector) { + try { + await fixture.teardown(testInfo, runnable); + } catch (error) { + firstError = firstError ?? error; } - if (firstError) - throw firstError; - } finally { - // To preserve fixtures integrity, forcefully cleanup fixtures that did not teardown - // due to a timeout in one of them. - for (const fixture of collector) - fixture._cleanupInstance(); - if (scope === 'test') - this.testScopeClean = true; } + if (scope === 'test') + this.testScopeClean = true; + if (firstError) + throw firstError; } async resolveParametersForFunction(fn: Function, testInfo: TestInfoImpl, autoFixtures: 'worker' | 'test' | 'all-hooks-only', runnable: RunnableDescription): Promise { diff --git a/packages/playwright/src/worker/timeoutManager.ts b/packages/playwright/src/worker/timeoutManager.ts index 441a87eca0..4a42146aa9 100644 --- a/packages/playwright/src/worker/timeoutManager.ts +++ b/packages/playwright/src/worker/timeoutManager.ts @@ -62,6 +62,12 @@ export class TimeoutManager { this._running.timeoutPromise.reject(this._createTimeoutError(this._running)); } + isTimeExhaustedFor(runnable: RunnableDescription) { + const slot = runnable.fixture?.slot || runnable.slot || this._defaultSlot; + // Note: the "-1" here matches the +1 in _updateTimeout. + return slot.timeout > 0 && (slot.elapsed >= slot.timeout - 1); + } + async withRunnable(runnable: RunnableDescription | undefined, cb: () => Promise): Promise { if (!runnable) return await cb(); @@ -99,7 +105,10 @@ export class TimeoutManager { return; } running.deadline = running.start + (running.slot.timeout - running.slot.elapsed); - const timeout = running.deadline - monotonicTime(); + // Compensate for Node.js troubles with timeouts that can fire too early. + // We add an extra millisecond which seems to be enough. + // See https://github.com/nodejs/node/issues/26578. + const timeout = running.deadline - monotonicTime() + 1; if (timeout <= 0) running.timeoutPromise.reject(this._createTimeoutError(running)); else diff --git a/packages/playwright/src/worker/workerMain.ts b/packages/playwright/src/worker/workerMain.ts index 26048e6542..6a86aeb55e 100644 --- a/packages/playwright/src/worker/workerMain.ts +++ b/packages/playwright/src/worker/workerMain.ts @@ -266,8 +266,11 @@ export class WorkerMain extends ProcessRunner { } }; - if (!this._isStopped) + const traceSlot = { timeout: this._project.project.timeout, elapsed: 0 }; + if (!this._isStopped) { this._fixtureRunner.setPool(test._pool!); + this._fixtureRunner.traceSlot = traceSlot; + } const suites = getSuites(test); const reversedSuites = suites.slice().reverse(); @@ -307,7 +310,7 @@ export class WorkerMain extends ProcessRunner { testInfo._allowSkips = true; await testInfo._runAsStage({ title: 'setup and test' }, async () => { - await testInfo._runAsStage({ title: 'start tracing', runnable: { type: 'test' } }, async () => { + await testInfo._runAsStage({ title: 'start tracing', runnable: { type: 'test', slot: traceSlot } }, 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. @@ -458,8 +461,7 @@ export class WorkerMain extends ProcessRunner { }).catch(() => {}); // Ignore the top-level error, it is already inside TestInfo.errors. } - const tracingSlot = { timeout: this._project.project.timeout, elapsed: 0 }; - await testInfo._runAsStage({ title: 'stop tracing', runnable: { type: 'test', slot: tracingSlot } }, async () => { + await testInfo._runAsStage({ title: 'stop tracing', runnable: { type: 'test', slot: traceSlot } }, async () => { await testInfo._tracing.stopIfNeeded(); }).catch(() => {}); // Ignore the top-level error, it is already inside TestInfo.errors. diff --git a/tests/playwright-test/hooks.spec.ts b/tests/playwright-test/hooks.spec.ts index d72cd7abb1..60a8700b82 100644 --- a/tests/playwright-test/hooks.spec.ts +++ b/tests/playwright-test/hooks.spec.ts @@ -625,7 +625,31 @@ test('uncaught error in beforeEach should not be masked by another error', async expect(result.output).toContain('Received: 1'); }); -test('should report error from fixture teardown when beforeAll times out', async ({ runInlineTest }) => { +test('should report error from worker fixture teardown when beforeAll times out', async ({ runInlineTest }) => { + const result = await runInlineTest({ + 'a.test.js': ` + import { test as base, expect } from '@playwright/test'; + const test = base.extend({ + foo: [async ({}, use) => { + let cb; + await use(new Promise((f, r) => cb = r)); + cb(new Error('Oh my!')); + }, { scope: 'worker' }], + }); + test.beforeAll(async ({ foo }, testInfo) => { + await foo; + }); + test('passing', () => { + }); + `, + }, { timeout: 1000 }); + expect(result.exitCode).toBe(1); + expect(result.failed).toBe(1); + expect(result.output).toContain('"beforeAll" hook timeout of 1000ms exceeded.'); + expect(result.output).toContain('Error: Oh my!'); +}); + +test('should not report error from test fixture teardown when beforeAll times out', async ({ runInlineTest }) => { const result = await runInlineTest({ 'a.test.js': ` import { test as base, expect } from '@playwright/test'; @@ -646,7 +670,7 @@ test('should report error from fixture teardown when beforeAll times out', async expect(result.exitCode).toBe(1); expect(result.failed).toBe(1); expect(result.output).toContain('"beforeAll" hook timeout of 1000ms exceeded.'); - expect(result.output).toContain('Error: Oh my!'); + expect(result.output).not.toContain('Error: Oh my!'); }); test('should not hang and report results when worker process suddenly exits during afterAll', async ({ runInlineTest }) => { diff --git a/tests/playwright-test/playwright.trace.spec.ts b/tests/playwright-test/playwright.trace.spec.ts index e4a1efe4d7..5ca08925b4 100644 --- a/tests/playwright-test/playwright.trace.spec.ts +++ b/tests/playwright-test/playwright.trace.spec.ts @@ -1225,4 +1225,44 @@ test('should not nest top level expect into unfinished api calls ', { ]); }); +test('should record trace after fixture teardown timeout', { + annotation: { type: 'issue', description: 'https://github.com/microsoft/playwright/issues/30718' }, +}, async ({ runInlineTest }) => { + const result = await runInlineTest({ + 'a.spec.ts': ` + import { test as base, expect } from '@playwright/test'; + const test = base.extend({ + fixture: async ({}, use) => { + await use('foo'); + await new Promise(() => {}); + }, + }); + // Note: it is important that "fixture" is last, so that it runs the teardown first. + test('fails', async ({ page, fixture }) => { + await page.evaluate(() => console.log('from the page')); + }); + `, + }, { trace: 'on', timeout: '3000' }, { DEBUG: 'pw:test' }); + expect(result.exitCode).toBe(1); + expect(result.failed).toBe(1); + const tracePath = test.info().outputPath('test-results', 'a-fails', 'trace.zip'); + const trace = await parseTrace(tracePath); + expect(trace.actionTree).toEqual([ + 'Before Hooks', + ' fixture: browser', + ' browserType.launch', + ' fixture: context', + ' browser.newContext', + ' fixture: page', + ' browserContext.newPage', + ' fixture: fixture', + 'page.evaluate', + 'After Hooks', + ' fixture: fixture', + 'Worker Cleanup', + ' fixture: browser', + ]); + // Check console events to make sure that library trace is recorded. + expect(trace.events).toContainEqual(expect.objectContaining({ type: 'console', text: 'from the page' })); +}); diff --git a/tests/playwright-test/timeout.spec.ts b/tests/playwright-test/timeout.spec.ts index a079c3f70b..7d30e3002f 100644 --- a/tests/playwright-test/timeout.spec.ts +++ b/tests/playwright-test/timeout.spec.ts @@ -558,3 +558,34 @@ test('should allow custom worker fixture timeout longer than force exit cap', as expect(result.output).toContain(`Error: Oh my!`); expect(result.output).toContain(`1 error was not a part of any test, see above for details`); }); + +test('should run fixture teardown with custom timeout after test timeout', { + annotation: { type: 'issue', description: 'https://github.com/microsoft/playwright/issues/31537' }, +}, async ({ runInlineTest }) => { + const result = await runInlineTest({ + 'a.spec.ts': ` + import { test as base, expect } from '@playwright/test'; + + const test = base.extend({ + foo: [async ({}, use) => { + console.log('\\n%%foo setup'); + await use('foo'); + console.log('\\n%%foo teardown'); + }, { timeout: 2000 }], + }); + + test('times out', async ({ foo }) => { + console.log('\\n%%test start'); + await new Promise(() => {}); + console.log('\\n%%test end'); + }); + ` + }, { timeout: 2000 }); + expect(result.exitCode).toBe(1); + expect(result.failed).toBe(1); + expect(result.outputLines).toEqual([ + 'foo setup', + 'test start', + 'foo teardown', + ]); +});