chore: show last poller error on test timeout (#24292)

packages/playwright-core/src/client/android.ts

@@ -28,7 +28,7 @@ import { Waiter } from './waiter';
 import { EventEmitter } from 'events';
 import { Connection } from './connection';
 import { isSafeCloseError, kBrowserClosedError } from '../common/errors';
-import { raceAgainstTimeout } from '../utils/timeoutRunner';
+import { raceAgainstDeadline } from '../utils/timeoutRunner';
 import type { AndroidServerLauncherImpl } from '../androidServerImpl';
 
 type Direction = 'down' | 'up' | 'left' | 'right';
@@ -93,7 +93,7 @@ export class Android extends ChannelOwner<channels.AndroidChannel> implements ap
         }
       });
 
-      const result = await raceAgainstTimeout(async () => {
+      const result = await raceAgainstDeadline(async () => {
         const playwright = await connection!.initializePlaywright();
         if (!playwright._initializer.preConnectedAndroidDevice) {
           closePipe();
@@ -103,7 +103,7 @@ export class Android extends ChannelOwner<channels.AndroidChannel> implements ap
         device._shouldCloseConnectionOnClose = true;
         device.on(Events.AndroidDevice.Close, closePipe);
         return device;
-      }, deadline ? deadline - monotonicTime() : 0);
+      }, deadline);
       if (!result.timedOut) {
         return result.result;
       } else {

packages/playwright-core/src/client/browserType.ts

@@ -26,7 +26,7 @@ import { envObjectToArray } from './clientHelper';
 import { jsonStringifyForceASCII, assert, headersObjectToArray, monotonicTime } from '../utils';
 import type * as api from '../../types/types';
 import { kBrowserClosedError } from '../common/errors';
-import { raceAgainstTimeout } from '../utils/timeoutRunner';
+import { raceAgainstDeadline } from '../utils/timeoutRunner';
 import type { Playwright } from './playwright';
 
 export interface BrowserServerLauncher {
@@ -185,7 +185,7 @@ export class BrowserType extends ChannelOwner<channels.BrowserTypeChannel> imple
         }
       });
 
