feat(test runner): expect(locator) matchers to show a nice error on timeout (#7935)

src/test/globals.ts

@@ -14,14 +14,14 @@
  * limitations under the License.
  */
 
-import type { TestInfo } from './types';
+import type { TestInfoImpl } from './types';
 import { Suite } from './test';
 
-let currentTestInfoValue: TestInfo | null = null;
+let currentTestInfoValue: TestInfoImpl | null = null;
-export function setCurrentTestInfo(testInfo: TestInfo | null) {
+export function setCurrentTestInfo(testInfo: TestInfoImpl | null) {
   currentTestInfoValue = testInfo;
 }
-export function currentTestInfo(): TestInfo | null {
+export function currentTestInfo(): TestInfoImpl | null {
   return currentTestInfoValue;
 }
 

src/test/matchers/toBeTruthy.ts

@@ -48,7 +48,7 @@ export async function toBeTruthy<T>(
     received = await query(remainingTime);
     pass = !!received;
     return pass === !matcherOptions.isNot;
-  }, options.timeout, 100);
+  }, options.timeout, 100, testInfo._testFinished);
 
   const message = () => {
     return matcherHint(matcherName, undefined, '', matcherOptions);

src/test/matchers/toEqual.ts

@@ -64,7 +64,7 @@ export async function toEqual<T>(
     received = await query(remainingTime);
     pass = equals(received, expected, [iterableEquality]);
     return pass === !matcherOptions.isNot;
-  }, options.timeout, 100);
+  }, options.timeout, 100, testInfo._testFinished);
 
   const message = pass
     ? () =>

src/test/matchers/toMatchText.ts

@@ -80,7 +80,7 @@ export async function toMatchText(
       pass = expected.test(received);
 
     return pass === !matcherOptions.isNot;
-  }, options.timeout, 100);
+  }, options.timeout, 100, testInfo._testFinished);
 
   const stringSubstring = options.matchSubstring ? 'substring' : 'string';
   const message = pass

src/test/types.ts

@@ -14,7 +14,7 @@
  * limitations under the License.
  */
 
-import type { Fixtures } from '../../types/test';
+import type { Fixtures, TestInfo } from '../../types/test';
 import type { Location } from '../../types/testReporter';
 export * from '../../types/test';
 export { Location } from '../../types/testReporter';
@@ -24,3 +24,7 @@ export type FixturesWithLocation = {
   location: Location;
 };
 export type Annotations = { type: string, description?: string }[];
+
+export interface TestInfoImpl extends TestInfo {
+  _testFinished: Promise<void>;
+}

src/test/util.ts

@@ -71,25 +71,40 @@ export async function raceAgainstDeadline<T>(promise: Promise<T>, deadline: numb
   return (new DeadlineRunner(promise, deadline)).result;
 }
 
