fix(test runner): make sure soft expect error does not mask a timeout flag (#18321)

We have to reliably know whether test timed out or not, and soft expect
error could have marked it with `status=failed` but it would still time
out. Now we have a separate `_didTimeout` flag for this.

Fixes #18023.

packages/playwright-test/src/index.ts

@@ -487,7 +487,7 @@ export const test = _baseTest.extend<TestFixtures, WorkerFixtures>({
       return context;
     });
 
-    const prependToError = testInfo.status === 'timedOut' ?
+    const prependToError = (testInfo as any)._didTimeout ?
       formatPendingCalls((browser as any)._connection.pendingProtocolCalls()) : '';
 
     let counter = 0;

packages/playwright-test/src/testInfo.ts

@@ -35,6 +35,7 @@ export class TestInfoImpl implements TestInfo {
   private _hasHardError: boolean = false;
   readonly _screenshotsDir: string;
   readonly _onTestFailureImmediateCallbacks = new Map<() => Promise<void>, string>(); // fn -> title
+  _didTimeout = false;
 
   // ------------ TestInfo fields ------------
   readonly repeatEachIndex: number;
@@ -164,9 +165,11 @@ export class TestInfoImpl implements TestInfo {
   async _runWithTimeout(cb: () => Promise<any>): Promise<void> {
     const timeoutError = await this._timeoutManager.runWithTimeout(cb);
     // Do not overwrite existing failure upon hook/teardown timeout.
-    if (timeoutError && (this.status === 'passed' || this.status === 'skipped')) {
-      this.status = 'timedOut';
+    if (timeoutError && !this._didTimeout) {
+      this._didTimeout = true;
       this.errors.push(timeoutError);
+      if (this.status === 'passed' || this.status === 'skipped')
+        this.status = 'timedOut';
     }
     this.duration = this._timeoutManager.defaultSlotTimings().elapsed | 0;
   }

packages/playwright-test/src/workerRunner.ts

@@ -411,7 +411,7 @@ export class WorkerRunner extends EventEmitter {
     let firstAfterHooksError: TestError | undefined;
 
     let afterHooksSlot: TimeSlot | undefined;
-    if (testInfo.status === 'timedOut') {
+    if (testInfo._didTimeout) {
       // A timed-out test gets a full additional timeout to run after hooks.
       afterHooksSlot = { timeout: this._project.timeout, elapsed: 0 };
       testInfo._timeoutManager.setCurrentRunnable({ type: 'afterEach', slot: afterHooksSlot });
@@ -425,12 +425,14 @@ export class WorkerRunner extends EventEmitter {
         const onFailureError = await testInfo._runFn(async () => {
           testInfo._timeoutManager.setCurrentRunnable({ type: 'test', slot: afterHooksSlot });
           for (const [fn, title] of testInfo._onTestFailureImmediateCallbacks) {
+            debugTest(`on-failure callback started`);
             await testInfo._runAsStep(fn, {
               category: 'hook',
               title,
               canHaveChildren: true,
               forceNoParent: false,
             });
+            debugTest(`on-failure callback finished`);
           }
         });
         firstAfterHooksError = firstAfterHooksError || onFailureError;
@@ -456,7 +458,9 @@ export class WorkerRunner extends EventEmitter {
       // Teardown test-scoped fixtures. Attribute to 'test' so that users understand
       // they should probably increate the test timeout to fix this issue.
       testInfo._timeoutManager.setCurrentRunnable({ type: 'test', slot: afterHooksSlot });
+      debugTest(`tearing down test scope started`);
       const testScopeError = await testInfo._runFn(() => this._fixtureRunner.teardownScope('test', testInfo._timeoutManager));
+      debugTest(`tearing down test scope finished`);
       firstAfterHooksError = firstAfterHooksError || testScopeError;
     });
 
@@ -470,6 +474,7 @@ export class WorkerRunner extends EventEmitter {
 
       // Give it more time for the full cleanup.
       await testInfo._runWithTimeout(async () => {
+        debugTest(`running full cleanup after the failure`);
         for (const suite of reversedSuites) {
           const afterAllError = await this._runAfterAllHooksForSuite(suite, testInfo);
           firstAfterHooksError = firstAfterHooksError || afterAllError;
@@ -477,11 +482,15 @@ export class WorkerRunner extends EventEmitter {
         const teardownSlot = { timeout: this._project.timeout, elapsed: 0 };
         // Attribute to 'test' so that users understand they should probably increate the test timeout to fix this issue.
         testInfo._timeoutManager.setCurrentRunnable({ type: 'test', slot: teardownSlot });
+        debugTest(`tearing down test scope started`);
         const testScopeError = await testInfo._runFn(() => this._fixtureRunner.teardownScope('test', testInfo._timeoutManager));
+        debugTest(`tearing down test scope finished`);
         firstAfterHooksError = firstAfterHooksError || testScopeError;
         // Attribute to 'teardown' because worker fixtures are not perceived as a part of a test.
         testInfo._timeoutManager.setCurrentRunnable({ type: 'teardown', slot: teardownSlot });
+        debugTest(`tearing down worker scope started`);
         const workerScopeError = await testInfo._runFn(() => this._fixtureRunner.teardownScope('worker', testInfo._timeoutManager));
+        debugTest(`tearing down worker scope finished`);
         firstAfterHooksError = firstAfterHooksError || workerScopeError;
       });
     }

tests/playwright-test/timeout.spec.ts

@@ -378,3 +378,42 @@ test('should not include fixtures with own timeout and beforeAll in test duratio
   expect(duration).toBeGreaterThanOrEqual(300 * 4);  // Includes test, beforeEach, afterEach and bar.
   expect(duration).toBeLessThan(300 * 4 + 1000);  // Does not include beforeAll and foo.
 });
+
+test('should run fixture teardowns after timeout with soft expect error', async ({ runInlineTest }) => {
+  const result = await runInlineTest({
+    'helper.ts': `
+      export const test = pwt.test.extend({
+        foo: async ({}, run, testInfo) => {
+          await run();
+          await new Promise(f => setTimeout(f, 500));
+          testInfo.attachments.push({ name: 'foo', contentType: 'text/plain', body: Buffer.from('foo') });
+        },
+        bar: async ({ foo }, run, testInfo) => {
+          await run(foo);
+          await new Promise(f => setTimeout(f, 500));
+          testInfo.attachments.push({ name: 'bar', contentType: 'text/plain', body: Buffer.from('bar') });
+        },
+      });
+    `,
+    'c.spec.ts': `
+      import { test } from './helper';
+      test('works', async ({ bar }) => {
+        expect.soft(1).toBe(2);
+        await new Promise(f => setTimeout(f, 5000));
+      });
+    `
+  }, { timeout: 2000 });
+  expect(result.exitCode).toBe(1);
+  expect(result.failed).toBe(1);
+  const test = result.report.suites[0].specs[0].tests[0];
+  expect(test.results[0].attachments[0]).toEqual({
+    name: 'bar',
+    body: 'YmFy',
+    contentType: 'text/plain',
+  });
+  expect(test.results[0].attachments[1]).toEqual({
+    name: 'foo',
+    body: 'Zm9v',
+    contentType: 'text/plain',
+  });
+});