From 879ddb73b063e9ff97654b4e3d92969f84f201c8 Mon Sep 17 00:00:00 2001 From: Pavel Feldman Date: Tue, 18 Jul 2023 17:03:26 -0700 Subject: [PATCH] chore: show last poller error on test timeout (#24292) --- .../playwright-core/src/client/android.ts | 6 ++--- .../playwright-core/src/client/browserType.ts | 6 ++--- .../playwright-core/src/server/recorder.ts | 4 ++-- .../src/utils/timeoutRunner.ts | 24 ++++++++++++------- .../playwright-test/src/matchers/DEPS.list | 1 + .../playwright-test/src/matchers/expect.ts | 9 +++---- .../playwright-test/src/matchers/matchers.ts | 10 ++++---- .../src/plugins/webServerPlugin.ts | 4 ++-- .../playwright-test/src/worker/testInfo.ts | 15 +++++++++++- .../src/worker/timeoutManager.ts | 4 ++++ tests/playwright-test/expect-poll.spec.ts | 14 +++++++++++ tests/playwright-test/expect-to-pass.spec.ts | 16 +++++++++++++ 12 files changed, 84 insertions(+), 29 deletions(-) diff --git a/packages/playwright-core/src/client/android.ts b/packages/playwright-core/src/client/android.ts index bdf8744771585..a6163b53c7206 100644 --- a/packages/playwright-core/src/client/android.ts +++ b/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 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 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 { diff --git a/packages/playwright-core/src/client/browserType.ts b/packages/playwright-core/src/client/browserType.ts index 603d39034acd9..90028a2aebcc2 100644 --- a/packages/playwright-core/src/client/browserType.ts +++ b/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 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 imple browser._connectHeaders = connectHeaders; browser.on(Events.Browser.Disconnected, closePipe); return browser; - }, deadline ? deadline - monotonicTime() : 0); + }, deadline); if (!result.timedOut) { return result.result; } else { diff --git a/packages/playwright-core/src/server/recorder.ts b/packages/playwright-core/src/server/recorder.ts index 64ffb379adb9a..0d710697dbc95 100644 --- a/packages/playwright-core/src/server/recorder.ts +++ b/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, diff --git a/packages/playwright-core/src/utils/timeoutRunner.ts b/packages/playwright-core/src/utils/timeoutRunner.ts index b482e3558f209..fb57ffc703b2b 100644 --- a/packages/playwright-core/src/utils/timeoutRunner.ts +++ b/packages/playwright-core/src/utils/timeoutRunner.ts @@ -25,10 +25,13 @@ type TimeoutRunnerData = { timeoutPromise: ManualPromise, }; +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(cb: () => Promise, timeout: number): Promise<{ result: T, timedOut: false } | { timedOut: true }> { - const runner = new TimeoutRunner(timeout); +export async function raceAgainstDeadline(cb: () => Promise, 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(cb: () => Promise, timeout: numbe } } -export async function pollAgainstTimeout(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(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)); } diff --git a/packages/playwright-test/src/matchers/DEPS.list b/packages/playwright-test/src/matchers/DEPS.list index 4e5606ac502c5..59b704628dfe0 100644 --- a/packages/playwright-test/src/matchers/DEPS.list +++ b/packages/playwright-test/src/matchers/DEPS.list @@ -1,3 +1,4 @@ [*] ../common/ ../util.ts +../worker/testInfo.ts diff --git a/packages/playwright-test/src/matchers/expect.ts b/packages/playwright-test/src/matchers/expect.ts index cdf96f3e7b53d..a18214f5382dd 100644 --- a/packages/playwright-test/src/matchers/expect.ts +++ b/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 { 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(async () => { + const result = await pollAgainstDeadline(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, '', diff --git a/packages/playwright-test/src/matchers/matchers.ts b/packages/playwright-test/src/matchers/matchers.ts index fa9678cc3d3f6..81fdf8c15fab1 100644 --- a/packages/playwright-test/src/matchers/matchers.ts +++ b/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(async () => { + const { deadline, timeoutMessage } = testInfo ? testInfo._deadlineForMatcher(timeout) : TestInfoImpl._defaultDeadlineForMatcher(timeout); + const result = await pollAgainstDeadline(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, '', diff --git a/packages/playwright-test/src/plugins/webServerPlugin.ts b/packages/playwright-test/src/plugins/webServerPlugin.ts index d381c6c5bda24..43c2bf7b2c2c0 100644 --- a/packages/playwright-test/src/plugins/webServerPlugin.ts +++ b/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; diff --git a/packages/playwright-test/src/worker/testInfo.ts b/packages/playwright-test/src/worker/testInfo.ts index 58b6361d704be..5813a51a78120 100644 --- a/packages/playwright-test/src/worker/testInfo.ts +++ b/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, diff --git a/packages/playwright-test/src/worker/timeoutManager.ts b/packages/playwright-test/src/worker/timeoutManager.ts index effaac4c3a9e2..72f1384bbca72 100644 --- a/packages/playwright-test/src/worker/timeoutManager.ts +++ b/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; } diff --git a/tests/playwright-test/expect-poll.spec.ts b/tests/playwright-test/expect-poll.spec.ts index 666ab263e51b6..e740fd5abeaa8 100644 --- a/tests/playwright-test/expect-poll.spec.ts +++ b/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'); +}); diff --git a/tests/playwright-test/expect-to-pass.spec.ts b/tests/playwright-test/expect-to-pass.spec.ts index 37bb8c7460277..2c732839301c2 100644 --- a/tests/playwright-test/expect-to-pass.spec.ts +++ b/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'); +});