-export async function pollUntilDeadline(state: ReturnType<Expect['getState']>, func: (remainingTime: number) => Promise<boolean>, pollTime: number | undefined, pollInterval: number): Promise<void> {
+export async function pollUntilDeadline(state: ReturnType<Expect['getState']>, func: (remainingTime: number) => Promise<boolean>, pollTime: number | undefined, pollInterval: number, deadlinePromise: Promise<void>): Promise<void> {
   const playwrightActionTimeout = (state as any).playwrightActionTimeout;
   pollTime = pollTime === 0 ? 0 : pollTime || playwrightActionTimeout;
   const deadline = pollTime ? monotonicTime() + pollTime : 0;
 
-  while (true) {
+  let aborted = false;
+  const abortedPromise = deadlinePromise.then(() => {
+    aborted = true;
+    return true;
+  });
+
+  while (!aborted) {
     const remainingTime = deadline ? deadline - monotonicTime() : 1000 * 3600 * 24;
     if (remainingTime <= 0)
       break;
 
     try {
-      if (await func(remainingTime))
+      // Either aborted, or func() returned truthy.
+      const result = await Promise.race([
+        func(remainingTime),
+        abortedPromise,
+      ]);
+      if (result)
         return;
     } catch (e) {
       if (e instanceof errors.TimeoutError)
         return;
       throw e;
     }
-    await new Promise(f => setTimeout(f, pollInterval));
+
+    let timer: NodeJS.Timer;
+    const timeoutPromise = new Promise(f => timer = setTimeout(f, pollInterval));
+    await Promise.race([abortedPromise, timeoutPromise]);
+    clearTimeout(timer!);
   }
 }
 

src/test/workerRunner.ts

@@ -24,7 +24,7 @@ import { TestBeginPayload, TestEndPayload, RunPayload, TestEntry, DonePayload, W
 import { setCurrentTestInfo } from './globals';
 import { Loader } from './loader';
 import { Modifier, Suite, TestCase } from './test';
-import { Annotations, TestError, TestInfo, WorkerInfo } from './types';
+import { Annotations, TestError, TestInfo, TestInfoImpl, WorkerInfo } from './types';
 import { ProjectImpl } from './project';
 import { FixturePool, FixtureRunner } from './fixtures';
 
@@ -43,7 +43,7 @@ export class WorkerRunner extends EventEmitter {
   private _fatalError: TestError | undefined;
   private _entries = new Map<string, TestEntry>();
   private _isStopped = false;
-  _currentTest: { testId: string, testInfo: TestInfo } | null = null;
+  _currentTest: { testId: string, testInfo: TestInfoImpl, testFinishedCallback: () => void } | null = null;
 
   constructor(params: WorkerInitParams) {
     super();
@@ -53,8 +53,10 @@ export class WorkerRunner extends EventEmitter {
 
   stop() {
     // TODO: mark test as 'interrupted' instead.
-    if (this._currentTest && this._currentTest.testInfo.status === 'passed')
+    if (this._currentTest && this._currentTest.testInfo.status === 'passed') {
       this._currentTest.testInfo.status = 'skipped';
+      this._currentTest.testFinishedCallback();
+    }
     this._isStopped = true;
   }
 
@@ -218,7 +220,8 @@ export class WorkerRunner extends EventEmitter {
       return path.join(this._project.config.outputDir, testOutputDir);
     })();
 
-    const testInfo: TestInfo = {
+    let testFinishedCallback = () => {};
+    const testInfo: TestInfoImpl = {
       ...this._workerInfo,
       title: test.title,
       file: test.location.file,
@@ -263,6 +266,7 @@ export class WorkerRunner extends EventEmitter {
         if (deadlineRunner)
           deadlineRunner.setDeadline(deadline());
       },
+      _testFinished: new Promise(f => testFinishedCallback = f),
     };
 
     // Inherit test.setTimeout() from parent suites.
@@ -291,7 +295,7 @@ export class WorkerRunner extends EventEmitter {
       }
     }
 
-    this._setCurrentTest({ testInfo, testId });
+    this._setCurrentTest({ testInfo, testId, testFinishedCallback });
     const deadline = () => {
       return testInfo.timeout ? startTime + testInfo.timeout : undefined;
     };
@@ -316,6 +320,7 @@ export class WorkerRunner extends EventEmitter {
     if (!this._isStopped) {
       // When stopped during the test run (usually either a user interruption or an unhandled error),
       // we do not run cleanup because the worker will cleanup() anyway.
+      testFinishedCallback();
       if (!result.timedOut) {
         deadlineRunner = new DeadlineRunner(this._runAfterHooks(test, testInfo), deadline());
         deadlineRunner.setDeadline(deadline());
@@ -350,7 +355,7 @@ export class WorkerRunner extends EventEmitter {
     }
   }
 
-  private _setCurrentTest(currentTest: { testId: string, testInfo: TestInfo} | null) {
+  private _setCurrentTest(currentTest: { testId: string, testInfo: TestInfoImpl, testFinishedCallback: () => void } | null) {
     this._currentTest = currentTest;
     setCurrentTestInfo(currentTest ? currentTest.testInfo : null);
   }

tests/playwright-test/playwright.expect.text.spec.ts

@@ -221,3 +221,22 @@ test('should support toHaveValue', async ({ runInlineTest }) => {
   expect(result.passed).toBe(1);
   expect(result.exitCode).toBe(0);
 });
+
+test('should print expected/received before timeout', async ({ runInlineTest }) => {
+  const result = await runInlineTest({
+    'a.test.ts': `
+      const { test } = pwt;
+
+      test('times out waiting for text', async ({ page }) => {
+        await page.setContent('<div id=node>Text content</div>');
+        await expect(page.locator('#node')).toHaveText('Text 2');
+      });
+      `,
+  }, { workers: 1, timeout: 2000 });
+  expect(result.exitCode).toBe(1);
+  expect(result.passed).toBe(0);
+  expect(result.failed).toBe(1);
+  expect(result.output).toContain('Timeout of 2000ms exceeded.');
+  expect(stripAscii(result.output)).toContain('Expected string: "Text 2"');
+  expect(stripAscii(result.output)).toContain('Received string: "Text content"');
+});