feat(test runner): record trace after a test-scoped fixture teardown times out

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,

packages/playwright/src/index.ts

@@ -297,7 +297,7 @@ const playwrightFixtures: Fixtures<TestFixtures, WorkerFixtures> = ({
     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;

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,19 +123,31 @@ class Fixture {
   }
 
   async teardown(testInfo: TestInfoImpl, runnable: RunnableDescription) {
+    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: { ...runnable, fixture: this._teardownDescription },
+          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
@@ -148,15 +158,6 @@ class Fixture {
       this._useFuncFinished = undefined;
       await this._selfTeardownComplete;
     }
-    } finally {
-      this._cleanupInstance();
-    }
-  }
-
-  _cleanupInstance() {
-    for (const dep of this._deps)
-      dep._usages.delete(this);
-    this.runner.instanceForId.delete(this.registration.id);
   }
 
   _collectFixturesInTeardownOrder(scope: FixtureScope, collector: Set<Fixture>) {
@@ -172,6 +173,7 @@ export class FixtureRunner {
   private testScopeClean = true;
   pool: FixturePool | undefined;
   instanceForId = new Map<string, Fixture>();
+  traceSlot?: TimeSlot;
 
   setPool(pool: FixturePool) {
     if (!this.testScopeClean)
@@ -203,27 +205,18 @@ export class FixtureRunner {
     const collector = new Set<Fixture>();
     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;
       }
     }
-      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 (firstError)
+      throw firstError;
   }
 
   async resolveParametersForFunction(fn: Function, testInfo: TestInfoImpl, autoFixtures: 'worker' | 'test' | 'all-hooks-only', runnable: RunnableDescription): Promise<object | null> {

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<T>(runnable: RunnableDescription | undefined, cb: () => Promise<T>): Promise<T> {
     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

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.
 

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 }) => {

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' }));
+});

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',
+  ]);
+});