-      const result = await raceAgainstTimeout(async () => {
+      const result = await raceAgainstDeadline(async () => {
         // For tests.
         if ((params as any).__testHookBeforeCreateBrowser)
           await (params as any).__testHookBeforeCreateBrowser();
@@ -202,7 +202,7 @@ export class BrowserType extends ChannelOwner<channels.BrowserTypeChannel> imple
         browser._connectHeaders = connectHeaders;
         browser.on(Events.Browser.Disconnected, closePipe);
         return browser;
-      }, deadline ? deadline - monotonicTime() : 0);
+      }, deadline);
       if (!result.timedOut) {
         return result.result;
       } else {

packages/playwright-core/src/server/recorder.ts

@@ -40,7 +40,7 @@ import { createGuid, monotonicTime } from '../utils';
 import { metadataToCallLog } from './recorder/recorderUtils';
 import { Debugger } from './debugger';
 import { EventEmitter } from 'events';
-import { raceAgainstTimeout } from '../utils/timeoutRunner';
+import { raceAgainstDeadline } from '../utils/timeoutRunner';
 import type { Language, LanguageGenerator } from './recorder/language';
 import { locatorOrSelectorAsSelector } from '../utils/isomorphic/locatorParser';
 import { eventsHelper, type RegisteredListener } from './../utils/eventsHelper';
@@ -534,7 +534,7 @@ class ContextRecorder extends EventEmitter {
     for (let i = 0; i < chain.length - 1; i++)
       selectorPromises.push(this._findFrameSelector(chain[i + 1], chain[i]));
 
-    const result = await raceAgainstTimeout(() => Promise.all(selectorPromises), 2000);
+    const result = await raceAgainstDeadline(() => Promise.all(selectorPromises), monotonicTime() + 2000);
     if (!result.timedOut && result.result.every(selector => !!selector)) {
       return {
         ...fallback,

packages/playwright-core/src/utils/timeoutRunner.ts

@@ -25,10 +25,13 @@ type TimeoutRunnerData = {
   timeoutPromise: ManualPromise<any>,
 };
 
+export const MaxTime = 2147483647; // 2^31-1
+
 export class TimeoutRunner {
   private _running: TimeoutRunnerData | undefined;
   private _timeout: number;
   private _elapsed: number;
+  private _deadline = MaxTime;
 
   constructor(timeout: number) {
     this._timeout = timeout;
@@ -65,6 +68,10 @@ export class TimeoutRunner {
     return this._elapsed;
   }
 
+  deadline(): number {
+    return this._deadline;
+  }
+
   updateTimeout(timeout: number, elapsed?: number) {
     this._timeout = timeout;
     if (elapsed !== undefined) {
@@ -89,6 +96,7 @@ export class TimeoutRunner {
       running.timer = undefined;
     }
     this._syncElapsedAndStart();
+    this._deadline = timeout ? monotonicTime() + timeout : MaxTime;
     if (timeout === 0)
       return;
     timeout = timeout - this._elapsed;
@@ -99,8 +107,8 @@ export class TimeoutRunner {
   }
 }
 
-export async function raceAgainstTimeout<T>(cb: () => Promise<T>, timeout: number): Promise<{ result: T, timedOut: false } | { timedOut: true }> {
-  const runner = new TimeoutRunner(timeout);
+export async function raceAgainstDeadline<T>(cb: () => Promise<T>, deadline: number): Promise<{ result: T, timedOut: false } | { timedOut: true }> {
+  const runner = new TimeoutRunner((deadline || MaxTime) - monotonicTime());
   try {
     return { result: await runner.run(cb), timedOut: false };
   } catch (e) {
@@ -110,24 +118,22 @@ export async function raceAgainstTimeout<T>(cb: () => Promise<T>, timeout: numbe
   }
 }
 
-export async function pollAgainstTimeout<T>(callback: () => Promise<{ continuePolling: boolean, result: T }>, timeout: number, pollIntervals: number[] = [100, 250, 500, 1000]): Promise<{ result?: T, timedOut: boolean }> {
-  const startTime = monotonicTime();
+export async function pollAgainstDeadline<T>(callback: () => Promise<{ continuePolling: boolean, result: T }>, deadline: number, pollIntervals: number[] = [100, 250, 500, 1000]): Promise<{ result?: T, timedOut: boolean }> {
   const lastPollInterval = pollIntervals.pop() ?? 1000;
   let lastResult: T|undefined;
   const wrappedCallback = () => Promise.resolve().then(callback);
   while (true) {
-    const elapsed = monotonicTime() - startTime;
-    if (timeout !== 0 && elapsed >= timeout)
+    const time = monotonicTime();
+    if (deadline && time >= deadline)
       break;
-    const received = timeout !== 0 ? await raceAgainstTimeout(wrappedCallback, timeout - elapsed)
-      : await wrappedCallback().then(value => ({ result: value, timedOut: false }));
+    const received = await raceAgainstDeadline(wrappedCallback, deadline);
     if (received.timedOut)
       break;
     lastResult = (received as any).result.result;
     if (!(received as any).result.continuePolling)
       return { result: lastResult, timedOut: false };
     const interval = pollIntervals!.shift() ?? lastPollInterval;
-    if (timeout !== 0 && startTime + timeout <= monotonicTime() + interval)
+    if (deadline && deadline <= monotonicTime() + interval)
       break;
     await new Promise(x => setTimeout(x, interval));
   }

packages/playwright-test/src/matchers/DEPS.list

@@ -1,3 +1,4 @@
 [*]
 ../common/
 ../util.ts
+../worker/testInfo.ts

packages/playwright-test/src/matchers/expect.ts

@@ -17,7 +17,7 @@
 import {
   captureRawStack,
   isString,
-  pollAgainstTimeout } from 'playwright-core/lib/utils';
+  pollAgainstDeadline } from 'playwright-core/lib/utils';
 import type { ExpectZone } from 'playwright-core/lib/utils';
 import {
   toBeAttached,
@@ -57,6 +57,7 @@ import {
 } from '../common/expectBundle';
 export type { ExpectMatcherContext } from '../common/expectBundle';
 import { zones } from 'playwright-core/lib/utils';
+import { TestInfoImpl } from '../worker/testInfo';
 
 // from expect/build/types
 export type SyncExpectationResult = {
@@ -328,8 +329,9 @@ class ExpectMetaInfoProxyHandler implements ProxyHandler<any> {
 
 async function pollMatcher(matcherName: any, isNot: boolean, pollIntervals: number[] | undefined, timeout: number, generator: () => any, ...args: any[]) {
   const testInfo = currentTestInfo();
+  const { deadline, timeoutMessage } = testInfo ? testInfo._deadlineForMatcher(timeout) : TestInfoImpl._defaultDeadlineForMatcher(timeout);
 
-  const result = await pollAgainstTimeout<Error|undefined>(async () => {
+  const result = await pollAgainstDeadline<Error|undefined>(async () => {
     if (testInfo && currentTestInfo() !== testInfo)
       return { continuePolling: false, result: undefined };
 
@@ -343,10 +345,9 @@ async function pollMatcher(matcherName: any, isNot: boolean, pollIntervals: numb
     } catch (error) {
       return { continuePolling: true, result: error };
     }
-  }, timeout, pollIntervals ?? [100, 250, 500, 1000]);
+  }, deadline, pollIntervals ?? [100, 250, 500, 1000]);
 
   if (result.timedOut) {
-    const timeoutMessage = `Timeout ${timeout}ms exceeded while waiting on the predicate`;
     const message = result.result ? [
       result.result.message,
       '',

packages/playwright-test/src/matchers/matchers.ts

@@ -21,9 +21,9 @@ import { expectTypes, callLogText, filteredStackTrace } from '../util';
 import { toBeTruthy } from './toBeTruthy';
 import { toEqual } from './toEqual';
 import { toExpectedTextValues, toMatchText } from './toMatchText';
-import { captureRawStack, constructURLBasedOnBaseURL, isTextualMimeType, pollAgainstTimeout } from 'playwright-core/lib/utils';
+import { captureRawStack, constructURLBasedOnBaseURL, isTextualMimeType, pollAgainstDeadline } from 'playwright-core/lib/utils';
 import { currentTestInfo } from '../common/globals';
-import type { TestStepInternal } from '../worker/testInfo';
+import { TestInfoImpl, type TestStepInternal } from '../worker/testInfo';
 import type { ExpectMatcherContext } from './expect';
 
 interface LocatorEx extends Locator {
@@ -356,7 +356,8 @@ export async function toPass(
   };
 
   return await runWithOrWithoutStep(async (step: TestStepInternal | undefined) => {
-    const result = await pollAgainstTimeout<Error|undefined>(async () => {
+    const { deadline, timeoutMessage } = testInfo ? testInfo._deadlineForMatcher(timeout) : TestInfoImpl._defaultDeadlineForMatcher(timeout);
+    const result = await pollAgainstDeadline<Error|undefined>(async () => {
       if (testInfo && currentTestInfo() !== testInfo)
         return { continuePolling: false, result: undefined };
       try {
@@ -365,10 +366,9 @@ export async function toPass(
       } catch (e) {
         return { continuePolling: !this.isNot, result: e };
       }
-    }, timeout, options.intervals || [100, 250, 500, 1000]);
+    }, deadline, options.intervals || [100, 250, 500, 1000]);
 
     if (result.timedOut) {
-      const timeoutMessage = `Timeout ${timeout}ms exceeded while waiting on the predicate`;
       const message = result.result ? [
         result.result.message,
         '',

packages/playwright-test/src/plugins/webServerPlugin.ts

@@ -17,7 +17,7 @@ import path from 'path';
 import net from 'net';
 
 import { debug } from 'playwright-core/lib/utilsBundle';
-import { raceAgainstTimeout, launchProcess, httpRequest } from 'playwright-core/lib/utils';
+import { raceAgainstDeadline, launchProcess, httpRequest, monotonicTime } from 'playwright-core/lib/utils';
 
 import type { FullConfig } from '../../types/testReporter';
 import type { TestRunnerPlugin } from '.';
@@ -128,7 +128,7 @@ export class WebServerPlugin implements TestRunnerPlugin {
     const launchTimeout = this._options.timeout || 60 * 1000;
     const cancellationToken = { canceled: false };
     const { timedOut } = (await Promise.race([
-      raceAgainstTimeout(() => waitFor(this._isAvailable!, cancellationToken), launchTimeout),
+      raceAgainstDeadline(() => waitFor(this._isAvailable!, cancellationToken), monotonicTime() + launchTimeout),
       this._processExitedPromise,
     ]));
     cancellationToken.canceled = true;

packages/playwright-test/src/worker/testInfo.ts

@@ -16,7 +16,7 @@
 
 import fs from 'fs';
 import path from 'path';
-import { captureRawStack, createAfterActionTraceEventForStep, createBeforeActionTraceEventForStep, monotonicTime, zones } from 'playwright-core/lib/utils';
+import { MaxTime, captureRawStack, createAfterActionTraceEventForStep, createBeforeActionTraceEventForStep, monotonicTime, zones } from 'playwright-core/lib/utils';
 import type { TestInfoError, TestInfo, TestStatus, FullProject, FullConfig } from '../../types/test';
 import type { AttachmentPayload, StepBeginPayload, StepEndPayload, WorkerInitParams } from '../common/ipc';
 import type { TestCase } from '../common/test';
@@ -107,6 +107,19 @@ export class TestInfoImpl implements TestInfo {
     // Ignored.
   }
 
+  _deadlineForMatcher(timeout: number): { deadline: number, timeoutMessage: string } {
+    const startTime = monotonicTime();
+    const matcherDeadline = timeout ? startTime + timeout : MaxTime;
+    const testDeadline = this._timeoutManager.currentSlotDeadline() - 100;
+    const matcherMessage = `Timeout ${timeout}ms exceeded while waiting on the predicate`;
+    const testMessage = `Test timeout of ${this.timeout}ms exceeded`;
+    return { deadline: Math.min(testDeadline, matcherDeadline), timeoutMessage: testDeadline < matcherDeadline ? testMessage : matcherMessage };
+  }
+
+  static _defaultDeadlineForMatcher(timeout: number): { deadline: any; timeoutMessage: any; } {
+    return { deadline: (timeout ? monotonicTime() + timeout : 0), timeoutMessage: `Timeout ${timeout}ms exceeded while waiting on the predicate` };
+  }
+
   constructor(
     configInternal: FullConfigInternal,
     projectInternal: FullProjectInternal,

packages/playwright-test/src/worker/timeoutManager.ts

@@ -95,6 +95,10 @@ export class TimeoutManager {
     return this._runnable.type;
   }
 
+  currentSlotDeadline() {
+    return this._timeoutRunner.deadline();
+  }
+
   private _currentSlot() {
     return this._fixture?.slot || this._runnable.slot || this._defaultSlot;
   }

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

@@ -218,3 +218,17 @@ test('should respect interval', async ({ runInlineTest }) => {
   });
   expect(result.exitCode).toBe(0);
 });
+
+test('should show intermediate result for poll that spills over test time', async ({ runInlineTest }) => {
+  const result = await runInlineTest({
+    'a.spec.ts': `
+      import { test, expect } from '@playwright/test';
+      test('should fail', async () => {
+        await test.expect.poll(() => 3).toBe(2);
+      });
+    `
+  }, { timeout: 2000 });
+  expect(result.exitCode).toBe(1);
+  expect(result.output).toContain('Expected: 2');
+  expect(result.output).toContain('Received: 3');
+});

tests/playwright-test/expect-to-pass.spec.ts

@@ -204,3 +204,19 @@ test('should not spin forever', async ({ runInlineTest }) => {
   expect(result.exitCode).toBe(0);
   expect(result.passed).toBe(2);
 });
+
+test('should show intermediate result for toPass that spills over test time', async ({ runInlineTest }) => {
+  const result = await runInlineTest({
+    'a.spec.ts': `
+      import { test, expect } from '@playwright/test';
+      test('should fail', async () => {
+        await expect(() => {
+          expect(3).toBe(2);
+        }).toPass();
+      });
+    `
+  }, { timeout: 1000 });
+  expect(result.exitCode).toBe(1);
+  expect(result.output).toContain('Expected: 2');
+  expect(result.output).toContain('Received: 3');
+});