diff --git a/.changeset/selenium-quit-screenshots.md b/.changeset/selenium-quit-screenshots.md new file mode 100644 index 00000000..ac43559d --- /dev/null +++ b/.changeset/selenium-quit-screenshots.md @@ -0,0 +1,5 @@ +--- +'@wdio/selenium-devtools': patch +--- + +Stop logging `[screenshot] Failed` warnings when the driver quits. Each command row's screenshot is taken in the background, so the last commands' screenshots could still be in flight when `driver.quit()` stopped the session under them, which on an Appium session logged a warning per screenshot. Quit now waits a few seconds for the captures already in flight, and a screenshot that still reaches the quitting session is skipped quietly. diff --git a/packages/core/src/trace-finalizer.ts b/packages/core/src/trace-finalizer.ts index 989d89bf..8f84d25b 100644 --- a/packages/core/src/trace-finalizer.ts +++ b/packages/core/src/trace-finalizer.ts @@ -127,7 +127,7 @@ const SLICE_COUNT_WARN_THRESHOLD = 200 * whole run (finalize never returns → the runner never tears the session down * → the capture stays stuck). Past this bound we write whatever snapshots * resolved in time — the same "flush from what exists" rule slices use. */ -const PENDING_SETTLE_TIMEOUT_MS = 5000 +export const PENDING_SETTLE_TIMEOUT_MS = 5000 /** * `Promise.allSettled` bounded by a timeout. Resolves when every pending @@ -135,7 +135,7 @@ const PENDING_SETTLE_TIMEOUT_MS = 5000 * can never hang the export. Returns whether it timed out so the caller can * warn. The timer is unref'd so it can't itself keep the process alive. */ -async function settlePending( +export async function settlePending( pending: Promise[], timeoutMs: number ): Promise { diff --git a/packages/core/tests/trace-finalizer.test.ts b/packages/core/tests/trace-finalizer.test.ts index 9a1d9a04..3470bcd7 100644 --- a/packages/core/tests/trace-finalizer.test.ts +++ b/packages/core/tests/trace-finalizer.test.ts @@ -12,7 +12,9 @@ import { type SpecRange, type TraceArtifact, type TraceCapturer, - type TraceExportContext + type TraceExportContext, + PENDING_SETTLE_TIMEOUT_MS, + settlePending } from '@wdio/devtools-core' import { TraceType, @@ -20,9 +22,6 @@ import { type TestMetadataMap } from '@wdio/devtools-shared' -/** Mirrors the ceiling in trace-finalizer.ts (module-private there). */ -const PENDING_SETTLE_TIMEOUT_MS = 5000 - function makeCapturer(commandCount = 4): TraceCapturer { return { mutations: [], @@ -75,6 +74,15 @@ function testRange( return { ...range(specFile, startIdx), key, testUid } } +describe('settlePending', () => { + it('reports whether every promise settled before the cap', async () => { + expect( + await settlePending([Promise.resolve(), Promise.reject(new Error())], 50) + ).toBe(false) + expect(await settlePending([new Promise(() => {})], 10)).toBe(true) + }) +}) + describe('finalizeTraceExport', () => { let outputDir: string let artifacts: TraceArtifact[] diff --git a/packages/selenium-devtools/package.json b/packages/selenium-devtools/package.json index a96a55b5..4e31e47f 100644 --- a/packages/selenium-devtools/package.json +++ b/packages/selenium-devtools/package.json @@ -36,7 +36,7 @@ "prepublishOnly": "pnpm build", "example": "pnpm example:cucumber", "example:mocha": "mocha --require @wdio/selenium-devtools --timeout 60000 ../../examples/selenium-js/mocha/example.js", - "example:mobile": "mocha --exit --require @wdio/selenium-devtools --timeout 180000 \"../../examples/selenium-js/mobile/${DEVTOOLS_MOBILE_PLATFORM:-android}/\"*.test.js", + "example:mobile": "mocha --require @wdio/selenium-devtools --timeout 180000 \"../../examples/selenium-js/mobile/${DEVTOOLS_MOBILE_PLATFORM:-android}/\"*.test.js", "example:mocha:allure": "mocha --require @wdio/selenium-devtools --reporter allure-mocha --reporter-options resultsDir=../../examples/selenium-js/mocha/allure-results --timeout 60000 ../../examples/selenium-js/mocha/example.js", "example:jest": "NODE_OPTIONS=--experimental-vm-modules jest --config ../../examples/selenium-js/jest/jest.config.json", "example:cucumber": "cucumber-js --config ../../examples/selenium-js/cucumber/cucumber.json" diff --git a/packages/selenium-devtools/src/helpers/commandPostActions.ts b/packages/selenium-devtools/src/helpers/commandPostActions.ts index f761c20a..db00ef32 100644 --- a/packages/selenium-devtools/src/helpers/commandPostActions.ts +++ b/packages/selenium-devtools/src/helpers/commandPostActions.ts @@ -187,7 +187,7 @@ function attachScreenshotAsync( entry: CommandLog ): void { const ts = entry.timestamp - capturer + const attached = capturer .takeScreenshot() .then((shot) => { if (shot) { @@ -196,6 +196,7 @@ function attachScreenshotAsync( } }) .catch(() => {}) + capturer.track(attached) } /** diff --git a/packages/selenium-devtools/src/index.ts b/packages/selenium-devtools/src/index.ts index 53b2cebf..f4cba7f3 100644 --- a/packages/selenium-devtools/src/index.ts +++ b/packages/selenium-devtools/src/index.ts @@ -538,8 +538,12 @@ class SeleniumDevToolsPlugin { await sessionOnDriverCreated(this.#getInternals(), driver) } - async onCommand(cmd: CapturedCommand) { - await handleOnCommand(this.#getInternals(), cmd) + onCommand(cmd: CapturedCommand): Promise { + const handled = handleOnCommand(this.#getInternals(), cmd).catch((err) => + log.warn(`Command capture failed: ${errorMessage(err)}`) + ) + this.#sessionCapturer?.track(handled) + return handled } /** Fallback path only: under the preload the destination instrumented itself. */ diff --git a/packages/selenium-devtools/src/session-lifecycle.ts b/packages/selenium-devtools/src/session-lifecycle.ts index d353cb1c..7318d2ae 100644 --- a/packages/selenium-devtools/src/session-lifecycle.ts +++ b/packages/selenium-devtools/src/session-lifecycle.ts @@ -295,6 +295,7 @@ export async function onDriverEnd(ctx: SessionLifecycleCtx): Promise { // live mode, before the dashboard loses the session). // Gated on ctx.driver so the post-quit onDriverEnd call skips a dead session. if (ctx.driver && ctx.sessionCapturer) { + await ctx.sessionCapturer.settleBeforeQuit() await ctx.sessionCapturer.nativeNetwork.forward() // Anchored: a run ending on a navigation (logout → /login as the last // action) leaves the destination's async initial anchor unrun at teardown. diff --git a/packages/selenium-devtools/src/session.ts b/packages/selenium-devtools/src/session.ts index ea9e25d4..aaab0a62 100644 --- a/packages/selenium-devtools/src/session.ts +++ b/packages/selenium-devtools/src/session.ts @@ -12,7 +12,9 @@ import { NativeNetworkCapture, mapChromeBrowserLogs, pollUntilReady, - serializeError + PENDING_SETTLE_TIMEOUT_MS, + serializeError, + settlePending } from '@wdio/devtools-core' import { WS_SCOPE } from '@wdio/devtools-shared' import { NAVIGATION_COMMANDS } from './constants.js' @@ -45,6 +47,11 @@ export class SessionCapturer extends SessionCapturerBase { log[level](message) ) + // Work the driver patcher does not await (a command's capture, its row screenshot); quit waits for it. + #inFlight = new Set>() + // A screenshot that reaches a driver being quit is skipped, not reported as a failure. + #endingDrivers = new WeakSet() + #clientConnected = false #clientConnectedWaiters: Array<() => void> = [] #onClientDisconnected?: () => void @@ -111,6 +118,34 @@ export class SessionCapturer extends SessionCapturerBase { this.#driver = driver } + track(work: Promise): void { + this.#inFlight.add(work) + const done = () => this.#inFlight.delete(work) + void work.then(done, done) + } + + /** Before quit, while the session is alive: lets tracked work finish, including what it queues meanwhile. */ + async settleBeforeQuit(): Promise { + const deadline = Date.now() + PENDING_SETTLE_TIMEOUT_MS + while (this.#inFlight.size > 0) { + const timedOut = await settlePending( + [...this.#inFlight], + Math.max(0, deadline - Date.now()) + ) + if (timedOut) { + log.warn( + `${this.#inFlight.size} capture(s) still in flight after ${PENDING_SETTLE_TIMEOUT_MS}ms; quitting without them` + ) + // Forgotten, or a capture that never settles would hold up every later quit too. + this.#inFlight.clear() + break + } + } + if (this.#driver) { + this.#endingDrivers.add(this.#driver) + } + } + /** Re-ref'd first so the close handshake keeps the process alive until it lands. */ override async closeWebSocket(): Promise { this.#socket?.ref() @@ -212,14 +247,15 @@ export class SessionCapturer extends SessionCapturerBase { const driver = this.#driver const originals = getDriverOriginals() const fn = originals.takeScreenshot - if (!driver || !fn) { + if (!driver || !fn || this.#endingDrivers.has(driver)) { return null } try { const data = await fn(driver) return data || null } catch (err) { - log.warn(`[screenshot] Failed: ${errorMessage(err)}`) + const level = this.#endingDrivers.has(driver) ? 'debug' : 'warn' + log[level](`[screenshot] Failed: ${errorMessage(err)}`) return null } } diff --git a/packages/selenium-devtools/tests/teardown-settle.test.ts b/packages/selenium-devtools/tests/teardown-settle.test.ts new file mode 100644 index 00000000..4ad6a745 --- /dev/null +++ b/packages/selenium-devtools/tests/teardown-settle.test.ts @@ -0,0 +1,148 @@ +import { afterEach, describe, expect, it, vi } from 'vitest' +import { PENDING_SETTLE_TIMEOUT_MS, RetryTracker } from '@wdio/devtools-core' +import { getDriverOriginals } from '../src/driverPatcher.js' +import { + handleOnCommand, + type OnCommandCtx +} from '../src/helpers/commandPostActions.js' +import { SuiteManager } from '../src/helpers/suiteManager.js' +import { TestManager } from '../src/helpers/testManager.js' +import { TestReporter } from '../src/reporter.js' +import { SessionCapturer } from '../src/session.js' +import { + onDriverEnd, + type SessionLifecycleCtx +} from '../src/session-lifecycle.js' + +// Regression: the last commands' row screenshots ran into driver.quit() and failed against a stopped Appium server. + +function deferred() { + let resolve: (value: T) => void = () => {} + const promise = new Promise((r) => (resolve = r)) + return { promise, resolve } +} + +const capturers: SessionCapturer[] = [] +function makeCapturer(driver: object = { id: 'd1' }) { + const capturer = new SessionCapturer({}, driver as never) + capturers.push(capturer) + return capturer +} + +function stubScreenshot(impl: () => Promise) { + const fn = vi.fn(impl) + getDriverOriginals().takeScreenshot = fn + return fn +} + +afterEach(() => { + vi.useRealTimers() + delete getDriverOriginals().takeScreenshot + capturers.splice(0).forEach((c) => c.cleanup()) +}) + +describe('selenium SessionCapturer.settleBeforeQuit', () => { + it('waits for tracked work, including work tracked while waiting', async () => { + const capturer = makeCapturer() + const first = deferred() + const second = deferred() + capturer.track(first.promise.then(() => capturer.track(second.promise))) + + let settled = false + const settling = capturer.settleBeforeQuit().then(() => (settled = true)) + first.resolve() + await new Promise((r) => setTimeout(r, 0)) + expect(settled).toBe(false) + + second.resolve() + await settling + expect(settled).toBe(true) + }) + + it('gives up at the ceiling', async () => { + vi.useFakeTimers() + const capturer = makeCapturer() + capturer.track(new Promise(() => {})) + const settling = capturer.settleBeforeQuit() + await vi.advanceTimersByTimeAsync(PENDING_SETTLE_TIMEOUT_MS) + await expect(settling).resolves.toBeUndefined() + + capturer.setDriver({ id: 'd2' } as never) + await expect(capturer.settleBeforeQuit()).resolves.toBeUndefined() + }) + + it('skips screenshots for the driver being quit, not for the next one', async () => { + const shoot = stubScreenshot(async () => 'png') + const capturer = makeCapturer() + await capturer.settleBeforeQuit() + expect(await capturer.takeScreenshot()).toBeNull() + expect(shoot).not.toHaveBeenCalled() + + capturer.setDriver({ id: 'd2' } as never) + expect(await capturer.takeScreenshot()).toBe('png') + }) +}) + +describe('selenium row screenshot', () => { + it('is tracked, so quit waits for it', async () => { + const shot = deferred() + stubScreenshot(() => shot.promise) + const capturer = makeCapturer() + const reporter = new TestReporter(vi.fn()) + const suiteManager = new SuiteManager(reporter) + const root = suiteManager.getOrCreateRootSuite('app.spec.ts', 'Suite') + await handleOnCommand( + { + sessionCapturer: capturer, + testManager: new TestManager(root, reporter, suiteManager), + retryTracker: new RetryTracker(), + options: { captureScreenshots: true, mode: 'live' }, + finalized: false, + driver: undefined, + actionSnapshots: [], + snapshotCaptures: [] + } as unknown as OnCommandCtx, + { + command: 'getTitle', + fromElement: false, + args: [], + timestamp: 0, + startTime: 0, + result: 'x', + error: undefined, + callSource: undefined + } + ) + + let settled = false + const settling = capturer.settleBeforeQuit().then(() => (settled = true)) + await new Promise((r) => setTimeout(r, 0)) + expect(settled).toBe(false) + + shot.resolve('png') + await settling + expect(capturer.commandsLog[0]?.screenshot).toBe('png') + }) +}) + +describe('selenium onDriverEnd', () => { + it('settles in-flight work before it touches the session', async () => { + const order: string[] = [] + const ctx = { + options: { mode: 'live' }, + driver: { id: 'd1' }, + sessionCapturer: { + settleBeforeQuit: vi.fn(async () => void order.push('settle')), + nativeNetwork: { + forward: vi.fn(async () => void order.push('drain')), + stop: vi.fn() + }, + drainAfterLiveCommand: vi.fn(async () => {}) + }, + filmstripFrames: [], + resetRetryTracker: vi.fn() + } as unknown as SessionLifecycleCtx + await onDriverEnd(ctx) + expect(order).toEqual(['settle', 'drain']) + }) +})