From ec77c0e75216bdfd40442ea729b796af2f0b376c Mon Sep 17 00:00:00 2001 From: Vince Graics Date: Sun, 13 Sep 2026 12:11:11 +0200 Subject: [PATCH 1/6] fix(tracing): Address redundant state captures per action --- ARCHITECTURE.md | 2 +- CLAUDE.md | 15 +- README.md | 2 +- examples/wdio/mocha/native/clock.e2e.ts | 44 ++ examples/wdio/mocha/wdio.native.conf.ts | 79 ++++ examples/wdio/mocha/wdio.trace.conf.ts | 4 + examples/wdio/package.json | 1 + package.json | 1 + packages/backend/src/trace-reader-utils.ts | 21 +- packages/backend/tests/trace-reader.test.ts | 29 +- packages/core/src/allure-artifacts.ts | 20 +- packages/core/src/screencast.ts | 48 ++- packages/core/tests/allure-artifacts.test.ts | 8 + packages/core/tests/screencast.test.ts | 133 ++++++ packages/service/src/action-snapshot.ts | 114 +++-- packages/service/src/index.ts | 171 ++++---- packages/service/src/session.ts | 32 +- .../service/tests/action-snapshot.test.ts | 54 +-- packages/service/tests/assertion-rows.test.ts | 2 +- packages/service/tests/session.test.ts | 5 +- .../tests/trace-action-capture.test.ts | 397 ++++++++++++++++++ .../service/tests/trace-granularity.test.ts | 7 +- packages/service/tests/trace-metadata.test.ts | 4 +- packages/shared/src/types.ts | 8 + 24 files changed, 976 insertions(+), 225 deletions(-) create mode 100644 examples/wdio/mocha/native/clock.e2e.ts create mode 100644 examples/wdio/mocha/wdio.native.conf.ts create mode 100644 packages/service/tests/trace-action-capture.test.ts diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index fd11018f..3776e8f4 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -192,7 +192,7 @@ The DOM-walking scripts run in the page via `browser.execute`, so — like `scri Per-framework demo projects used for manual verification. -- `examples/wdio/` — WebdriverIO, split into `cucumber/` and `mocha/` (shared page objects in `pageobjects/`). Run via `pnpm demo:wdio` (Cucumber) or `pnpm demo:wdio:mocha`. +- `examples/wdio/` — WebdriverIO, split into `cucumber/` and `mocha/` (shared page objects in `pageobjects/`). Run via `pnpm demo:wdio` (Cucumber), `pnpm demo:wdio:mocha`, or `pnpm demo:wdio:native` (Appium native app — needs a running Appium server and a device, see the README's Mobile testing section). - `examples/nightwatch/` — Nightwatch (both vanilla and Cucumber). Run via `pnpm demo:nightwatch`. - `examples/selenium/` — Selenium with subdirs for `mocha-test/`, `jest-test/`, `cucumber-test/`, `jasmine-test/`, `vitest-test/`. `pnpm demo:selenium` runs mocha; `pnpm --filter @wdio/selenium-devtools example:` runs the others. diff --git a/CLAUDE.md b/CLAUDE.md index 9196819f..09511648 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -81,6 +81,10 @@ The split is not aesthetic. **`backend` may not import `core`** (it would pull f The test for a new helper: *would the backend ever need this to build a zip?* If yes, `trace`. If it needs a driver, a framework hook, or a capture session, `core`. +### One DOM snapshot per action, taken before it + +The per-action trace snapshot is captured in `beforeCommand`, stamped at the previous action's end, so an action's result IS the next action's "before" and every row resolves to a state the driver was idle for. `afterCommand` captures nothing in trace mode. An eager post-action capture — added and removed twice — lands while the screen is still moving, which is the only reason `waitForActionResult` and the `__wdioSnapMark` document tag existed; both are deleted, and both should stay that way. The last action has no successor, so `#finalizePerScenario` supplies it and names its capture after that action — `lastRenderedScreenshot` skips a capture named `__final__`, which is reserved for a session that ran no action at all. What that one capture waits on is `settleAfterLastAction`, and the wait is **gated, not timed**: the drain that runs immediately before it (`captureTrace(browser, true)`) anchors each document once, so `SessionCapturer.replacedDocumentInLastDrain` says whether the last action navigated to a document the session had not seen. No → return at once (the app has been at rest since the last action, so the test's own teardown is the gap that let the paint land). Yes → `waitUntil(document.readyState === 'complete')`, which is only meaningful once you know the document being described is the incoming one: ungated, the OUTGOING document already reports 'complete' right after a click, so a blind poll returns instantly and captures the page the test just left, and the old `body.childElementCount > 0` clause that papered over that made a legitimately blank destination a guaranteed 8 s timeout per test. Native pauses 250 ms instead (no document to poll; a capture at a 0 s gap measures 359–476 KB against 1.87 MB settled on Appium). Residual: a navigation that has not *committed* when the anchor is read still reads as "no navigation" — the same blind spot the deleted document tag had. Don't reintroduce a poll without a gate, or a tag. + ### Adapters are thin and isolated Adapter packages own only: @@ -308,7 +312,7 @@ Documented divergences from the conventions above. They exist today as debt to b - **A Nightwatch command failure arrives as a callback RESULT, not a throw.** Only a synchronous failure reaches the `try/catch` around the wrapped method; an async one (a command that times out waiting for an element) invokes the capture callback with an error-shaped object, and the driver response nests it one level down under the W3C `value` wrapper. `browserProxy.ts` `callbackError` unwraps that and promotes it to the row's `error`. Left in `result`, the row kept `error: undefined` and rendered as a success — no red row, nothing in the Errors tab, the failure readable only as raw text in the result pane. A result carrying `passed` is an assertion outcome and is deliberately not reinterpreted, since those have their own pass/fail path. - **Row order comes from issue order (`CommandLog.sequence`), not from the millisecond clock.** `browser.assert.*` calls are enqueued synchronously and the next command is invoked in the same millisecond, so their `startTime`s tie; because assert rows are appended in the test-end batch while driver rows are appended at completion, the tie resolved in insertion order and put an assert *after* the command it preceded (measured: `assert.textContains` landing below the logout click it ran before). Nightwatch stamps `sequence` when the test issues a row — a driver command at invocation, an assert at enqueue — and `buildActionEvents` uses it as the sort tiebreak. Adapters that emit no deferred rows leave it unset and keep insertion order. - Nightwatch's own per-assertion execution windows are unavailable here: `results.commands` is **empty** for the BDD interface, so `assertCommandTimings` always returns nulls and the rows keep their enqueue timestamp. That is why issue order, not reported timing, has to carry the ordering. -- **Actions that only read the page inherit the preceding action's capture** (`core/trace-frame-snapshots.ts` `claimAfter`). It is non-consuming and falls back to the most recent earlier capture instead of returning nothing, because several actions legitimately share one page state — Nightwatch emits its native assertion rows in a batch whose execution windows collapse onto one instant, and handing the capture to whichever claimed first left the rest of the batch with no DOM, no a11y tree and no screenshot. Nightwatch correspondingly takes **no** capture for an assertion row (`captureAssertCommand`): those rows are emitted at test-end but positioned back on their real execution window, so probing there recorded the page as it was *then* under a timestamp seconds earlier (an assert that ran on `/secure` rendered the `/login` page the test later logged out to). +- **Actions that only read the page inherit the preceding action's capture** (`packages/trace/src/trace-frame-snapshots.ts` `claimAfter`). It is non-consuming and falls back to the most recent earlier capture instead of returning nothing, because several actions legitimately share one page state — Nightwatch emits its native assertion rows in a batch whose execution windows collapse onto one instant, and handing the capture to whichever claimed first left the rest of the batch with no DOM, no a11y tree and no screenshot. Nightwatch correspondingly takes **no** capture for an assertion row (`captureAssertCommand`): those rows are emitted at test-end but positioned back on their real execution window, so probing there recorded the page as it was *then* under a timestamp seconds earlier (an assert that ran on `/secure` rendered the `/login` page the test later logged out to). - **Every per-action snapshot probe is timeout-guarded** (`core/action-snapshot.ts` `probe`, `SNAPSHOT_DRIVER_PROBE_TIMEOUT_MS`), not just the in-page scripts. Nightwatch's `browser.getCurrentUrl()`/`getTitle()` are QUEUED commands: called from inside the plugin's own command hook they enqueue behind the command still running and never resolve, and one unguarded probe in the capture's `Promise.all` stranded the whole snapshot — 10 of 14 captures never settled, so those actions reached the trace with no DOM, no a11y tree and no element rects. Nightwatch now runs all four probes (url/title/screenshot/script) over the raw WebDriver HTTP transport in `nightwatch-devtools/src/helpers/webdriverHttp.ts`, bypassing the queue entirely — the pattern `takeScreenshotViaHttp` already used. Relatedly, `runWith` treats a `null` script result as its fallback: a driver that answers `null` instead of rejecting (no-such-session, transport-swallowed script error) otherwise handed the serializers a non-array and lost the entire snapshot, screenshot and all. - The per-test `screenshot` and `video` options live on the **WDIO `ServiceOptions` only** — not `BaseDevToolsOptions` — because only the service implements them (an option belongs on an adapter until a second adapter consumes it, mirroring the core-helper rule; putting them on the shared base made them appear available in Selenium/Nightwatch and broke those adapters' `Required<>` option types). The policy *types* (`TraceScreenshotPolicy`/`TraceVideoPolicy`) and the capture/slice/encode logic (`core/screenshot-artifact.ts`, `core/video-slice.ts`) are framework-agnostic, so Selenium/Nightwatch adoption was wiring-only — now done (Selenium adds the options on its own `DevToolsOptions` with full inline attach; Nightwatch adds them produce-only — see the Allure-attach entry below). All are gated to `traceGranularity:'test'` (per-test inline Allure); coarser granularities keep artifacts in the manifest. Video records the screencast continuously and slices per-test by wall-time — the session frame buffer is bounded by `maxBufferFrames` (default 2000; decimates keeping first/last), and on non-Chrome the polling recorder issues many `takeScreenshot`s that flood `@wdio/allure-reporter` (pair with `disableWebdriverStepsReporting`). - The `filmstrip` option (dense screencast into the trace) is on **`BaseDevToolsOptions`** — the counterexample to the screenshot/video entry above — because all three adapters implement it (the "second consumer → base" rule realized). Core owns the work (`core/screencast-trace.ts` `thinScreencastFrames`/`buildDenseScreencast`; slice windowing in `spec-trace-helpers.ts`); adapters only default the option, un-gate the recorder in trace mode when it's set, and feed `recorder.frames` into the finalize context. Each adapter captures frames while the recorder is still alive (service `onReload` → `#filmstripFrames`; Selenium `onDriverEnd` drain before nulling; Nightwatch `#finalizeCurrentScreencast` snapshot before delegating), and each finalize context spreads `[...accumulated, ...(live recorder frames)]` so a **mid-run** per-spec/per-test slice flush (which fires before the recorder is drained) isn't blank. When dense frames are present they **supersede** the sparse per-action filmstrip (the per-action DOM `elements`/`snapshot` are carried independently by the `frame-snapshot` events, so no DOM data is lost); a run without dense frames keeps the sparse filmstrip, byte-stable with before. Thinning is applied at export; the live session frame buffer is bounded by `maxBufferFrames` (default 2000; see the screenshot/video entry above). Per-test filmstrip slicing follows the same per-test-hook availability as `traceGranularity:'test'` (works for WDIO mocha/cucumber, Selenium mocha, Nightwatch exports-object/cucumber; Nightwatch BDD `describe/it` degrades to session scope per the entry below), and non-Chrome polling carries the same reporter-noise caveat. @@ -330,11 +334,18 @@ Documented divergences from the conventions above. They exist today as debt to b - **Two mechanisms resolve a command's target selector, and the WDIO one is wrong for interleaved handles.** Selenium keys a `WeakMap` on handle identity (`WebElement.id_` is a promise, so no id is readable when a command is invoked); the service uses a mutable last-selector in `service/src/command-selectors.ts`, which stamps the wrong locator for `const a = await $('#a'); const b = await $('#b'); await a.click()` (the Selenium side is covered in `selenium-devtools/tests/element-locators.test.ts`; the WDIO failure itself has **no** test — it is an unverified reading of `command-selectors.ts`). They cannot share a registry — WDIO's hook sees a *serialized* handle carrying an id string and never the live object, Selenium has the object and no readable id. Unifying would need the policy parameterized rather than the storage shared; until then the WDIO path is knowingly wrong in that case. Nightwatch is a third mechanism: it reads arg 0 through a per-kind allowlist (`assertTarget.ts`) rather than tracking handles at all, because its classic API takes selector strings. The allowlists are deliberately **not** derived from shared's `ACTION_MAP` — that table says how a command *renders* (its `Element` entries include WDIO commands called on a handle, with no selector argument), not whether arg 0 is an element definition. - Service renders expect-webdriverio matchers as single `expect.` rows by **folding**, not stack/depth suppression (the old `#assertionDepth`/`#matcherStarted`/self-heal machinery is gone). The matcher's value-read (`toHaveText`→`getText`, `toExist`→`isExisting`, …) is captured as a normal command; `afterAssertion` then coalesces the synthesized `expect.*` row into that read in place — inheriting its callSource, screenshot, and timeline position — and the fold replaces **by timestamp, never a public `id`**: `id` is the per-worker `commandCounter`, which resets per spec, so stamping one lets the app's id-first `replaceCommand` swap a same-id row from another spec (duplicate rows + a fold from another spec vanishing, in multi-spec live mode). `beforeAssertion` arms the pending matcher (depth-counted so aliases like `toBeChecked`→`toBeSelected` fold once); a matcher that **hard-throws** — element never resolves, so expect-webdriverio's `waitUntil` rethrows and `afterAssertion` never fires — is synthesized at `afterTest`/`afterStep` from the throwing read, so a failing assertion renders as `expect.` whether or not the element existed. Two limits: its error is then the read's (`Can't call getText on … element wasn't found`), not an assertion-phrased message; and `MATCHER_READ_COMMANDS` is a hand-maintained allowlist, so a matcher whose read isn't listed leaves its raw read visible alongside the `expect.*` row. Plain-value jest matchers (`expect(x).toBe(y)`) don't fire the ewdio hooks, so they aren't captured as rows. +### What a per-action trace capture costs + +- **One capture per action means two driver round trips per action, and the platform decides which half is expensive.** Measured on Appium 3.7.0 / UiAutomator2 (emulator-5554, Android API 37, 1080×2424): `GET /screenshot` 1.18–2.22 s (steady ~1.20 s) at 1.86 MB, `GET /source` (page-source XML) 0.09–0.53 s at 40 KB, `window/rect` 0.015 s — the screenshot dominates by ~10× on Android. **iOS is unmeasured**; the issue claims the split inverts there, and the native example (`examples/wdio/mocha/wdio.native.conf.ts`) is what makes it measurable. Measured per action: two captures 2.41 s against one capture 1.19 s; end-to-end on the native example 19.1 s against 12.4 s, with live mode (no per-action capture) at 5.9 s. That is the case for the `beforeCommand` capture, and the reason an eager post-action capture is not worth re-adding: it cost a second capture per action and existed only to be patched by a `readyState` poll that could not tell a document that had not navigated yet from one that was loading. +- A filmstrip poll against a native session stacks requests: `setInterval` never waits for its async handler, a native screenshot takes ~1.2 s against the 200 ms default, and a serialised driver serves that queue ahead of the test's own commands — measured, a **15 ms command took 4.5–7.8 s**. `ScreencastRecorderBase`'s `#pollInFlight` latch bounds it to one outstanding shot, and `#pollGeneration` stops a shot orphaned by `stop()` from appending into the next recording or clearing its successor's latch. +- Residual: **a polling matcher fires one capture per poll** — each poll is a top-level mapped read — so "one capture per action" undercounts a real suite. Pre-existing in `d924a02`, unmeasured on a device, and the likeliest next lever. +- The next test's first pre-capture used to be stamped at the previous test's last-action timestamp — the log it scans is run-long, so a test boundary was invisible to it. That slot already holds the previous test's finalize capture, and the richer-screenshot merge could replace it: with a `reloadSession` between the tests the row replayed the post-reload page. The capture now stamps `Date.now()` when the scanned timestamp predates `#currentTestStartWallTime` (0 without per-test hooks, so the standalone path is unchanged) — the same rule that makes a session's first capture its initial frame. Per-test slices were never affected: `flushTest` runs inside `afterTest`, before the next test's commands. + ### File-size (raw line counts; soft cap is 500 logic lines) Most entries below don't trigger the `max-lines` lint rule after `skipBlankLines`/`skipComments`; they're documented because their raw line count is over 500, and the next substantive change to any of them should still look for an extraction opportunity. The service plugin is the exception — it's now over the *logic*-line cap. -- `packages/service/src/index.ts` (602 logic / 843 raw, was 729/1043). Still over the 500-logic cap. The screencast and trace-slice seams are extracted: `screencast-lifecycle.ts` (139 logic / 217 raw) owns every read and write of recorder frames — start, reload, finalize, the cross-`reloadSession` filmstrip buffer and the per-test video slice, two invariants that were previously produced and consumed 400 lines apart — and `trace-slices.ts` (58 logic / 87 raw) owns boundary recording plus the eager per-test flush beside the flush I/O it already held. The only remaining cluster large enough to close the gap is the command-hook family (`beforeCommand`/`afterCommand`/`#commandStack`/`#markDocument`/`#drainAfterLiveCommand`, ~120 logic lines); `before()` is still over the function cap at 62 logic lines. +- `packages/service/src/index.ts` (608 logic / 903 raw, was 729/1043). Still over the 500-logic cap. The screencast and trace-slice seams are extracted: `screencast-lifecycle.ts` (139 logic / 217 raw) owns every read and write of recorder frames — start, reload, finalize, the cross-`reloadSession` filmstrip buffer and the per-test video slice, two invariants that were previously produced and consumed 400 lines apart — and `trace-slices.ts` (58 logic / 87 raw) owns boundary recording plus the eager per-test flush beside the flush I/O it already held. The only remaining cluster large enough to close the gap is the command-hook family (`beforeCommand`/`afterCommand`/`#commandStack`/`#drainAfterLiveCommand`, ~120 logic lines); `before()` is still over the function cap at 62 logic lines. - `packages/nightwatch-devtools/src/index.ts` (783 raw / 676 logic). Cucumber/test/run-lifecycle, session-init, event-hub and now the screencast seam (`plugin-screencast.ts`, 105 raw / 60 logic) are extracted; the remainder is the `PluginInternals` accessor bag plus per-method delegators plus the factory. The bag is deliberately declarative — accept as-is. - `packages/selenium-devtools/src/index.ts` (~644 raw, down from ~758 — the dead `scriptInjected` accessor pair and setter are gone). Session/test-lifecycle **and** the per-test-artifact seam are now extracted: the sink cache + input snapshot + produce/attach flow live in `selenium-devtools/src/test-artifacts.ts` as `SeleniumTestArtifacts` (mirrors Nightwatch's twin — a typed input bag threading the Allure sink + flushed-trace promise), and the plugin keeps only a thin bag-building delegator. Remainder is the `PluginInternals` accessor bag plus onCommand/onDriverCreated wiring. Still over the 500 **raw** soft cap (under the logic-line cap after `skipBlankLines`/`skipComments`); the accessor bag / command wiring is the next extraction candidate if it grows. - `packages/nightwatch-devtools/src/session.ts` (519 raw, under the logic-line cap after `skipBlankLines`/`skipComments`). `captureNetworkFromPerformanceLogs` + `captureBrowserLogs` + `drainCollector` are tightly coupled to NightwatchBrowser state. Coverage at 78% after recent backfill; further extraction would need rewriting the browser-coupling. diff --git a/README.md b/README.md index 9cec10dc..deefa1a5 100644 --- a/README.md +++ b/README.md @@ -202,7 +202,7 @@ services: [[DevToolsHookService, { Adapters detect mobile sessions via `platformName: 'android' | 'ios'` (case-insensitive) and adjust the per-action snapshot to extract elements from the mobile XML tree instead of the DOM. The trace's `context-options` records `title: 'android' — ` / `'ios' — ` so the viewer labels frames correctly. -A reference WDIO config is at [examples/wdio/cucumber/wdio.mobile.conf.ts](examples/wdio/cucumber/wdio.mobile.conf.ts). Prereqs to run it end-to-end with a local emulator: +A reference WDIO config is at [examples/wdio/cucumber/wdio.mobile.conf.ts](examples/wdio/cucumber/wdio.mobile.conf.ts) — that one drives Chrome *on* the device. For a native app (no document at all, so the snapshot reads the page-source XML) there is [examples/wdio/mocha/wdio.native.conf.ts](examples/wdio/mocha/wdio.native.conf.ts), run via `pnpm demo:wdio:native`: it needs no APK, launches a preinstalled app, and reads its Appium endpoint from `APPIUM_HOST` / `APPIUM_PORT` / `APPIUM_DEVICE` (plus `APPIUM_APP` to install a bundle instead). No Chromedriver is involved. Prereqs to run either end-to-end with a local emulator: 1. **Java JDK** — `brew install --cask temurin` 2. **Android SDK** — `brew install --cask android-commandlinetools` then `yes | sdkmanager --licenses && sdkmanager "platform-tools" "emulator" "system-images;android-34;google_apis_playstore;arm64-v8a"`. The brew cask installs sdkmanager under `/opt/homebrew/share/android-commandlinetools/`, and sdkmanager downloads other SDK pieces alongside it — set `ANDROID_HOME` to that path (not `~/Library/Android/sdk/`). diff --git a/examples/wdio/mocha/native/clock.e2e.ts b/examples/wdio/mocha/native/clock.e2e.ts new file mode 100644 index 00000000..8d6ce80f --- /dev/null +++ b/examples/wdio/mocha/native/clock.e2e.ts @@ -0,0 +1,44 @@ +// A native Android spec: no document, no URL, no DOM — the capture path a +// browser session never exercises. Drives Clock, which ships with every Android +// system image, so the example needs no APK and no app upload. +// +// Every selector below was read off an emulator (API 37, Clock from +// com.google.android.deskclock); resource-ids are used over text because the +// countdown text changes every second. +import { expect } from '@wdio/globals' + +const APP_ID = 'com.google.android.deskclock' + +const byId = (id: string) => + $( + `android=new UiSelector().resourceId("com.google.android.deskclock:id/${id}")` + ) + +describe('Clock (native)', () => { + it('starts a preset timer, pauses it, and clears it', async () => { + console.log('[TEST] launching the Clock app') + // `mobile: activateApp` rather than an `appium:app`/`appActivity` + // capability: the activity name is build-specific and this needs no + // adb_shell, which Appium does not enable by default. + await browser.execute('mobile: activateApp', { appId: APP_ID }) + + console.log('[TEST] opening the Timers tab') + await byId('tab_menu_timer').click() + + console.log('[TEST] starting the 5 minute preset') + // This build starts the timer straight from the preset — verified on the + // device — so the running countdown is the evidence the tap landed. + await byId('timer_preset_2').click() + await expect(byId('timer_text')).toHaveText(/^\d{2}:\d{2}$/) + + console.log('[TEST] pausing the timer') + await byId('play_pause_button').click() + // The button's accessibility label flips with the timer's state; asserting + // on it keeps this step off the countdown's own clock. + await expect($('~Start 5 minutes timer')).toBeDisplayed() + + console.log('[TEST] clearing the timer') + await byId('delete_button').click() + await expect(byId('timer_text')).not.toBeDisplayed() + }) +}) diff --git a/examples/wdio/mocha/wdio.native.conf.ts b/examples/wdio/mocha/wdio.native.conf.ts new file mode 100644 index 00000000..e289f2d3 --- /dev/null +++ b/examples/wdio/mocha/wdio.native.conf.ts @@ -0,0 +1,79 @@ +// Native-app variant of wdio.trace.conf.ts: drives a preinstalled Android app +// over Appium, so a trace can be produced from a session that has NO document — +// the path where the per-action snapshot reads page-source XML instead of +// running page scripts. The mobile-WEB variant lives in +// cucumber/wdio.mobile.conf.ts; that one drives Chrome on the device and takes +// the web capture path, so the two are not interchangeable. +// +// Prerequisites: an Appium server with the UiAutomator2 driver +// (`appium driver install uiautomator2`) and an emulator or device attached. +// The endpoint and device come from the environment, so a remote host works: +// +// APPIUM_HOST=100.69.254.5 APPIUM_PORT=4723 pnpm native +// +// No APK is needed — the spec launches a preinstalled app itself. Set +// APPIUM_APP to a bundle path or URL to install one instead. +export const config: WebdriverIO.Config = { + runner: 'local', + + // Native specs live in their own folder so the web configs' `./specs/**` + // glob can't pick them up — they drive Appium, not a browser. + specs: ['./native/**/*.e2e.ts'], + exclude: [], + + hostname: process.env.APPIUM_HOST ?? '127.0.0.1', + port: Number(process.env.APPIUM_PORT ?? 4723), + path: '/', + + maxInstances: 1, + capabilities: [ + { + platformName: 'Android', + 'appium:automationName': 'UiAutomator2', + 'appium:deviceName': process.env.APPIUM_DEVICE ?? 'emulator-5554', + // Keep whatever the app already has on the device — this example drives + // an app it did not install. + 'appium:noReset': true, + ...(process.env.APPIUM_APP + ? { 'appium:app': process.env.APPIUM_APP } + : {}), + // Appium's BiDi shim for UiAutomator2 doesn't implement every BiDi + // command (e.g. script.addPreloadScript), so keep WDIO on classic. + 'wdio:enforceWebDriverClassic': true + } + // eslint-disable-next-line @typescript-eslint/no-explicit-any + ] as any, + + logLevel: 'warn', + bail: 0, + waitforTimeout: 15000, + connectionRetryTimeout: 120000, + connectionRetryCount: 3, + services: [ + [ + 'devtools', + { + // Trace by default; DEVTOOLS_MODE=live gives the same spec a baseline to + // measure the capture cost against. + mode: (process.env.DEVTOOLS_MODE === 'live' ? 'live' : 'trace') as + 'live' | 'trace', + traceGranularity: (process.env.DEVTOOLS_TRACE_GRANULARITY ?? + 'session') as 'session' | 'spec' | 'test', + tracePolicy: (process.env.DEVTOOLS_TRACE_POLICY ?? 'on') as + 'on' | 'retain-on-failure' | 'retain-on-first-failure', + // Off by default because a native session has no CDP: the recorder + // falls back to polling `takeScreenshot` on an interval, which against a + // phone is a second, competing source of driver round trips. Set + // DEVTOOLS_FILMSTRIP=on to record one anyway. + filmstrip: process.env.DEVTOOLS_FILMSTRIP === 'on', + emitArtifactsManifest: true + } + ] + ], + framework: 'mocha', + reporters: ['spec'], + mochaOpts: { + ui: 'bdd', + timeout: 120000 + } +} diff --git a/examples/wdio/mocha/wdio.trace.conf.ts b/examples/wdio/mocha/wdio.trace.conf.ts index b50b9961..3994b419 100644 --- a/examples/wdio/mocha/wdio.trace.conf.ts +++ b/examples/wdio/mocha/wdio.trace.conf.ts @@ -46,6 +46,10 @@ export const config: WebdriverIO.Config = { | 'on-first-retry' | 'on-all-retries' | 'retain-on-failure-and-retries', + // Dense screencast frames written into the trace; on by default, and the + // heaviest part of a session's teardown. DEVTOOLS_FILMSTRIP=off measures + // the trace without them. + filmstrip: process.env.DEVTOOLS_FILMSTRIP !== 'off', // Always emit the manifest so the artifact set is inspectable per run. emitArtifactsManifest: true } diff --git a/examples/wdio/package.json b/examples/wdio/package.json index f2a13edd..30c3e369 100644 --- a/examples/wdio/package.json +++ b/examples/wdio/package.json @@ -22,6 +22,7 @@ "cucumber": "wdio run ./cucumber/wdio.conf.ts", "mocha": "wdio run ./mocha/wdio.conf.ts", "mobile": "wdio run ./cucumber/wdio.mobile.conf.ts", + "native": "wdio run ./mocha/wdio.native.conf.ts", "trace": "wdio run ./cucumber/wdio.trace.conf.ts", "retention": "wdio run ./cucumber/wdio.retention.conf.ts" } diff --git a/package.json b/package.json index 0fd9355a..9c6d2bd2 100644 --- a/package.json +++ b/package.json @@ -10,6 +10,7 @@ "demo:wdio": "wdio run ./examples/wdio/cucumber/wdio.conf.ts", "demo:wdio:mocha": "wdio run ./examples/wdio/mocha/wdio.conf.ts", "demo:wdio:retry": "wdio run ./examples/wdio/mocha/wdio.retry.conf.ts", + "demo:wdio:native": "wdio run ./examples/wdio/mocha/wdio.native.conf.ts", "demo:nightwatch": "pnpm --filter @wdio/nightwatch-devtools example", "demo:nightwatch:retry": "pnpm --filter @wdio/nightwatch-devtools example:retry", "demo:selenium": "pnpm --filter @wdio/selenium-devtools example", diff --git a/packages/backend/src/trace-reader-utils.ts b/packages/backend/src/trace-reader-utils.ts index 0026dce0..7e23b1ed 100644 --- a/packages/backend/src/trace-reader-utils.ts +++ b/packages/backend/src/trace-reader-utils.ts @@ -290,20 +290,27 @@ export function buildSources( return sources } +/** The frame that shows a command's state: the latest capture at or before it, + * since a capture is stamped when the document was read. Falling back to the + * next later frame only when nothing precedes keeps a row without a capture of + * its own from replaying the state its SUCCESSOR produced, which is what an + * absolute-nearest rule does when the successor's frame is the closer one. */ export function nearestFrame( frames: TracePlayerFrame[], timestamp: number ): TracePlayerFrame | undefined { - let best: TracePlayerFrame | undefined - let bestDelta = Infinity + let preceding: TracePlayerFrame | undefined + let following: TracePlayerFrame | undefined for (const frame of frames) { - const delta = Math.abs(frame.timestamp - timestamp) - if (delta < bestDelta) { - bestDelta = delta - best = frame + if (frame.timestamp <= timestamp) { + if (!preceding || frame.timestamp > preceding.timestamp) { + preceding = frame + } + } else if (!following || frame.timestamp < following.timestamp) { + following = frame } } - return best + return preceding ?? following } export function buildMetadata(ctx: ContextOptionsEvent | undefined): Metadata { diff --git a/packages/backend/tests/trace-reader.test.ts b/packages/backend/tests/trace-reader.test.ts index a414ac56..6aae8008 100644 --- a/packages/backend/tests/trace-reader.test.ts +++ b/packages/backend/tests/trace-reader.test.ts @@ -6,7 +6,11 @@ import type { TraceActionGroupNode } from '@wdio/devtools-shared' import { parseTraceZip } from '../src/trace-reader.js' -import { buildSources, stackToCallSource } from '../src/trace-reader-utils.js' +import { + buildSources, + nearestFrame, + stackToCallSource +} from '../src/trace-reader-utils.js' import type { BeforeEvent } from '../src/trace-reader-types.js' function allGroups(children: TraceActionChild[]): TraceActionGroupNode[] { @@ -858,3 +862,26 @@ describe('glued callSource recovery from older zips', () => { expect(sources).toEqual({ [clean]: 'glued source' }) }) }) + +describe('nearestFrame', () => { + const frame = (timestamp: number) => ({ timestamp, screenshot: 'x' }) + + it('shows a row the state it observed, not the one its successor produced', () => { + // One capture per action means a row without one of its own (an assert row, + // an internal command) sits BETWEEN two captures. The later one is the + // successor's result, so the earlier is the state this row actually saw. + const frames = [frame(100), frame(300)] + expect(nearestFrame(frames, 220)).toEqual(frame(100)) + expect(nearestFrame(frames, 260)).toEqual(frame(100)) + }) + + it('takes the next frame when nothing precedes the row', () => { + expect(nearestFrame([frame(300)], 220)).toEqual(frame(300)) + }) + + it('prefers the frame at the row own timestamp', () => { + const frames = [frame(100), frame(300)] + expect(nearestFrame(frames, 300)).toEqual(frame(300)) + expect(nearestFrame(frames, 100)).toEqual(frame(100)) + }) +}) diff --git a/packages/core/src/allure-artifacts.ts b/packages/core/src/allure-artifacts.ts index 88c80c34..a4779753 100644 --- a/packages/core/src/allure-artifacts.ts +++ b/packages/core/src/allure-artifacts.ts @@ -81,13 +81,21 @@ export async function attachTraceArtifact( } } +/** A snapshot's command for a session that ran no action at all, so the frame + * carries no result to show and may be a blank post-teardown page. Written by + * the service's per-scenario finalize, skipped by `lastRenderedScreenshot`. + * Shared rather than repeated: a rename on one side would silently stop the + * skip from matching and start attaching those frames as test screenshots. */ +export const FINAL_SNAPSHOT_COMMAND = '__final__' + /** * The base64 of the last rendered action snapshot for the current test, skipping - * the end-of-scenario `__final__` frame (captured post-teardown, often blank when - * a reloadSession runs before the after-hook). Scoped to `>= startWallTime` so a - * test that captured nothing doesn't borrow the previous test's frame. Reused as - * the per-test screenshot — reload-immune and one fewer WebDriver command than a - * fresh end-of-test capture. + * a `FINAL_SNAPSHOT_COMMAND` frame — which a session that ran no action at all + * produces, so it carries no result to show and may be a blank post-teardown + * page. Scoped to `>= startWallTime` so a test that captured nothing doesn't + * borrow the previous test's frame. Reused as the per-test screenshot — + * reload-immune and one fewer WebDriver command than a fresh end-of-test + * capture. */ export function lastRenderedScreenshot( snapshots: readonly ActionSnapshot[], @@ -98,7 +106,7 @@ export function lastRenderedScreenshot( if (snap.timestamp < startWallTime) { return undefined } - if (snap.command !== '__final__' && snap.screenshot) { + if (snap.command !== FINAL_SNAPSHOT_COMMAND && snap.screenshot) { return snap.screenshot } } diff --git a/packages/core/src/screencast.ts b/packages/core/src/screencast.ts index e5d3b8f9..44afc2e1 100644 --- a/packages/core/src/screencast.ts +++ b/packages/core/src/screencast.ts @@ -22,6 +22,11 @@ export abstract class ScreencastRecorderBase { protected options: Required protected driver?: TDriver #pollTimer: ReturnType | undefined + #pollInFlight = false + /** Bumped by start and stop alike. A shot that outlives its loop compares + * against this: its frame belongs to the old recording, and the latch it + * holds is not the successor's to clear. */ + #pollGeneration = 0 #isRecording = false #cdpActive = false #startIndex = 0 @@ -41,14 +46,22 @@ export abstract class ScreencastRecorderBase { if (this.#isRecording) { return } + // Claimed before the first await, because a stop() arriving during any of + // them has nothing else to invalidate: nothing is armed, and #isRecording is + // still false, so without this the loop would be armed after the caller + // stopped it. A native session's first screenshot runs ~1.2 s. + const generation = ++this.#pollGeneration this.driver = driver const cdpOk = await this.tryStartCdp() + if (generation !== this.#pollGeneration) { + return + } if (cdpOk) { this.#cdpActive = true this.#isRecording = true return } - await this.#startPolling() + await this.#startPolling(generation) } /** @@ -56,6 +69,10 @@ export abstract class ScreencastRecorderBase { * never called or failed. */ async stop(): Promise { + // Bumped before the early return: a stop() that lands while start() is still + // awaiting its first screenshot finds nothing armed and #isRecording still + // false, so returning above would let start() arm the loop afterwards. + this.#pollGeneration++ if (!this.#isRecording) { return } @@ -209,9 +226,12 @@ export abstract class ScreencastRecorderBase { // ─── Polling implementation ───────────────────────────────────────────── - async #startPolling(): Promise { + async #startPolling(generation: number): Promise { try { const first = await this.takeScreenshot() + if (generation !== this.#pollGeneration) { + return + } if (first === null) { this.onUnavailable(new Error('first screenshot returned null')) return @@ -227,14 +247,28 @@ export abstract class ScreencastRecorderBase { if (isInputDispatchInFlight()) { return } + // setInterval does not wait for this handler. A screenshot slower than + // the interval stacks requests that a serialised driver then serves + // ahead of the test's own commands (a native session's screenshot runs + // ~1.2 s against a 200 ms default) — keep at most one outstanding. + if (this.#pollInFlight) { + return + } + this.#pollInFlight = true try { const data = await this.takeScreenshot() - if (data !== null) { + if (data !== null && generation === this.#pollGeneration) { this.#appendFrame({ data, timestamp: Date.now() }) } } catch { // Session ended mid-interval — stop polling gracefully. - this.#stopPolling() + if (generation === this.#pollGeneration) { + this.#stopPolling() + } + } finally { + if (generation === this.#pollGeneration) { + this.#pollInFlight = false + } } }, intervalMs) @@ -249,6 +283,12 @@ export abstract class ScreencastRecorderBase { if (this.#pollTimer !== undefined) { clearInterval(this.#pollTimer) this.#pollTimer = undefined + // A shot issued just before the stop outlives it. Bumping the generation + // keeps that orphan from appending into a later recording or clearing the + // successor's latch, and clearing the latch here lets a restart tick + // without waiting on it. + this.#pollGeneration++ + this.#pollInFlight = false this.onPollingStopped(this.buffer.length) } } diff --git a/packages/core/tests/allure-artifacts.test.ts b/packages/core/tests/allure-artifacts.test.ts index 7ce26252..39bffc9f 100644 --- a/packages/core/tests/allure-artifacts.test.ts +++ b/packages/core/tests/allure-artifacts.test.ts @@ -106,6 +106,14 @@ describe('lastRenderedScreenshot', () => { expect(lastRenderedScreenshot(snaps, 100)).toBe('BB') }) + it('returns a last-action frame that carries the action name', () => { + // The service captures the FINAL action's result in its own finalize, named + // after that action — the marker is only for a session with no action at + // all, so the screenshot a failing test is judged on is the failure's. + const snaps = [snap('setValue', 200, 'BB'), snap('click', 300, 'CC')] + expect(lastRenderedScreenshot(snaps, 100)).toBe('CC') + }) + it('returns undefined when the only snapshots predate the test start', () => { expect( lastRenderedScreenshot([snap('click', 50, 'AA')], 100) diff --git a/packages/core/tests/screencast.test.ts b/packages/core/tests/screencast.test.ts index 663a7693..b58eb207 100644 --- a/packages/core/tests/screencast.test.ts +++ b/packages/core/tests/screencast.test.ts @@ -54,6 +54,32 @@ describe('ScreencastRecorderBase — polling path', () => { expect(throwR.isRecording).toBe(false) }) + it('does not arm a loop that a stop() during the first shot has cancelled', async () => { + vi.useFakeTimers() + let release: ((value: string) => void) | undefined + class SlowFirst extends TestRecorder { + protected override takeScreenshot(): Promise { + this.shotsTaken++ + return new Promise((resolve) => { + release = resolve + }) + } + } + const r = new SlowFirst({ pollIntervalMs: 50 }) + const starting = r.start({ name: 'driver' }) + // Nothing is armed yet and `isRecording` is still false, so this stop() has + // no timer to clear — without the generation it would return as a no-op and + // the interval would arm underneath it. + await r.stop() + release?.('late-shot') + await starting + await vi.advanceTimersByTimeAsync(500) + + expect(r.isRecording).toBe(false) + expect(r.bufferLength).toBe(0) + vi.useRealTimers() + }) + it('captures multiple frames at the configured interval', async () => { vi.useFakeTimers() const r = new TestRecorder({ pollIntervalMs: 50 }) @@ -144,6 +170,113 @@ describe('ScreencastRecorderBase — input-dispatch gate', () => { }) }) +describe('ScreencastRecorderBase — in-flight latch', () => { + it('keeps at most one screenshot outstanding when a shot outruns the interval', async () => { + vi.useFakeTimers() + let shots = 0 + class SlowRecorder extends TestRecorder { + protected override takeScreenshot(): Promise { + shots++ + // The first shot (before the interval starts) resolves, so recording + // begins; every later one stays in flight, standing in for a native + // session's ~1.2 s screenshot against a 200 ms interval. setInterval + // does not wait, so without the latch ten ticks stack ten requests that + // a serialised driver then serves ahead of the test's own commands. + return shots === 1 ? Promise.resolve('initial') : new Promise(() => {}) + } + } + const r = new SlowRecorder({ pollIntervalMs: 50 }) + await r.start({ name: 'driver' }) + expect(shots).toBe(1) + + await vi.advanceTimersByTimeAsync(500) // 10 ticks + expect(shots).toBe(2) // one outstanding; the other nine dropped + + await r.stop() + vi.useRealTimers() + }) + + it('restarts polling without waiting for a shot orphaned by stop()', async () => { + vi.useFakeTimers() + let hanging = true + let shots = 0 + class Orphaned extends TestRecorder { + protected override takeScreenshot(): Promise { + shots++ + return hanging && shots > 1 + ? new Promise(() => {}) + : Promise.resolve(`f-${shots}`) + } + } + const r = new Orphaned({ pollIntervalMs: 50 }) + await r.start({ name: 'driver' }) // shot 1 resolves + await vi.advanceTimersByTimeAsync(50) // shot 2 hangs + expect(shots).toBe(2) + + await r.stop() // shot 2 is still outstanding + hanging = false + await r.start({ name: 'driver' }) // shot 3 resolves, recording resumes + const started = r.bufferLength + await vi.advanceTimersByTimeAsync(150) + + // The latch has to clear with the timer, or the restarted loop drops every + // tick until the orphan from the previous recording settles. + expect(r.bufferLength).toBeGreaterThan(started) + await r.stop() + vi.useRealTimers() + }) + + it('discards a shot that outlived the loop it was issued from', async () => { + vi.useFakeTimers() + let release: ((value: string) => void) | undefined + class Orphan extends TestRecorder { + protected override takeScreenshot(): Promise { + this.shotsTaken++ + return this.shotsTaken === 1 + ? Promise.resolve('initial') + : new Promise((resolve) => { + release = resolve + }) + } + } + const r = new Orphan({ pollIntervalMs: 50 }) + await r.start({ name: 'driver' }) + await vi.advanceTimersByTimeAsync(50) // tick → its shot hangs + expect(r.bufferLength).toBe(1) + + await r.stop() + release?.('late-frame') + await vi.advanceTimersByTimeAsync(60) + + // The frame belongs to the recording that ended — appending it would put a + // post-stop screenshot into the export. + expect(r.bufferLength).toBe(1) + vi.useRealTimers() + }) + + it('releases the latch when a shot settles, so polling continues', async () => { + vi.useFakeTimers() + class Bumpy extends TestRecorder { + protected override async takeScreenshot(): Promise { + this.shotsTaken++ + if (this.shotsTaken === 2) { + await new Promise((resolve) => setTimeout(resolve, 300)) + } + return `f-${this.shotsTaken}` + } + } + const r = new Bumpy({ pollIntervalMs: 50 }) + await r.start({ name: 'driver' }) + const initial = r.bufferLength + await vi.advanceTimersByTimeAsync(50) // tick → slow shot starts + await vi.advanceTimersByTimeAsync(300) // slow shot settles, ticks resume + await vi.advanceTimersByTimeAsync(200) + expect(r.bufferLength).toBeGreaterThan(initial + 1) + await r.stop() + vi.useRealTimers() + }) +}) + describe('ScreencastRecorderBase — frames / setStartMarker / duration', () => { it('setStartMarker trims preceding frames from the public getter', async () => { class CdpFlavor extends ScreencastRecorderBase<{ name: string }> { diff --git a/packages/service/src/action-snapshot.ts b/packages/service/src/action-snapshot.ts index b0834a89..3fe11427 100644 --- a/packages/service/src/action-snapshot.ts +++ b/packages/service/src/action-snapshot.ts @@ -10,13 +10,11 @@ import { captureActionSnapshot as coreCapture, - mapCommandToAction, upsertRichestSnapshot } from '@wdio/devtools-core' import { sessionHasDocument, type ActionSnapshot } from '@wdio/devtools-shared' import { mobilePlatform } from './mobile.js' import { directProbes } from './direct-probes.js' -import { INTERNAL_COMMANDS } from './constants.js' import { wdioRunnerId } from './wdio-runner-id.js' function reviveScript(src: string): () => unknown { @@ -26,82 +24,68 @@ function reviveScript(src: string): () => unknown { return new Function(`return (${src})`) as () => unknown } +/** Bound on the end-of-test wait for a document the last action navigated to. */ +const FINAL_SETTLE_TIMEOUT_MS = 8000 +/** Time to let a paint land, so the final capture is not a transitional frame — + * measured on Appium, where a mid-paint screenshot runs 359-476 KB against a + * settled 1.87 MB. */ +const FINAL_SETTLE_PAUSE_MS = 250 + /** - * After a mapped action, wait for the resulting page to settle before the - * post-action screenshot. readyState alone is unreliable — right after a click - * the OLD document still reports 'complete'. beforeCommand tags the document; - * if the tag is gone the action navigated, so we wait for the NEW document to - * finish loading AND render content before the destination is screenshotted. + * Settle the page after the LAST action, before its capture. Every other + * capture is taken in `beforeCommand`, at a moment the driver is idle and the + * previous action's effect has had the test's own gap to land; the last action + * has no successor, so this is the one place a settle earns its cost. + * + * `navigated` says the drain immediately before this brought a document the + * session had not seen — the only condition under which `readyState` is worth + * asking about. Ungated it is unreliable: right after a click the OUTGOING + * document already reports 'complete', so a blind poll returns instantly and + * captures the page the test just left. Gated, the document it describes is the + * incoming one. Never throws. */ -export async function waitForActionResult( - browser: WebdriverIO.Browser -): Promise { - const navigated = await browser - .execute( - () => !(window as Window & { __wdioSnapMark?: boolean }).__wdioSnapMark - ) - .catch(() => true) - if (!navigated) { - return - } - await browser - .waitUntil( - async () => - (await browser - .execute( - () => - document.readyState === 'complete' && - !!document.body && - document.body.childElementCount > 0 - ) - .catch(() => false)) === true, - { timeout: 8000, interval: 150 } - ) - .catch(() => undefined) - // Headless renderers can return a blank shot right after load; let it paint. - await browser.pause(250).catch(() => undefined) -} - -/** Post-action capture: settle the resulting page, screenshot it, and push the - * snapshot stamped at the latest logged action. No-op for internal/non-mapped - * commands. Skipped by the caller outside trace mode. */ -export async function captureActionResult( +export async function settleAfterLastAction( browser: WebdriverIO.Browser, - command: string, - actionSnapshots: ActionSnapshot[], - stampTimestamp: () => number, + navigated: boolean, /** Appium context the session is in, so a hybrid app's webview takes the web * path. Undefined for every non-Appium session, which has no contexts. */ context?: string ): Promise { - if (!mapCommandToAction(command) || INTERNAL_COMMANDS.includes(command)) { - return - } - // Keyed on having a document, matching `#markDocument`, which writes the tag - // this reads — split, a session tags a document nothing settles on. - if (sessionHasDocument(browser.capabilities, context)) { - await waitForActionResult(browser) - } - // Stamped before the capture, not after: a snapshot probe can never enter - // commandsLog (beforeCommand requires an empty command stack), so the latest - // logged action is the same either way — and reading it up front keeps the - // stamp a capture input rather than a post-hoc mutation. - const snap = await captureActionSnapshot( - browser, - command, - stampTimestamp(), - context - ) - if (snap) { - upsertRichestSnapshot(actionSnapshots, snap) + // A test double or a driver without `pause`/`waitUntil` must not fail a + // capture that has nothing to do with it, so the whole settle is best-effort. + try { + if (!sessionHasDocument(browser.capabilities, context)) { + await browser.pause(FINAL_SETTLE_PAUSE_MS) + return + } + // Not navigated: the app has been at rest since the last action, so the + // test's own teardown is the gap that lets the paint land. Waiting costs + // every test for nothing. + if (!navigated) { + return + } + // Caught separately from the outer handler: a slow load that blows the + // timeout still leaves a page mid-paint, and that is exactly the frame the + // pause exists to avoid capturing. + await browser + .waitUntil( + async () => + (await browser + .execute(() => document.readyState === 'complete') + .catch(() => false)) === true, + { timeout: FINAL_SETTLE_TIMEOUT_MS, interval: 150 } + ) + .catch(() => undefined) + await browser.pause(FINAL_SETTLE_PAUSE_MS) + } catch { + // The capture is worth taking regardless of why the settle could not run. } } /** Capture a DOM snapshot for a synthesized action row (e.g. an `expect.*` * assertion) and push it stamped at the row's OWN timestamp — the trace * player's Snapshot tab claims it by timestamp the same way it claims a - * regular command's post-action snapshot (see FrameSnapshotIndex.claimAfter). - * Mirrors the tail of `captureActionResult` for a command with no page-settle. */ + * command's own snapshot (see FrameSnapshotIndex.claimAfter). */ export async function pushActionSnapshotAt( browser: WebdriverIO.Browser, command: string, diff --git a/packages/service/src/index.ts b/packages/service/src/index.ts index 5d7ef87b..7919af6c 100644 --- a/packages/service/src/index.ts +++ b/packages/service/src/index.ts @@ -5,6 +5,7 @@ import { beginInputDispatch, captureAndAttachScreenshot, errorMessage, + FINAL_SNAPSHOT_COMMAND, finalizeTraceExport, lastRenderedScreenshot, mapCommandToAction, @@ -30,14 +31,10 @@ import { import { resolveCallSourceFromFrame } from './call-source.js' import { TraceSliceTracker } from './trace-slices.js' import { - captureActionResult, - captureActionSnapshot + captureActionSnapshot, + settleAfterLastAction } from './action-snapshot.js' -import { - sessionHasDocument, - type ActionSnapshot, - type TestMetadataMap -} from '@wdio/devtools-shared' +import type { ActionSnapshot, TestMetadataMap } from '@wdio/devtools-shared' import { SevereServiceError } from 'webdriverio' import type { Services, Capabilities, Options, Reporters } from '@wdio/types' import type { WebDriverCommands } from '@wdio/protocols' @@ -61,7 +58,6 @@ import { PAGE_TRANSITION_COMMANDS } from './constants.js' import { inPageProbesDeadlock, isAppiumSession } from './mobile.js' -import { directProbes } from './direct-probes.js' import { resolveSessionMetadata } from './session-metadata.js' import { stampRunnerMetadata } from './wdio-runner-id.js' import { detectInvocationConfigPath } from './standalone.js' @@ -559,28 +555,75 @@ export default class DevToolsHookService implements Services.ServiceInstance { // otherwise never be captured before teardown. forceAnchor: the destination's // async initial anchor may not have run yet, so anchor it synchronously here. await this.#sessionCapturer.captureTrace(this.#browser, true) - const snap = await captureActionSnapshot( - this.#browser, - '__final__', - this.#lastActionTimestamp() - ) - if (snap) { - // The last action's post-capture shares this timestamp and resources are - // named by timestamp, so keep only the richer screenshot — a blank - // end-of-scenario frame must not clobber the action's real result. - upsertRichestSnapshot(this.#actionSnapshots, snap) + // Named after the action it captures, because that is what it is: every + // other row's result comes from the NEXT action's pre-capture, so the last + // action's has no successor and this is the only capture of it. A session + // that ran no action names it FINAL_SNAPSHOT_COMMAND, which the per-test + // screenshot reads as "post-teardown frame, do not use". + const lastAction = this.#lastAction() + // A session with no action has no timestamp of its own to key on, so its + // frame is recognised by the marker instead — otherwise `Date.now()` differs + // between the per-test finalize and `after()` and both capture. + const alreadyCaptured = lastAction + ? this.#actionSnapshots.some( + (snap) => snap.timestamp === lastAction.timestamp + ) + : this.#actionSnapshots.some( + (snap) => snap.command === FINAL_SNAPSHOT_COMMAND + ) + // `after()` finalizes once more at session end, for the standalone path that + // has no per-test hook. On a framework run the test that just ended has + // already recorded this slot, and the driver would return the same page a + // second time — capture only when it is still empty. + if (!alreadyCaptured) { + await settleAfterLastAction( + this.#browser, + this.#sessionCapturer.replacedDocumentInLastDrain, + this.#sessionCapturer.currentContext + ) + const snap = await captureActionSnapshot( + this.#browser, + lastAction?.command ?? FINAL_SNAPSHOT_COMMAND, + lastAction?.timestamp ?? Date.now(), + this.#sessionCapturer.currentContext + ) + if (snap) { + // Stamped at the last action's own timestamp, where an assertion row can + // have captured too, and resources are named by timestamp — keep only the + // richer screenshot so a blank end-of-scenario frame cannot clobber it. + upsertRichestSnapshot(this.#actionSnapshots, snap) + } } } - #lastActionTimestamp(): number { + /** A command a snapshot can be attributed to: mapped (so it has a row to + * render on) and not internal (several of those ARE mapped — getTitle, + * getUrl, execute — and a snapshot stamped at one would sit at a timestamp + * no row owns). Both the capture gate and `#lastAction` ask this. */ + #isActionCommand(command: string): boolean { + return ( + Boolean(mapCommandToAction(command)) && + !INTERNAL_COMMANDS.includes(command) + ) + } + + /** The last action a capture can be attributed to. Scans rather than tracks a + * pointer: the log is run-long and never reset per test, so the scan + * self-scopes, and a slot already filled at its own boundary converges on + * `alreadyCaptured`. */ + #lastAction(): { command: string; timestamp: number } | undefined { const commands = this.#sessionCapturer.commandsLog for (let i = commands.length - 1; i >= 0; i--) { const cmd = commands[i]! - if (mapCommandToAction(cmd.command)) { - return cmd.timestamp + if (this.#isActionCommand(cmd.command)) { + return cmd } } - return Date.now() + return undefined + } + + #lastActionTimestamp(): number { + return this.#lastAction()?.timestamp ?? Date.now() } private resetStack() { @@ -653,11 +696,16 @@ export default class DevToolsHookService implements Services.ServiceInstance { if (PAGE_TRANSITION_COMMANDS.includes(command)) { await this.#sessionCapturer.captureTrace(this.#browser) } - // Pre-action capture: state BEFORE this action executes. Stamped at the - // previous action's end time (or 0 for the first). Trace mode only. + // Pre-action capture: the state this action runs against, which is the state + // the previous action left behind. Taken HERE, before the command is issued, + // because that is the one moment the driver is guaranteed idle and the app + // at rest — a capture taken the instant a command returns catches whatever + // transition it started. Stamped at the previous action's end (or now, for + // the first, which makes it the initial frame). Trace mode only. // - // Not while Appium has a document to probe — see `inPageProbesDeadlock`, - // which carries the measurements. A native session is captured normally. + // Not while a mobile-web Appium session has a document to probe — the + // re-entrant probes can deadlock a serialising driver (#374). A native + // session is captured normally. if ( topLevelUserCommand && this.#options.mode === 'trace' && @@ -666,51 +714,30 @@ export default class DevToolsHookService implements Services.ServiceInstance { this.#browser, this.#sessionCapturer.currentContext ) && - mapCommandToAction(command) && - !INTERNAL_COMMANDS.includes(command) + this.#isActionCommand(command) ) { + // Stamped at the previous action's end so this capture IS that action's + // result — except across a test boundary, where that slot already holds + // its own finalize capture and a second frame at the same timestamp lets + // the richer-screenshot merge replace it (with a reloadSession between + // the tests, the row then replays the post-reload page). The first + // capture of a test stamps now instead, the same rule the session's first + // capture uses to become the initial frame. + const previousEnd = this.#lastActionTimestamp() const snap = await captureActionSnapshot( this.#browser, command, - this.#lastActionTimestamp(), + previousEnd >= this.#currentTestStartWallTime + ? previousEnd + : Date.now(), this.#sessionCapturer.currentContext ) if (snap) { upsertRichestSnapshot(this.#actionSnapshots, snap) } - // Tag the current document so the post-action capture can tell whether - // this action navigated (a new document drops the tag). - await this.#markDocument() } } - #markDocument(): Promise { - // Keyed on having a document: `waitForActionResult` reads this tag on the - // same condition, so the pair must not be split across the two predicates. - if ( - !this.#browser || - !sessionHasDocument( - this.#browser.capabilities, - this.#sessionCapturer.currentContext - ) - ) { - return Promise.resolve() - } - // Issued from inside beforeCommand, so it takes the direct path on a - // driver that serialises per session (#374). - const direct = directProbes(this.#browser) - if (direct) { - return direct - .runScript('window.__wdioSnapMark = true') - .catch(() => undefined) - } - return this.#browser - .execute(() => { - ;(window as Window & { __wdioSnapMark?: boolean }).__wdioSnapMark = true - }) - .catch(() => undefined) - } - async afterCommand( command: keyof WebDriverCommands, args: unknown[], @@ -754,23 +781,9 @@ export default class DevToolsHookService implements Services.ServiceInstance { this.#currentTestUid, this.#currentStepUid ) - // Paired with the pre-action capture above, and gated on the same - // question: this settles and screenshots from inside the command hook. - if ( - this.#options.mode === 'trace' && - !inPageProbesDeadlock( - this.#browser, - this.#sessionCapturer.currentContext - ) - ) { - await captureActionResult( - this.#browser, - command, - this.#actionSnapshots, - () => this.#lastActionTimestamp(), - this.#sessionCapturer.currentContext - ) - } else { + // Trace mode captures nothing here: the state this action produced is + // taken by the NEXT action's pre-capture, when the app has settled. + if (this.#options.mode !== 'trace') { await this.#drainAfterLiveCommand(command) } return captured @@ -815,6 +828,12 @@ export default class DevToolsHookService implements Services.ServiceInstance { return } + // The last action's result is captured by the NEXT action's pre-capture, so + // a session that ends without one — a standalone run has no per-test hook to + // finalize on — would lose it. A framework run has already finalized per + // test; there this only re-captures the same timestamp and merges. + await this.#finalizePerScenario() + // Stop and encode the screencast for the current session. await this.#screencast.finalize(this.#browser.sessionId) diff --git a/packages/service/src/session.ts b/packages/service/src/session.ts index 0e62666c..5138f0e8 100644 --- a/packages/service/src/session.ts +++ b/packages/service/src/session.ts @@ -31,7 +31,7 @@ import { loadInjectableScript, type CapturedPerformancePayload } from '@wdio/devtools-core' -import type { DevToolsMode } from '@wdio/devtools-shared' +import type { DevToolsMode, TraceMutation } from '@wdio/devtools-shared' import type { CommandLog } from './types.js' import { directProbes } from './direct-probes.js' @@ -50,6 +50,7 @@ export class SessionCapturer extends SessionCapturerBase { traceMode: DevToolsMode = 'live' #isScriptInjected = false + #replacedDocumentInLastDrain = false /** Session start wall time for trace event timestamps. */ readonly startWallTime = Date.now() /** Last find-element selector — carried forward to the next element command. */ @@ -181,7 +182,7 @@ export class SessionCapturer extends SessionCapturerBase { // can have: no DOM to replay, and the per-action snapshot is trace-only, so // skipping it left the player with nothing for any command and the device // pane falling back to desktop browser chrome. Trace mode is excluded - // because `captureActionResult` already screenshots the same command — two + // because the per-action pre-capture already screenshots this command — two // Appium round trips at ~1.2s each is the cost #351 exists to remove. A // mobile BROWSER session keeps the old behaviour throughout: it replays // from its mutation stream. @@ -422,11 +423,20 @@ export class SessionCapturer extends SessionCapturerBase { this.#isScriptInjected = false } + /** Whether the most recent `captureTrace` brought a document this session had + * not anchored before. The collector anchors once per document, so a new + * anchor means the page was replaced — the end-of-test settle reads this to + * know a navigation is still loading, rather than guessing from a clock. */ + get replacedDocumentInLastDrain(): boolean { + return this.#replacedDocumentInLastDrain + } + /** Drain the current page's buffered trace data (mutations/console/network) * into the capturer. Public so the plugin can flush BEFORE a navigating * command, capturing the outgoing page's field edits (value/checked * mutations fire no page transition) before its collector is discarded. */ async captureTrace(browser: WebdriverIO.Browser, forceAnchor = false) { + this.#replacedDocumentInLastDrain = false // A native app has no document to drain, so the collector probe, the // recovery injection and the url read are all round trips that can only // fail. Guarded here rather than at each call site, because two of the four @@ -472,6 +482,24 @@ export class SessionCapturer extends SessionCapturerBase { if (!payload) { return } + // `captureCurrentDom` is the only producer of a mutation carrying a url, + // and it anchors each document once — so one in this batch is a document + // the session had not seen. Shape-checked like `processTracePayload` + // does: this is page-side data, and a throw here would discard the whole + // payload's console and network streams with it. + const mutations = (payload as { mutations?: unknown }).mutations + if ( + Array.isArray(mutations) && + mutations.some( + (mutation) => + typeof mutation === 'object' && + mutation !== null && + 'url' in mutation && + (mutation as TraceMutation).url !== undefined + ) + ) { + this.#replacedDocumentInLastDrain = true + } this.processTracePayload(payload as Record) } catch (err) { log.error(`Failed to capture trace: ${errorMessage(err)}`) diff --git a/packages/service/tests/action-snapshot.test.ts b/packages/service/tests/action-snapshot.test.ts index 6c38c9b2..634cd4e4 100644 --- a/packages/service/tests/action-snapshot.test.ts +++ b/packages/service/tests/action-snapshot.test.ts @@ -1,9 +1,6 @@ import { describe, it, expect, vi } from 'vitest' import type { ActionSnapshot } from '@wdio/devtools-shared' -import { - captureActionResult, - pushActionSnapshotAt -} from '../src/action-snapshot.js' +import { pushActionSnapshotAt } from '../src/action-snapshot.js' const mockBrowser = () => ({ @@ -109,52 +106,3 @@ describe('an Appium session driving a browser', () => { expect(browser.getUrl).not.toHaveBeenCalled() }) }) - -/** - * The settle waits on the `__wdioSnapMark` tag that `#markDocument` writes, and - * both key on having a document — split across the two predicates, a session - * tags a document nothing ever settles on, and its post-action screenshot comes - * from the page it navigated away from. - */ -describe('the post-action settle', () => { - const settleable = (flags: Record) => - Object.assign(mockBrowser(), flags, { - execute: vi.fn().mockResolvedValue(true), - waitUntil: vi.fn().mockResolvedValue(undefined), - pause: vi.fn().mockResolvedValue(undefined) - }) as unknown as WebdriverIO.Browser - - it('runs for an Appium session driving a browser', async () => { - const browser = settleable({ - isMobile: false, - isAndroid: true, - capabilities: { platformName: 'Android', browserName: 'Chrome' } - }) - - await captureActionResult(browser, 'click', [], () => 1) - - // The mark probe is the settle's first act, so its body identifies it. - const bodies = vi - .mocked(browser.execute) - .mock.calls.map(([fn]) => String(fn)) - expect(bodies.some((body) => body.includes('__wdioSnapMark'))).toBe(true) - }) - - it('does not for a native app, which has no document to settle', async () => { - const browser = settleable({ - isMobile: true, - isAndroid: true, - capabilities: { - platformName: 'Android', - 'appium:app': '/app.apk' - } - }) - - await captureActionResult(browser, 'click', [], () => 1) - - const bodies = vi - .mocked(browser.execute) - .mock.calls.map(([fn]) => String(fn)) - expect(bodies.some((body) => body.includes('__wdioSnapMark'))).toBe(false) - }) -}) diff --git a/packages/service/tests/assertion-rows.test.ts b/packages/service/tests/assertion-rows.test.ts index 66890162..382d5c70 100644 --- a/packages/service/tests/assertion-rows.test.ts +++ b/packages/service/tests/assertion-rows.test.ts @@ -38,7 +38,7 @@ const pushActionSnapshotAt = vi.hoisted(() => vi.mock('../src/action-snapshot.js', () => ({ pushActionSnapshotAt, captureActionSnapshot: vi.fn().mockResolvedValue(null), - captureActionResult: vi.fn().mockResolvedValue(undefined) + settleAfterLastAction: vi.fn().mockResolvedValue(undefined) })) import DevToolsHookService from '../src/index.js' diff --git a/packages/service/tests/session.test.ts b/packages/service/tests/session.test.ts index 7289d910..20e52e18 100644 --- a/packages/service/tests/session.test.ts +++ b/packages/service/tests/session.test.ts @@ -103,8 +103,9 @@ describe('SessionCapturer', () => { expect(capturer.commandsLog[0].screenshot).toBe('native-shot') }) - // `captureActionResult` already screenshots the same command in trace mode; - // two Appium round trips at ~1.2s each is the cost #351 exists to remove. + // The per-action pre-capture already screenshots the same command in trace + // mode; two Appium round trips at ~1.2s each is the cost #351 exists to + // remove. it('skips one for a native session in trace mode', async () => { const capturer = new SessionCapturer() capturer.traceMode = 'trace' diff --git a/packages/service/tests/trace-action-capture.test.ts b/packages/service/tests/trace-action-capture.test.ts new file mode 100644 index 00000000..e05799f2 --- /dev/null +++ b/packages/service/tests/trace-action-capture.test.ts @@ -0,0 +1,397 @@ +import { describe, it, expect, vi, beforeEach } from 'vitest' +import type * as DevtoolsCore from '@wdio/devtools-core' +import { captureActionSnapshot } from '@wdio/devtools-core' +import DevToolsHookService from '../src/index.js' + +// One user-spec frame, so `beforeCommand` reads every command as top-level. +vi.mock('stack-trace', () => ({ + parse: () => [ + { + getFileName: () => '/test/specs/fake.spec.ts', + getLineNumber: () => 1, + getColumnNumber: () => 1 + } + ] +})) + +/** + * The command has to be in the log by the time `afterCommand` returns: + * `#lastActionTimestamp()` reads it to stamp the NEXT action's capture, and that + * stamp is what makes an action's result the following action's "before". + */ +const commandsLog: { command: string; timestamp: number }[] = [] +let clock = 0 +const capturer = { + afterCommand: vi.fn(async (_browser: unknown, command: string) => { + commandsLog.push({ command, timestamp: ++clock }) + }), + sendUpstream: vi.fn(), + mergeMetadata: vi.fn(), + captureTrace: vi.fn().mockResolvedValue(undefined), + noteResolvedSelector: vi.fn(), + resetLastSelector: vi.fn(), + resetRetryTracker: vi.fn(), + captureSource: vi.fn(), + captureAssertCommand: vi.fn(), + cleanup: vi.fn(), + commandsLog, + sources: new Map(), + mutations: [], + traceLogs: [], + consoleLogs: [], + networkRequests: [], + isReportingUpstream: false, + metadata: {}, + setBrowser: vi.fn(), + /** Set by a test to stand in for the drain having brought a document the + * session had not anchored before. */ + replacedDocumentInLastDrain: false +} + +vi.mock('../src/session.js', () => ({ + SessionCapturer: vi.fn(function () { + return capturer + }) +})) + +vi.mock('../src/screencast.js', () => ({ + ScreencastRecorder: vi.fn(function () { + return { + start: vi.fn().mockResolvedValue(undefined), + stop: vi.fn().mockResolvedValue(undefined), + setStartMarker: vi.fn(), + frames: [] + } + }) +})) + +vi.mock('@wdio/devtools-core', async (importOriginal) => { + const actual = await importOriginal() + return { + ...actual, + captureActionSnapshot: vi.fn(actual.captureActionSnapshot), + encodeToVideo: vi.fn().mockResolvedValue(undefined) + } +}) + +vi.mock('node:fs/promises', () => ({ + default: { writeFile: vi.fn().mockResolvedValue(undefined) } +})) + +/** A native Appium session: no `browserName` anywhere in the capabilities, so + * `isNativeAppSession` is true and the capture takes the screenshot + + * page-source path — the one an Appium run pays for. */ +const nativeBrowser = () => { + const capabilities = { platformName: 'Android', deviceName: 'emulator-5554' } + return { + isBidi: false, + isMobile: true, + isAndroid: true, + sessionId: 'native-session', + capabilities, + options: { capabilities }, + addCommand: vi.fn(), + on: vi.fn(), + emit: vi.fn(), + pause: vi.fn(async () => undefined), + execute: vi.fn(async () => []), + takeScreenshot: vi.fn(async () => 'SHOT'), + getPageSource: vi.fn( + async () => '' + ), + getWindowSize: vi.fn(async () => ({ width: 1080, height: 2424 })) + } as unknown as WebdriverIO.Browser +} + +/** A plain web session: a browser in the capabilities, so `isNativeAppSession` + * is false and the capture takes the page-script path. */ +const webBrowser = () => { + const capabilities = { browserName: 'chrome', platformName: 'linux' } + return { + isBidi: true, + isMobile: false, + sessionId: 'web-session', + capabilities, + options: { capabilities }, + addCommand: vi.fn(), + on: vi.fn(), + emit: vi.fn(), + pause: vi.fn(async () => undefined), + // Invokes the predicate, so the probe it runs is observable — WDIO's real + // `waitUntil` polls it. + waitUntil: vi.fn(async (predicate: () => Promise) => { + await predicate() + }), + execute: vi.fn(async () => []), + takeScreenshot: vi.fn(async () => 'SHOT'), + getUrl: vi.fn(async () => 'http://example.com/'), + getTitle: vi.fn(async () => 'Example') + } as unknown as WebdriverIO.Browser +} + +/** The service's own wrapper funnels into core's single-object signature. */ +const stampedAt = (call: number): number | undefined => + vi.mocked(captureActionSnapshot).mock.calls[call]?.[0]?.timestamp +const namedAt = (call: number): string | undefined => + vi.mocked(captureActionSnapshot).mock.calls[call]?.[0]?.command + +describe('trace mode: one capture per action, taken before it', () => { + beforeEach(() => { + vi.clearAllMocks() + commandsLog.length = 0 + clock = 0 + capturer.replacedDocumentInLastDrain = false + }) + + it('captures in beforeCommand and not again after the command', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + + vi.mocked(browser.takeScreenshot).mockClear() + vi.mocked(browser.getPageSource!).mockClear() + + await service.beforeCommand('click' as never, []) + expect(browser.takeScreenshot).toHaveBeenCalledTimes(1) + + await service.afterCommand('click' as never, [], undefined) + // The state this action produced belongs to the NEXT action's capture, taken + // once the app has settled. Capturing here instead is what makes a trace + // blurry: the screen is still moving when the command returns. + expect(browser.takeScreenshot).toHaveBeenCalledTimes(1) + }) + + it('costs one capture per action across a sequence', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + + vi.mocked(browser.takeScreenshot).mockClear() + vi.mocked(browser.getPageSource!).mockClear() + vi.mocked(captureActionSnapshot).mockClear() + + for (const command of ['click', 'setValue', 'click']) { + await service.beforeCommand(command as never, []) + await service.afterCommand(command as never, [], undefined) + } + + expect(vi.mocked(captureActionSnapshot)).toHaveBeenCalledTimes(3) + expect(browser.takeScreenshot).toHaveBeenCalledTimes(3) + expect(browser.getPageSource).toHaveBeenCalledTimes(3) + }) + + it('stamps each capture at the previous action end', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + vi.mocked(captureActionSnapshot).mockClear() + + await service.beforeCommand('click' as never, []) + await service.afterCommand('click' as never, [], undefined) + await service.beforeCommand('setValue' as never, []) + await service.afterCommand('setValue' as never, [], undefined) + + // The first action runs against a state nothing has recorded yet, so it + // takes the capture now (it becomes the trace's initial frame). The second + // takes the state the first produced — the first action's result IS the + // second action's before, which is the whole design. + expect(stampedAt(0)).toBeGreaterThan(0) + expect(stampedAt(1)).toBe(commandsLog[0]!.timestamp) + }) + + it('captures the final state when the session ends', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + + vi.mocked(captureActionSnapshot).mockClear() + await service.beforeCommand('click' as never, []) + await service.afterCommand('click' as never, [], undefined) + await service.after() + + // A standalone run has no per-test hook, so the last action's result would + // never be taken: the next action's pre-capture is what supplies it + // everywhere else. + expect(stampedAt(1)).toBe(commandsLog[0]!.timestamp) + expect(stampedAt(0)).toBeGreaterThan(0) + + // A framework run reaches this finalize twice — once per test and once from + // `after()`. The slot is recorded by then, so the second pass must not pay + // another screenshot and page-source round trip for it. + await service.after() + expect(vi.mocked(captureActionSnapshot)).toHaveBeenCalledTimes(2) + }) + + it('captures the no-action frame once per session', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + + vi.mocked(captureActionSnapshot).mockClear() + await service.after() + await service.after() + + // A session that ran no action has no timestamp to key on, so the marker + // carries the "already captured" answer — otherwise each finalize takes the + // same frame again under a fresh `Date.now()`. + expect(vi.mocked(captureActionSnapshot)).toHaveBeenCalledTimes(1) + expect(namedAt(0)).toBe('__final__') + }) + + it('settles the driver once, only for the final capture', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + + vi.mocked(browser.pause).mockClear() + for (const command of ['click', 'setValue']) { + await service.beforeCommand(command as never, []) + await service.afterCommand(command as never, [], undefined) + } + // Per-action captures take the page at a moment the driver is already idle — + // paying a settle for each of them is the cost this design removed. + expect(browser.pause).not.toHaveBeenCalled() + + await service.after() + // The last action has no successor, so its capture is the one that needs it. + expect(browser.pause).toHaveBeenCalledTimes(1) + }) + + it('takes the final capture at the last action, past an internal command', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + await service.beforeCommand('click' as never, []) + await service.afterCommand('click' as never, [], undefined) + // A read the capture gates exclude, and the last thing the test did. It is + // mapped, so counting it would stamp the final capture at a timestamp no + // visible row owns — and skipping it entirely would lose the click's result. + await service.beforeCommand('getTitle' as never, []) + await service.afterCommand('getTitle' as never, [], 'title') + + vi.mocked(captureActionSnapshot).mockClear() + await service.after() + + expect(namedAt(0)).toBe('click') + expect(stampedAt(0)).toBe(commandsLog[0]!.timestamp) + }) + + it('does not merge the next test first capture into the previous test slot', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + const first = { file: '/spec/a.ts', title: 'first' } + service.beforeTest(first as never) + await service.beforeCommand('click' as never, []) + await service.afterCommand('click' as never, [], undefined) + await service.afterTest(first as never, {} as never, {} as never) + + const lastOfFirst = commandsLog[0]!.timestamp + vi.mocked(captureActionSnapshot).mockClear() + + await new Promise((resolve) => setTimeout(resolve, 5)) + const secondTestStart = Date.now() + service.beforeTest({ file: '/spec/a.ts', title: 'second' } as never) + await service.beforeCommand('click' as never, []) + + // The previous test's last action already has its own capture, taken by that + // test's finalize. Stamping this test's initial frame at the same timestamp + // lets the richer-screenshot merge replace it — under a reloadSession the + // row then shows the post-reload page instead of that test's last state. + expect(stampedAt(0)).not.toBe(lastOfFirst) + expect(stampedAt(0)).toBeGreaterThanOrEqual(secondTestStart) + }) + + it('still lets the paint land when the wait for a load times out', async () => { + const browser = webBrowser() + capturer.replacedDocumentInLastDrain = true + vi.mocked(browser.waitUntil).mockRejectedValueOnce(new Error('timeout')) + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + await service.beforeCommand('click' as never, []) + await service.afterCommand('click' as never, [], undefined) + + vi.mocked(browser.pause).mockClear() + await service.after() + + // A page slow enough to blow the timeout is still mid-paint, so it is the + // one that most needs the pause — the wait's rejection must not skip it. + expect(browser.pause).toHaveBeenCalledTimes(1) + }) + + it('names the final capture after the action it captures', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + await service.beforeCommand('click' as never, []) + await service.afterCommand('click' as never, [], undefined) + + vi.mocked(captureActionSnapshot).mockClear() + await service.after() + + // Not `__final__`: this capture IS the last action's result, and the + // per-test screenshot reader (`lastRenderedScreenshot`) skips that marker, + // so naming it `__final__` made the Allure screenshot show the page from + // BEFORE the last action — the one a failure is inspected for. + expect(namedAt(0)).toBe('click') + }) + + it('never settles the driver', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + + vi.mocked(browser.pause).mockClear() + vi.mocked(browser.execute).mockClear() + for (const command of ['click', 'setValue', 'getText']) { + await service.beforeCommand(command as never, []) + await service.afterCommand(command as never, [], undefined) + } + + // No pause, no readyState poll, no document tag: the capture happens at a + // moment the driver is already idle, so there is nothing to wait for. + expect(browser.pause).not.toHaveBeenCalled() + expect(browser.execute).not.toHaveBeenCalled() + }) + + it('waits for a document the last action navigated to, and only that', async () => { + const browser = webBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + await service.beforeCommand('click' as never, []) + await service.afterCommand('click' as never, [], undefined) + + vi.mocked(browser.pause).mockClear() + vi.mocked(browser.waitUntil).mockClear() + vi.mocked(browser.execute).mockClear() + await service.after() + + // No new document in the final drain: the app has been at rest since the + // last action, so its paint already landed. Waiting here is the cost this + // design removes from every test. + expect(browser.waitUntil).not.toHaveBeenCalled() + expect(browser.pause).not.toHaveBeenCalled() + + capturer.replacedDocumentInLastDrain = true + await service.beforeCommand('click' as never, []) + await service.afterCommand('click' as never, [], undefined) + vi.mocked(browser.pause).mockClear() + vi.mocked(browser.waitUntil).mockClear() + vi.mocked(browser.execute).mockClear() + await service.after() + + // A document the session had not seen IS loading, so readyState is the + // right question — it describes the incoming document, not the outgoing one + // that still reports 'complete'. + expect(browser.waitUntil).toHaveBeenCalledTimes(1) + const bodies = vi + .mocked(browser.execute) + .mock.calls.map(([fn]) => String(fn)) + expect(bodies.some((body) => body.includes('readyState'))).toBe(true) + // The old poll also required a non-empty body, which made a legitimately + // blank destination a guaranteed timeout rather than a settled page. + expect(bodies.some((body) => body.includes('childElementCount'))).toBe( + false + ) + }) +}) diff --git a/packages/service/tests/trace-granularity.test.ts b/packages/service/tests/trace-granularity.test.ts index f74e4089..3d51f228 100644 --- a/packages/service/tests/trace-granularity.test.ts +++ b/packages/service/tests/trace-granularity.test.ts @@ -59,10 +59,13 @@ vi.mock('../src/session.js', () => ({ }) })) +// `pushActionSnapshotAt` is imported by the assertion tracker, which this file +// reaches through the service — leave it out and a test that drives a failing +// matcher calls undefined. vi.mock('../src/action-snapshot.js', () => ({ captureActionSnapshot: vi.fn().mockResolvedValue(null), - captureActionResult: vi.fn().mockResolvedValue(undefined), - waitForActionResult: vi.fn().mockResolvedValue(undefined) + pushActionSnapshotAt: vi.fn().mockResolvedValue(undefined), + settleAfterLastAction: vi.fn().mockResolvedValue(undefined) })) vi.mock('@wdio/devtools-core', async (importOriginal) => { diff --git a/packages/service/tests/trace-metadata.test.ts b/packages/service/tests/trace-metadata.test.ts index 22607ff5..e76bf228 100644 --- a/packages/service/tests/trace-metadata.test.ts +++ b/packages/service/tests/trace-metadata.test.ts @@ -42,8 +42,8 @@ vi.mock('../src/session.js', () => ({ // Keep the after* hooks from touching a real browser/CDP. vi.mock('../src/action-snapshot.js', () => ({ captureActionSnapshot: vi.fn().mockResolvedValue(null), - captureActionResult: vi.fn().mockResolvedValue(undefined), - waitForActionResult: vi.fn().mockResolvedValue(undefined) + pushActionSnapshotAt: vi.fn().mockResolvedValue(undefined), + settleAfterLastAction: vi.fn().mockResolvedValue(undefined) })) vi.mock('@wdio/devtools-core', async (importOriginal) => { diff --git a/packages/shared/src/types.ts b/packages/shared/src/types.ts index 7fc79a35..936f1861 100644 --- a/packages/shared/src/types.ts +++ b/packages/shared/src/types.ts @@ -507,7 +507,15 @@ export function isMutationsTruncationMarker( * downstream trace.zip exporter (Phase 4). `screenshot` is base64-encoded JPEG. */ export interface ActionSnapshot { + /** The key every reader joins on. A capture is stamped, once the exporter + * has run, with the action whose RESULT it is — which is why `command` + * below is not that action's name. */ timestamp: number + /** A label, not a key: the action the capture was taken for, which mid-run is + * the one it PRECEDES (the capture is its state before it ran), while the + * timestamp names the action it follows. No reader may select on it — the + * one value with meaning is core's `FINAL_SNAPSHOT_COMMAND`, which marks a + * frame carrying no result to show. */ command: string url?: string title?: string From 25a087ee7295b09dc08b4151ee40b9f3228b6a09 Mon Sep 17 00:00:00 2001 From: Vince Graics Date: Sun, 20 Sep 2026 15:47:34 +0200 Subject: [PATCH 2/6] fix(core): serialise screencast start/stop --- packages/core/src/screencast.ts | 57 +++++++++---- packages/core/tests/screencast.test.ts | 113 +++++++++++++++++++++++-- 2 files changed, 146 insertions(+), 24 deletions(-) diff --git a/packages/core/src/screencast.ts b/packages/core/src/screencast.ts index 44afc2e1..e79c1094 100644 --- a/packages/core/src/screencast.ts +++ b/packages/core/src/screencast.ts @@ -31,6 +31,7 @@ export abstract class ScreencastRecorderBase { #cdpActive = false #startIndex = 0 #startMarkerSet = false + #queue: Promise = Promise.resolve() constructor(options: ScreencastOptions = {}) { this.options = { ...SCREENCAST_DEFAULTS, ...options } @@ -43,20 +44,46 @@ export abstract class ScreencastRecorderBase { * recording is simply skipped. */ async start(driver: TDriver): Promise { + return this.#enqueue(() => this.#startInner(driver)) + } + + /** + * Stop recording and release resources. Safe to call even if start() was + * never called or failed. + */ + async stop(): Promise { + return this.#enqueue(() => this.#stopInner()) + } + + /** + * Serialise start and stop against each other, so a stop always runs against + * a start that has finished arming. Unserialised, a stop landing mid-handshake + * observes nothing armed and returns, leaving what the handshake armed with no + * owner — and a second start in that window overwrites the session the first + * is about to claim, because both CDP overrides hold theirs in a single field. + * + * The cost is that stop() now waits on an in-flight handshake. Only selenium + * caps its own (the first-frame race); the service's CDP handshake and the + * polling path's first screenshot have no ceiling, so a driver that wedges in + * one of those wedges stop() — where the old stop() returned early and leaked + * the session instead. Ceiling those awaits, or race this at the call site. + */ + #enqueue(op: () => Promise): Promise { + const run = this.#queue.then(op, op) + this.#queue = run.then( + () => undefined, + () => undefined + ) + return run + } + + async #startInner(driver: TDriver): Promise { if (this.#isRecording) { return } - // Claimed before the first await, because a stop() arriving during any of - // them has nothing else to invalidate: nothing is armed, and #isRecording is - // still false, so without this the loop would be armed after the caller - // stopped it. A native session's first screenshot runs ~1.2 s. const generation = ++this.#pollGeneration this.driver = driver - const cdpOk = await this.tryStartCdp() - if (generation !== this.#pollGeneration) { - return - } - if (cdpOk) { + if (await this.tryStartCdp()) { this.#cdpActive = true this.#isRecording = true return @@ -64,14 +91,10 @@ export abstract class ScreencastRecorderBase { await this.#startPolling(generation) } - /** - * Stop recording and release resources. Safe to call even if start() was - * never called or failed. - */ - async stop(): Promise { - // Bumped before the early return: a stop() that lands while start() is still - // awaiting its first screenshot finds nothing armed and #isRecording still - // false, so returning above would let start() arm the loop afterwards. + async #stopInner(): Promise { + // Bumped before the early return: a shot issued by a loop this stop is + // ending must not land in the next recording, and the latch it holds is not + // the successor's to clear. this.#pollGeneration++ if (!this.#isRecording) { return diff --git a/packages/core/tests/screencast.test.ts b/packages/core/tests/screencast.test.ts index b58eb207..26c70864 100644 --- a/packages/core/tests/screencast.test.ts +++ b/packages/core/tests/screencast.test.ts @@ -54,12 +54,18 @@ describe('ScreencastRecorderBase — polling path', () => { expect(throwR.isRecording).toBe(false) }) - it('does not arm a loop that a stop() during the first shot has cancelled', async () => { + it('tears down a loop that a stop() during the first shot has cancelled', async () => { vi.useFakeTimers() let release: ((value: string) => void) | undefined class SlowFirst extends TestRecorder { + shotIssued!: () => void + readonly firstShot = new Promise((resolve) => { + this.shotIssued = resolve + }) + protected override takeScreenshot(): Promise { this.shotsTaken++ + this.shotIssued() return new Promise((resolve) => { release = resolve }) @@ -67,16 +73,19 @@ describe('ScreencastRecorderBase — polling path', () => { } const r = new SlowFirst({ pollIntervalMs: 50 }) const starting = r.start({ name: 'driver' }) - // Nothing is armed yet and `isRecording` is still false, so this stop() has - // no timer to clear — without the generation it would return as a no-op and - // the interval would arm underneath it. - await r.stop() + await r.firstShot + // Queued behind the handshake, so the stop now runs against a start that + // finished arming: what it has to clear is a live timer, not a pending one. + const stopping = r.stop() release?.('late-shot') - await starting + await Promise.all([starting, stopping]) await vi.advanceTimersByTimeAsync(500) expect(r.isRecording).toBe(false) - expect(r.bufferLength).toBe(0) + // The shot was already issued when the stop took effect, so it is the one + // frame the recording holds; the interval it armed must add no more. + expect(r.bufferLength).toBe(1) + expect(r.shotsTaken).toBe(1) vi.useRealTimers() }) @@ -342,6 +351,96 @@ describe('ScreencastRecorderBase — CDP override path', () => { }) }) +describe('ScreencastRecorderBase — start/stop serialisation', () => { + class CdpRaceRecorder extends ScreencastRecorderBase<{ name: string }> { + /** Session ids in arm order, and the one currently held — a single field, + * exactly as both CDP overrides keep theirs. */ + armed: string[] = [] + stopped: string[] = [] + session = 'none' + // Arm numbers whose handshake stays pending until release() — lets a test + // park start() mid-handshake while stop()/start() land on top of it. + holdCalls = new Set() + private gates = new Map void>() + private entered = new Set() + private enteredWaiters = new Map void>() + + protected override async takeScreenshot(): Promise { + return null + } + + protected override tryStartCdp(): Promise { + const call = this.armed.length + 1 + const id = `s${call}` + this.armed.push(id) + this.session = id + this.entered.add(call) + this.enteredWaiters.get(call)?.() + if (this.holdCalls.has(call)) { + return new Promise((resolve) => { + this.gates.set(call, resolve) + }) + } + return Promise.resolve(true) + } + + protected override async tryStopCdp(): Promise { + if (this.session === 'none') { + return + } + this.stopped.push(this.session) + this.session = 'none' + } + + /** Resolves once arm `call` has been entered, gated or not. */ + armEntered(call: number): Promise { + if (this.entered.has(call)) { + return Promise.resolve() + } + return new Promise((resolve) => { + this.enteredWaiters.set(call, resolve) + }) + } + + release(call: number): void { + this.gates.get(call)?.(true) + } + } + + it('stop() during the CDP handshake still tears the session down', async () => { + const r = new CdpRaceRecorder() + r.holdCalls.add(1) + const starting = r.start({ name: 'driver' }) + await r.armEntered(1) + // Not awaited here: the queue parks it behind the handshake, and the whole + // point is that it must run once that handshake has finished arming. + const stopping = r.stop() + r.release(1) + await Promise.all([starting, stopping]) + expect(r.stopped).toEqual(['s1']) + expect(r.isRecording).toBe(false) + }) + + it('a start landing mid-handshake never has its session torn down', async () => { + const r = new CdpRaceRecorder() + r.holdCalls = new Set([1, 2]) + const first = r.start({ name: 'driver' }) + const stopping = r.stop() + const second = r.start({ name: 'driver' }) + await r.armEntered(1) + r.release(1) + await r.armEntered(2) + r.release(2) + await Promise.all([first, stopping, second]) + // s1 is the session the stop was for; s2 belongs to the start that followed + // it and is still recording. Unserialised, the first handshake's stale path + // stopped s2 and left a dead stream flagged as recording. + expect(r.stopped).toEqual(['s1']) + expect(r.session).toBe('s2') + expect(r.isRecording).toBe(true) + }) +}) + describe('ScreencastRecorderBase — buffer cap / decimation', () => { class PushRecorder extends ScreencastRecorderBase<{ name: string }> { protected override async takeScreenshot() { From 953fe121abe1edc41ed22b6383f2a31ba79742f1 Mon Sep 17 00:00:00 2001 From: Vince Graics Date: Sun, 20 Sep 2026 16:01:23 +0200 Subject: [PATCH 3/6] chore(changeset): introduce 2 changesets for the fixes --- .changeset/one-capture-per-action.md | 9 +++++++++ .changeset/serialise-screencast-start-and-stop.md | 10 ++++++++++ CLAUDE.md | 1 + 3 files changed, 20 insertions(+) create mode 100644 .changeset/one-capture-per-action.md create mode 100644 .changeset/serialise-screencast-start-and-stop.md diff --git a/.changeset/one-capture-per-action.md b/.changeset/one-capture-per-action.md new file mode 100644 index 00000000..08bbd2ac --- /dev/null +++ b/.changeset/one-capture-per-action.md @@ -0,0 +1,9 @@ +--- +"@wdio/devtools-backend": patch +"@wdio/devtools-core": patch +"@wdio/devtools-service": patch +--- + +Take one DOM capture per action again. Trace mode had grown a second, eager post-action capture beside the pre-action one, with a `readyState` poll and a 250 ms pause on top to hide the fact that the eager one lands while the screen is still moving — so every action paid two captures, and on a native Appium session each capture is two serial round trips. Measured on the native example spec: 15 screenshots and 15 page-source reads against 8 and 8, and a 14.0–14.7 s test against 11.4 s, with the captured frames equivalent. + +The pre-action capture is the one that was right: taken before the command is issued, it is the moment the driver is guaranteed idle, so an action's result is the next action's "before". Only the last action has no successor to hand its result to, so a settle survives in exactly that one place, and it is gated rather than timed — no navigation, no wait. The eager capture, the poll that patched it and the document tag it was built on are deleted. Two related fixes ride along: a row with no capture of its own now replays the latest state at or before it rather than the nearest in absolute distance, which could hand it its successor's; and the screencast poll keeps at most one screenshot outstanding, so it cannot queue ahead of the test's own commands on a serialised driver. diff --git a/.changeset/serialise-screencast-start-and-stop.md b/.changeset/serialise-screencast-start-and-stop.md new file mode 100644 index 00000000..6947943a --- /dev/null +++ b/.changeset/serialise-screencast-start-and-stop.md @@ -0,0 +1,10 @@ +--- +"@wdio/devtools-core": patch +"@wdio/devtools-service": patch +"@wdio/selenium-devtools": patch +"@wdio/nightwatch-devtools": patch +--- + +Stop a screencast session outliving the recording it was armed for. A `stop()` arriving while the CDP handshake was still in flight returned early — the recording flag it checks is only set once the handshake finishes — so the session and its frame listener stayed live after teardown and kept pushing frames into the buffer the next recording reuses. `start()` and `stop()` are now serialised, so a stop always runs against a start that has finished arming and tears down what that start armed. + +The visible consequence of the fix: `stop()` now waits for an in-flight handshake rather than returning immediately. Only Selenium caps its own; the service's CDP handshake and the polling path's first screenshot do not, so a driver that wedges in one of those now wedges `stop()` as well. diff --git a/CLAUDE.md b/CLAUDE.md index 09511648..34a687e8 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -338,6 +338,7 @@ Documented divergences from the conventions above. They exist today as debt to b - **One capture per action means two driver round trips per action, and the platform decides which half is expensive.** Measured on Appium 3.7.0 / UiAutomator2 (emulator-5554, Android API 37, 1080×2424): `GET /screenshot` 1.18–2.22 s (steady ~1.20 s) at 1.86 MB, `GET /source` (page-source XML) 0.09–0.53 s at 40 KB, `window/rect` 0.015 s — the screenshot dominates by ~10× on Android. **iOS is unmeasured**; the issue claims the split inverts there, and the native example (`examples/wdio/mocha/wdio.native.conf.ts`) is what makes it measurable. Measured per action: two captures 2.41 s against one capture 1.19 s; end-to-end on the native example 19.1 s against 12.4 s, with live mode (no per-action capture) at 5.9 s. That is the case for the `beforeCommand` capture, and the reason an eager post-action capture is not worth re-adding: it cost a second capture per action and existed only to be patched by a `readyState` poll that could not tell a document that had not navigated yet from one that was loading. - A filmstrip poll against a native session stacks requests: `setInterval` never waits for its async handler, a native screenshot takes ~1.2 s against the 200 ms default, and a serialised driver serves that queue ahead of the test's own commands — measured, a **15 ms command took 4.5–7.8 s**. `ScreencastRecorderBase`'s `#pollInFlight` latch bounds it to one outstanding shot, and `#pollGeneration` stops a shot orphaned by `stop()` from appending into the next recording or clearing its successor's latch. +- **`start()` and `stop()` are serialised against each other, because unserialised neither owns what it arms.** A `stop()` landing mid-handshake returned at its `#isRecording` guard — still false, the handshake not having finished — so it never reached its own CDP teardown, and the `start()` it interrupted then returned on the generation mismatch without stopping what it had armed: the session and its frame listener stayed live after teardown, pushing frames into the buffer the next recording reuses. The obvious repair — stopping the session on that mismatch path — is wrong, and it is the shape to keep out: it guards a field both CDP overrides write at handshake **start** (`#cdpSession` / `#cdp`) with a flag they set only at handshake **end** (`#cdpActive`), so a start arriving in that window is indistinguishable from no start at all and the stale path tears down the *newer* recording's session instead. Overlapping starts are the adapters' normal mode rather than a corner: Selenium's `driverPatcher` documents the second test's body racing an in-flight `screencast.start()`, and Nightwatch's session rotation is fire-and-forget from a command hook. Queued, a stop always runs against a start that has finished arming and owns what it armed, which makes the mismatch branch unreachable and deleted — the tick-phase generation checks in `#startPolling` are **not**, since a shot orphaned by a stop still lands afterwards. Two consequences: `stop()` now waits on an in-flight handshake, and only Selenium caps its own (its first-frame race) — the service's CDP handshake and the polling path's first screenshot have no ceiling, so a driver that wedges in one of those wedges `stop()` where it previously returned early and leaked. And a stop landing during a polling session's first screenshot now records that shot before tearing the loop down, where it previously cancelled the start outright; the interval is still never left armed underneath the stop. - Residual: **a polling matcher fires one capture per poll** — each poll is a top-level mapped read — so "one capture per action" undercounts a real suite. Pre-existing in `d924a02`, unmeasured on a device, and the likeliest next lever. - The next test's first pre-capture used to be stamped at the previous test's last-action timestamp — the log it scans is run-long, so a test boundary was invisible to it. That slot already holds the previous test's finalize capture, and the richer-screenshot merge could replace it: with a `reloadSession` between the tests the row replayed the post-reload page. The capture now stamps `Date.now()` when the scanned timestamp predates `#currentTestStartWallTime` (0 without per-test hooks, so the standalone path is unchanged) — the same rule that makes a session's first capture its initial frame. Per-test slices were never affected: `flushTest` runs inside `afterTest`, before the next test's commands. From 1629f1fa051fcf899e6e5754d4c6ae60d4cc1599 Mon Sep 17 00:00:00 2001 From: Vince Graics Date: Tue, 22 Sep 2026 14:30:47 +0200 Subject: [PATCH 4/6] fix(screencast): resolve CDP startup's teardown block --- .../serialise-screencast-start-and-stop.md | 4 +- packages/core/src/screencast.ts | 50 ++++++++--- packages/core/tests/screencast.test.ts | 29 ++++++ packages/selenium-devtools/src/screencast.ts | 38 ++++++-- packages/service/src/screencast.ts | 88 ++++++++++++++----- packages/service/tests/screencast.test.ts | 54 ++++++++++++ 6 files changed, 222 insertions(+), 41 deletions(-) diff --git a/.changeset/serialise-screencast-start-and-stop.md b/.changeset/serialise-screencast-start-and-stop.md index 6947943a..9e9e93f8 100644 --- a/.changeset/serialise-screencast-start-and-stop.md +++ b/.changeset/serialise-screencast-start-and-stop.md @@ -7,4 +7,6 @@ Stop a screencast session outliving the recording it was armed for. A `stop()` arriving while the CDP handshake was still in flight returned early — the recording flag it checks is only set once the handshake finishes — so the session and its frame listener stayed live after teardown and kept pushing frames into the buffer the next recording reuses. `start()` and `stop()` are now serialised, so a stop always runs against a start that has finished arming and tears down what that start armed. -The visible consequence of the fix: `stop()` now waits for an in-flight handshake rather than returning immediately. Only Selenium caps its own; the service's CDP handshake and the polling path's first screenshot do not, so a driver that wedges in one of those now wedges `stop()` as well. +The visible consequence of the fix: `stop()` now waits for an in-flight handshake rather than returning immediately — so every driver primitive that handshake awaits is ceilinged. An unbounded one (the service's `getPuppeteer()`/`pages()`/`createCDPSession()`/`Page.startScreencast`, the polling path's first screenshot, Selenium's `createCDPConnection`) would have parked teardown behind a driver that never answers, turning a leaked session into a hung test run. On the ceiling the handshake gives up and the recorder falls back to polling, or reports the screencast unavailable when polling was what wedged. + +Nothing is claimed until the handshake has answered, which is what keeps the ceiling safe: a `Page.startScreencast` that times out leaves no session, no frame listener and no stream behind for teardown to find. The same ceiling covers the stop-side `Page.stopScreencast` send, so a wedged stop cannot block the next recording either. diff --git a/packages/core/src/screencast.ts b/packages/core/src/screencast.ts index e79c1094..cf439c81 100644 --- a/packages/core/src/screencast.ts +++ b/packages/core/src/screencast.ts @@ -1,6 +1,14 @@ import type { ScreencastFrame, ScreencastOptions } from '@wdio/devtools-shared' import { SCREENCAST_DEFAULTS } from '@wdio/devtools-shared' import { isInputDispatchInFlight } from './input-dispatch.js' +import { withTimeout } from './with-timeout.js' + +/** Ceiling for one awaited driver primitive in the screencast start/stop + * handshake. The queue serialises start against stop, so a primitive that + * never settles parks teardown behind it for good. */ +export const SCREENCAST_HANDSHAKE_TIMEOUT_MS = 5000 + +const FIRST_SHOT_TIMEOUT = Symbol('first-shot-timeout') /** * Shared screencast scaffolding consumed by every adapter (service, selenium, @@ -62,11 +70,9 @@ export abstract class ScreencastRecorderBase { * owner — and a second start in that window overwrites the session the first * is about to claim, because both CDP overrides hold theirs in a single field. * - * The cost is that stop() now waits on an in-flight handshake. Only selenium - * caps its own (the first-frame race); the service's CDP handshake and the - * polling path's first screenshot have no ceiling, so a driver that wedges in - * one of those wedges stop() — where the old stop() returned early and leaked - * the session instead. Ceiling those awaits, or race this at the call site. + * Every awaited driver primitive in start/stop is ceilinged at + * SCREENCAST_HANDSHAKE_TIMEOUT_MS, so a queued op always settles and a driver + * that wedges cannot park teardown behind it. */ #enqueue(op: () => Promise): Promise { const run = this.#queue.then(op, op) @@ -249,14 +255,38 @@ export abstract class ScreencastRecorderBase { // ─── Polling implementation ───────────────────────────────────────────── + /** + * The first shot of a polling session, under the handshake ceiling — it runs + * on the start/stop queue, so a driver that never answers it would park + * teardown behind the handshake for good. Returns null when there is nothing + * to record: a stale generation, a null shot, or a timeout. + */ + async #takeFirstShot(generation: number): Promise { + const first = await withTimeout( + this.takeScreenshot(), + SCREENCAST_HANDSHAKE_TIMEOUT_MS, + FIRST_SHOT_TIMEOUT + ) + if (generation !== this.#pollGeneration) { + return null + } + if (typeof first !== 'string') { + this.onUnavailable( + new Error( + first === null + ? 'first screenshot returned null' + : 'first screenshot timed out' + ) + ) + return null + } + return first + } + async #startPolling(generation: number): Promise { try { - const first = await this.takeScreenshot() - if (generation !== this.#pollGeneration) { - return - } + const first = await this.#takeFirstShot(generation) if (first === null) { - this.onUnavailable(new Error('first screenshot returned null')) return } this.#appendFrame({ data: first, timestamp: Date.now() }) diff --git a/packages/core/tests/screencast.test.ts b/packages/core/tests/screencast.test.ts index 26c70864..3b25cb01 100644 --- a/packages/core/tests/screencast.test.ts +++ b/packages/core/tests/screencast.test.ts @@ -441,6 +441,35 @@ describe('ScreencastRecorderBase — start/stop serialisation', () => { }) }) +describe('ScreencastRecorderBase — handshake ceiling', () => { + it('a first shot that never settles still lets start() and a queued stop() resolve', async () => { + vi.useFakeTimers() + try { + class HungFirst extends TestRecorder { + unavailable: unknown[] = [] + protected override takeScreenshot(): Promise { + return new Promise(() => {}) + } + protected override onUnavailable(err: unknown): void { + this.unavailable.push(err) + } + } + const r = new HungFirst({ pollIntervalMs: 50 }) + const starting = r.start({ name: 'driver' }) + const stopping = r.stop() + await vi.advanceTimersByTimeAsync(5000) + await Promise.all([starting, stopping]) + expect(r.isRecording).toBe(false) + expect(r.unavailable).toHaveLength(1) + expect((r.unavailable[0] as Error).message).toBe( + 'first screenshot timed out' + ) + } finally { + vi.useRealTimers() + } + }) +}) + describe('ScreencastRecorderBase — buffer cap / decimation', () => { class PushRecorder extends ScreencastRecorderBase<{ name: string }> { protected override async takeScreenshot() { diff --git a/packages/selenium-devtools/src/screencast.ts b/packages/selenium-devtools/src/screencast.ts index 7198b920..bfca534a 100644 --- a/packages/selenium-devtools/src/screencast.ts +++ b/packages/selenium-devtools/src/screencast.ts @@ -1,5 +1,10 @@ import logger from '@wdio/logger' -import { ScreencastRecorderBase, errorMessage } from '@wdio/devtools-core' +import { + ScreencastRecorderBase, + SCREENCAST_HANDSHAKE_TIMEOUT_MS, + errorMessage, + withTimeout +} from '@wdio/devtools-core' import { BLANK_FRAME_THRESHOLD_BYTES } from './constants.js' import { getDriverOriginals } from './driverPatcher.js' import type { SeleniumDriverLike } from './types.js' @@ -115,18 +120,33 @@ export class ScreencastRecorder extends ScreencastRecorderBase { + /** + * Open the CDP connection under the handshake ceiling. The base class + * serialises start against stop, so a connection that never answers would + * park teardown behind this handshake for good. + */ + async #openCdpConnection(): Promise { const driver = this.driver if (!driver || typeof driver.createCDPConnection !== 'function') { - return false + return undefined } + // selenium-webdriver types createCDPConnection() as Promise; the + // runtime shape is stable across patch releases and captured by + // SeleniumCdpConnection above. + return withTimeout( + driver.createCDPConnection('page') as Promise, + SCREENCAST_HANDSHAKE_TIMEOUT_MS, + undefined + ) + } + + protected override async tryStartCdp(): Promise { try { - // selenium-webdriver types createCDPConnection() as Promise; - // the runtime shape is stable across patch releases and captured by - // SeleniumCdpConnection above. - const cdp = (await driver.createCDPConnection( - 'page' - )) as SeleniumCdpConnection + const cdp = await this.#openCdpConnection() + if (!cdp) { + log.warn('CDP connection unavailable — falling back to polling') + return false + } this.#cdp = cdp const ws = cdp._wsConnection if (!ws || typeof ws.on !== 'function') { diff --git a/packages/service/src/screencast.ts b/packages/service/src/screencast.ts index 528a37b6..1d529b4a 100644 --- a/packages/service/src/screencast.ts +++ b/packages/service/src/screencast.ts @@ -1,8 +1,15 @@ import logger from '@wdio/logger' -import { ScreencastRecorderBase, errorMessage } from '@wdio/devtools-core' +import { + ScreencastRecorderBase, + errorMessage, + withTimeout, + SCREENCAST_HANDSHAKE_TIMEOUT_MS +} from '@wdio/devtools-core' const log = logger('@wdio/devtools-service:ScreencastRecorder') +const CDP_TIMEOUT = Symbol('cdp-timeout') + interface CdpSessionLike { send(method: string, params?: Record): Promise on(event: string, handler: (event: unknown) => void | Promise): void @@ -47,34 +54,69 @@ export class ScreencastRecorder extends ScreencastRecorderBase { + // getPuppeteer is augmented onto WebdriverIO.Browser in types.ts; the + // returned Puppeteer object isn't typed by WDIO, so narrow it locally. + const raw = await withTimeout( + Promise.resolve(this.driver?.getPuppeteer?.()), + SCREENCAST_HANDSHAKE_TIMEOUT_MS, + undefined + ) + if (!raw) { + return undefined + } + const pages = await withTimeout( + (raw as PuppeteerLike).pages(), + SCREENCAST_HANDSHAKE_TIMEOUT_MS, + [] + ) + if (!pages.length) { + return undefined + } + + const session = await withTimeout( + pages[0].createCDPSession(), + SCREENCAST_HANDSHAKE_TIMEOUT_MS, + undefined + ) + if (!session) { + return undefined + } + + const started = await withTimeout( + session.send('Page.startScreencast', { + format: this.options.captureFormat, + quality: this.options.quality, + maxWidth: this.options.maxWidth, + maxHeight: this.options.maxHeight + }), + SCREENCAST_HANDSHAKE_TIMEOUT_MS, + CDP_TIMEOUT + ) + if (started === CDP_TIMEOUT) { + log.warn('Screencast: CDP handshake timed out — falling back to polling') + return undefined + } + return session + } + protected override async tryStartCdp(): Promise { if (!this.driver) { return false } try { - // getPuppeteer is augmented onto WebdriverIO.Browser in types.ts; the - // returned Puppeteer object isn't typed by WDIO, so narrow it locally. - const raw = await this.driver.getPuppeteer?.() - if (!raw) { + const session = await this.#openCdpSession() + if (!session) { return false } - const puppeteer = raw as PuppeteerLike - const pages = await puppeteer.pages() - if (!pages.length) { - return false - } - - const page = pages[0] - const session = await page.createCDPSession() this.#cdpSession = session - await session.send('Page.startScreencast', { - format: this.options.captureFormat, - quality: this.options.quality, - maxWidth: this.options.maxWidth, - maxHeight: this.options.maxHeight - }) - session.on('Page.screencastFrame', async (rawEvent) => { const event = rawEvent as { data: string @@ -106,7 +148,11 @@ export class ScreencastRecorder extends ScreencastRecorderBase { expect(recorder.duration).toBe(0) await expect(recorder.stop()).resolves.toBeUndefined() }) + + it('hung getPuppeteer resolves and a queued stop resolves', async () => { + vi.useFakeTimers() + try { + const browser = { + getPuppeteer: vi.fn(() => new Promise(() => {})), + takeScreenshot: vi.fn().mockRejectedValue(new Error('no screenshots')) + } as any + const recorder = new ScreencastRecorder() + const starting = recorder.start(browser) + const stopping = recorder.stop() + await vi.advanceTimersByTimeAsync(5000) + await Promise.all([starting, stopping]) + expect(browser.getPuppeteer).toHaveBeenCalled() + expect(recorder.isRecording).toBe(false) + expect(recorder.frames).toEqual([]) + } finally { + vi.useRealTimers() + } + }) + + it('hung startScreencast send arms nothing and queued stop resolves', async () => { + vi.useFakeTimers() + try { + const cdpSession = { + send: vi.fn(() => new Promise(() => {})), + on: vi.fn() + } + const browser = { + getPuppeteer: vi.fn().mockResolvedValue({ + pages: vi + .fn() + .mockResolvedValue([ + { createCDPSession: vi.fn().mockResolvedValue(cdpSession) } + ]) + }), + takeScreenshot: vi.fn().mockRejectedValue(new Error('no screenshots')) + } as any + const recorder = new ScreencastRecorder() + const starting = recorder.start(browser) + const stopping = recorder.stop() + await vi.advanceTimersByTimeAsync(5000) + await Promise.all([starting, stopping]) + expect(recorder.isRecording).toBe(false) + expect(cdpSession.send).toHaveBeenCalledWith( + 'Page.startScreencast', + expect.anything() + ) + expect(cdpSession.on).not.toHaveBeenCalled() + expect(recorder.frames).toEqual([]) + } finally { + vi.useRealTimers() + } + }) }) From 1fb78c42b527c4080a00ec76eb30beea98e7d02e Mon Sep 17 00:00:00 2001 From: Vince Graics Date: Tue, 22 Sep 2026 16:27:26 +0200 Subject: [PATCH 5/6] fix: harden the screencast handshake and the final capture - every driver primitive the handshake awaits is ceilinged at SCREENCAST_HANDSHAKE_TIMEOUT_MS, so a wedged driver falls back to polling instead of parking teardown - The final capture's alreadyCaptured check tracks the slot it captured instead of scanning by timestamp - Selenium's CDP ceiling gets its regression tests --- .../direct-probes-for-a-serialising-driver.md | 2 +- .changeset/follow-the-runtime-context.md | 2 +- .changeset/live-native-run-is-visible.md | 2 +- .../no-page-drain-on-a-native-session.md | 2 +- .../serialise-screencast-start-and-stop.md | 4 +- CLAUDE.md | 6 +- packages/core/src/screencast.ts | 2 +- .../tests/screencast.test.ts | 65 +++++++++++++++++++ packages/service/src/index.ts | 32 ++++++--- packages/service/src/screencast.ts | 17 +++++ packages/service/tests/screencast.test.ts | 36 +++++++++- .../tests/trace-action-capture.test.ts | 37 +++++++++++ 12 files changed, 186 insertions(+), 21 deletions(-) create mode 100644 packages/selenium-devtools/tests/screencast.test.ts diff --git a/.changeset/direct-probes-for-a-serialising-driver.md b/.changeset/direct-probes-for-a-serialising-driver.md index 1bdbb88d..944dbb49 100644 --- a/.changeset/direct-probes-for-a-serialising-driver.md +++ b/.changeset/direct-probes-for-a-serialising-driver.md @@ -3,7 +3,7 @@ "@wdio/nightwatch-devtools": patch --- -Stop the WDIO service deadlocking a mobile-web Appium session. `beforeCommand` issues its probes — the collector drain, the per-action snapshot's two scripts plus `url`/`title`, and the `__wdioSnapMark` tag — from inside the hook wrapping the command it is observing. Desktop chromedriver tolerates that re-entrancy; Appium serialises per session, so each probe enqueued behind the command it was meant to observe and neither resolved. Measured on an emulator: a two-command mobile-web spec passes in 1.6 s without the service and took 6 m 13 s of timeouts with it, every command at the WDIO timeout, with Chrome still on its new-tab page. +Stop the WDIO service deadlocking a mobile-web Appium session. `beforeCommand` issues its probes — the collector drain and the per-action snapshot's two scripts plus `url`/`title` — from inside the hook wrapping the command it is observing. Desktop chromedriver tolerates that re-entrancy; Appium serialises per session, so each probe enqueued behind the command it was meant to observe and neither resolved. Measured on an emulator: a two-command mobile-web spec passes in 1.6 s without the service and took 6 m 13 s of timeouts with it, every command at the WDIO timeout, with Chrome still on its new-tab page. The probes now go straight to the driver's HTTP endpoint for a session whose driver serialises, which is the only escape that does not change the ordering guarantee the pre-action snapshot depends on — the alternative, not awaiting in the hook, trades "state BEFORE this action executes" for every adapter and platform. diff --git a/.changeset/follow-the-runtime-context.md b/.changeset/follow-the-runtime-context.md index 838ae2d6..d498724b 100644 --- a/.changeset/follow-the-runtime-context.md +++ b/.changeset/follow-the-runtime-context.md @@ -5,7 +5,7 @@ Capture a hybrid app's webview half as a page, and frame a mobile capture as a device in the trace player as well as live. -**Following the context.** Document availability was answered from the startup capabilities and never revisited, so a session that switched into a webview was still treated as native: the collector injection, the DOM drain and the `__wdioSnapMark` tag stayed skipped, and its per-action snapshot read a real HTML document through the page-source XML reader. `sessionHasDocument(capabilities, context)` in shared is now the question a capture guard asks; `isNativeAppSession` remains the capability-level answer for what genuinely cannot change. Anything that is not Appium's `NATIVE_APP` counts as a webview, because the `WEBVIEW_` prefix is a convention and a driver naming its webview otherwise would have its capture skipped. Following it costs no round trip: `switchContext` carries the context it moves to in its own arguments, and a switch that failed is ignored. +**Following the context.** Document availability was answered from the startup capabilities and never revisited, so a session that switched into a webview was still treated as native: the collector injection, the DOM drain and the `__wdioSnapMark` tag (since removed — trace mode now takes one capture per action) stayed skipped, and its per-action snapshot read a real HTML document through the page-source XML reader. `sessionHasDocument(capabilities, context)` in shared is now the question a capture guard asks; `isNativeAppSession` remains the capability-level answer for what genuinely cannot change. Anything that is not Appium's `NATIVE_APP` counts as a webview, because the `WEBVIEW_` prefix is a convention and a driver naming its webview otherwise would have its capture skipped. Following it costs no round trip: `switchContext` carries the context it moves to in its own arguments, and a switch that failed is ignored. Verified on a real hybrid app (Appium's ApiDemos on an Android emulator): the webview action is exported with a page snapshot — `[Page: I am a page title — file:///android_asset/html/index.html]`, a heading, a link and a working locator — where the native actions on either side stay `[android] hierarchy FrameLayout…`. diff --git a/.changeset/live-native-run-is-visible.md b/.changeset/live-native-run-is-visible.md index 5ba4b0a0..2848ee28 100644 --- a/.changeset/live-native-run-is-visible.md +++ b/.changeset/live-native-run-is-visible.md @@ -9,6 +9,6 @@ Make a live native mobile run visible on the dashboard. Three separate gaps left Drop reporting is re-entrancy guarded, because the fix uncovered a second trap: `patchConsole` forwards console output upstream, so an adapter's drop handler that logs re-enters `sendUpstream`, drops again and recurses until the stack blows — surfacing as `Maximum call stack size exceeded` raised inside the user's own spec, pointing nowhere near the capturer. -**A native command carried no image.** The per-command screenshot was skipped for every Appium session. A native session has no DOM to replay and no per-action snapshot outside trace mode, so the player had nothing to show for any command and the device pane fell back to desktop browser chrome. Native sessions now take one in **live mode only** — trace mode already screenshots the same command through `captureActionResult`, and two Appium round trips at ~1.2 s each is the cost #351 exists to remove. A mobile *browser* session is unchanged: it replays from its mutation stream. +**A native command carried no image.** The per-command screenshot was skipped for every Appium session. A native session has no DOM to replay and no per-action snapshot outside trace mode, so the player had nothing to show for any command and the device pane fell back to desktop browser chrome. Native sessions now take one in **live mode only** — trace mode already screenshots the same command through its pre-action capture, and two Appium round trips at ~1.2 s each is the cost #351 exists to remove. A mobile *browser* session is unchanged: it replays from its mutation stream. **The capture had nowhere sensible to sit.** The trace player puts the dock beside the capture, which works when the whole window is the trace. A live dashboard has already spent its left edge on the suite tree, so a third column squeezed the dock into an unreadable strip and the tab row overflowed under the capture. Live mode now stacks the action list and the dock in one column beside a full-height capture, with both drag handles working and the collapse reversible. diff --git a/.changeset/no-page-drain-on-a-native-session.md b/.changeset/no-page-drain-on-a-native-session.md index 1aa0ccf8..08125a7a 100644 --- a/.changeset/no-page-drain-on-a-native-session.md +++ b/.changeset/no-page-drain-on-a-native-session.md @@ -11,7 +11,7 @@ It also had to be a **narrower** check than the one the service had. The existin Four page-side call sites move to the narrower predicate, and three of them were wrong for a mobile browser session before this change rather than because of it: - the drain itself, plus the drain-and-performance-read after a page-transition command. Its recovery injection is the only collector such a session ever gets, since the BiDi preload is skipped for every Appium session — so gating it on being mobile would have left it with no DOM capture at all. -- the `__wdioSnapMark` document tag and the post-action settle that reads it. These have to move together: split across the two predicates, a session tags a document nothing settles on, and its post-action screenshot comes from the page it navigated away from. +- the `__wdioSnapMark` document tag and the post-action settle that read it (both since removed — trace mode now takes one capture per action and settles only after the last one, via `settleAfterLastAction`). They had to move together at the time: split across the two predicates, a session tagged a document nothing settled on, and its post-action screenshot came from the page it navigated away from. - the per-action snapshot strategy, which fed a chromedriver session's HTML through the page-source XML parser and produced a snapshot with no elements, no a11y tree, no url and no title. - the viewport read. Documented as metadata-only, but the player sizes the DOM-replay iframe from it, so it is load-bearing wherever there is DOM to replay — and the driver window it was reading includes browser chrome and carries a hardcoded scale of 1. diff --git a/.changeset/serialise-screencast-start-and-stop.md b/.changeset/serialise-screencast-start-and-stop.md index 9e9e93f8..bc981c57 100644 --- a/.changeset/serialise-screencast-start-and-stop.md +++ b/.changeset/serialise-screencast-start-and-stop.md @@ -5,8 +5,8 @@ "@wdio/nightwatch-devtools": patch --- -Stop a screencast session outliving the recording it was armed for. A `stop()` arriving while the CDP handshake was still in flight returned early — the recording flag it checks is only set once the handshake finishes — so the session and its frame listener stayed live after teardown and kept pushing frames into the buffer the next recording reuses. `start()` and `stop()` are now serialised, so a stop always runs against a start that has finished arming and tears down what that start armed. +Stop a screencast session outliving the recording it was armed for. A `stop()` arriving while the CDP handshake was still in flight returned early — the recording flag it checks is only set once the handshake finishes — so the session, its frame listener and the browser-side screencast stream stayed live after teardown (the late frames themselves were moot: every adapter builds a fresh recorder per session). `start()` and `stop()` are now serialised, so a stop always runs against a start that has finished arming and tears down what that start armed. -The visible consequence of the fix: `stop()` now waits for an in-flight handshake rather than returning immediately — so every driver primitive that handshake awaits is ceilinged. An unbounded one (the service's `getPuppeteer()`/`pages()`/`createCDPSession()`/`Page.startScreencast`, the polling path's first screenshot, Selenium's `createCDPConnection`) would have parked teardown behind a driver that never answers, turning a leaked session into a hung test run. On the ceiling the handshake gives up and the recorder falls back to polling, or reports the screencast unavailable when polling was what wedged. +The visible consequence of the fix: `stop()` now waits for an in-flight handshake rather than returning immediately — so every driver primitive that handshake awaits is ceilinged. An unbounded one (the service's `getPuppeteer()`/`pages()`/`createCDPSession()`/`Page.startScreencast` and the `session.detach()` its timeout path takes, the polling path's first screenshot, Selenium's `createCDPConnection`) would have parked teardown behind a driver that never answers, turning a leaked session into a hung test run. On the ceiling the handshake gives up and the recorder falls back to polling, or reports the screencast unavailable when polling was what wedged. Nothing is claimed until the handshake has answered, which is what keeps the ceiling safe: a `Page.startScreencast` that times out leaves no session, no frame listener and no stream behind for teardown to find. The same ceiling covers the stop-side `Page.stopScreencast` send, so a wedged stop cannot block the next recording either. diff --git a/CLAUDE.md b/CLAUDE.md index 34a687e8..5efab78d 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -337,8 +337,8 @@ Documented divergences from the conventions above. They exist today as debt to b ### What a per-action trace capture costs - **One capture per action means two driver round trips per action, and the platform decides which half is expensive.** Measured on Appium 3.7.0 / UiAutomator2 (emulator-5554, Android API 37, 1080×2424): `GET /screenshot` 1.18–2.22 s (steady ~1.20 s) at 1.86 MB, `GET /source` (page-source XML) 0.09–0.53 s at 40 KB, `window/rect` 0.015 s — the screenshot dominates by ~10× on Android. **iOS is unmeasured**; the issue claims the split inverts there, and the native example (`examples/wdio/mocha/wdio.native.conf.ts`) is what makes it measurable. Measured per action: two captures 2.41 s against one capture 1.19 s; end-to-end on the native example 19.1 s against 12.4 s, with live mode (no per-action capture) at 5.9 s. That is the case for the `beforeCommand` capture, and the reason an eager post-action capture is not worth re-adding: it cost a second capture per action and existed only to be patched by a `readyState` poll that could not tell a document that had not navigated yet from one that was loading. -- A filmstrip poll against a native session stacks requests: `setInterval` never waits for its async handler, a native screenshot takes ~1.2 s against the 200 ms default, and a serialised driver serves that queue ahead of the test's own commands — measured, a **15 ms command took 4.5–7.8 s**. `ScreencastRecorderBase`'s `#pollInFlight` latch bounds it to one outstanding shot, and `#pollGeneration` stops a shot orphaned by `stop()` from appending into the next recording or clearing its successor's latch. -- **`start()` and `stop()` are serialised against each other, because unserialised neither owns what it arms.** A `stop()` landing mid-handshake returned at its `#isRecording` guard — still false, the handshake not having finished — so it never reached its own CDP teardown, and the `start()` it interrupted then returned on the generation mismatch without stopping what it had armed: the session and its frame listener stayed live after teardown, pushing frames into the buffer the next recording reuses. The obvious repair — stopping the session on that mismatch path — is wrong, and it is the shape to keep out: it guards a field both CDP overrides write at handshake **start** (`#cdpSession` / `#cdp`) with a flag they set only at handshake **end** (`#cdpActive`), so a start arriving in that window is indistinguishable from no start at all and the stale path tears down the *newer* recording's session instead. Overlapping starts are the adapters' normal mode rather than a corner: Selenium's `driverPatcher` documents the second test's body racing an in-flight `screencast.start()`, and Nightwatch's session rotation is fire-and-forget from a command hook. Queued, a stop always runs against a start that has finished arming and owns what it armed, which makes the mismatch branch unreachable and deleted — the tick-phase generation checks in `#startPolling` are **not**, since a shot orphaned by a stop still lands afterwards. Two consequences: `stop()` now waits on an in-flight handshake, and only Selenium caps its own (its first-frame race) — the service's CDP handshake and the polling path's first screenshot have no ceiling, so a driver that wedges in one of those wedges `stop()` where it previously returned early and leaked. And a stop landing during a polling session's first screenshot now records that shot before tearing the loop down, where it previously cancelled the start outright; the interval is still never left armed underneath the stop. +- A filmstrip poll against a native session stacks requests: `setInterval` never waits for its async handler, a native screenshot takes ~1.2 s against the 200 ms default, and a serialised driver serves that queue ahead of the test's own commands — measured, a **15 ms command took 4.5–7.8 s**. `ScreencastRecorderBase`'s `#pollInFlight` latch bounds it to one outstanding shot, and `#pollGeneration` stops a shot orphaned by `stop()` from appending after the stop or clearing its successor's latch. +- **`start()` and `stop()` are serialised against each other, because unserialised neither owns what it arms.** A `stop()` landing mid-handshake returned at its `#isRecording` guard — still false, the handshake not having finished — so it never reached its own CDP teardown, and the `start()` it interrupted then returned on the generation mismatch without stopping what it had armed: the session and its frame listener stayed live after teardown. The frames themselves were moot — every adapter builds a fresh recorder per session (`screencast-lifecycle.ts` does so even across `reloadSession`), so the leaked session and its browser-side stream were the damage, not buffer pollution. The obvious repair — stopping the session on that mismatch path — is wrong, and it is the shape to keep out: it guards a field both CDP overrides write at handshake **start** (`#cdpSession` / `#cdp`) with a flag they set only at handshake **end** (`#cdpActive`), so a start arriving in that window is indistinguishable from no start at all and the stale path tears down the *newer* recording's session instead. Overlapping starts are the adapters' normal mode rather than a corner: Selenium's `driverPatcher` documents the second test's body racing an in-flight `screencast.start()`, and Nightwatch's session rotation is fire-and-forget from a command hook. Queued, a stop always runs against a start that has finished arming and owns what it armed, which makes the mismatch branch unreachable and deleted — the tick-phase generation checks in `#startPolling` are **not**, since a shot orphaned by a stop still lands afterwards. Two consequences: `stop()` now waits on an in-flight handshake, and every awaited driver primitive in that handshake is ceilinged at `SCREENCAST_HANDSHAKE_TIMEOUT_MS` (the service's `getPuppeteer()`/`pages()`/`createCDPSession()`/`Page.startScreencast` and the stop-side `Page.stopScreencast`, Selenium's `createCDPConnection`, the polling path's first screenshot) — a driver that wedges gives up after the ceiling, falls back to polling, or reports the screencast unavailable when polling was what wedged. Nothing is claimed until the handshake has answered, so a timed-out start leaves nothing armed. And a stop landing during a polling session's first screenshot now records that shot before tearing the loop down, where it previously cancelled the start outright; the interval is still never left armed underneath the stop. - Residual: **a polling matcher fires one capture per poll** — each poll is a top-level mapped read — so "one capture per action" undercounts a real suite. Pre-existing in `d924a02`, unmeasured on a device, and the likeliest next lever. - The next test's first pre-capture used to be stamped at the previous test's last-action timestamp — the log it scans is run-long, so a test boundary was invisible to it. That slot already holds the previous test's finalize capture, and the richer-screenshot merge could replace it: with a `reloadSession` between the tests the row replayed the post-reload page. The capture now stamps `Date.now()` when the scanned timestamp predates `#currentTestStartWallTime` (0 without per-test hooks, so the standalone path is unchanged) — the same rule that makes a session's first capture its initial frame. Per-test slices were never affected: `flushTest` runs inside `afterTest`, before the next test's commands. @@ -346,7 +346,7 @@ Documented divergences from the conventions above. They exist today as debt to b Most entries below don't trigger the `max-lines` lint rule after `skipBlankLines`/`skipComments`; they're documented because their raw line count is over 500, and the next substantive change to any of them should still look for an extraction opportunity. The service plugin is the exception — it's now over the *logic*-line cap. -- `packages/service/src/index.ts` (608 logic / 903 raw, was 729/1043). Still over the 500-logic cap. The screencast and trace-slice seams are extracted: `screencast-lifecycle.ts` (139 logic / 217 raw) owns every read and write of recorder frames — start, reload, finalize, the cross-`reloadSession` filmstrip buffer and the per-test video slice, two invariants that were previously produced and consumed 400 lines apart — and `trace-slices.ts` (58 logic / 87 raw) owns boundary recording plus the eager per-test flush beside the flush I/O it already held. The only remaining cluster large enough to close the gap is the command-hook family (`beforeCommand`/`afterCommand`/`#commandStack`/`#drainAfterLiveCommand`, ~120 logic lines); `before()` is still over the function cap at 62 logic lines. +- `packages/service/src/index.ts` (619 logic / 928 raw, was 729/1043). Still over the 500-logic cap. The screencast and trace-slice seams are extracted: `screencast-lifecycle.ts` (139 logic / 217 raw) owns every read and write of recorder frames — start, reload, finalize, the cross-`reloadSession` filmstrip buffer and the per-test video slice, two invariants that were previously produced and consumed 400 lines apart — and `trace-slices.ts` (58 logic / 87 raw) owns boundary recording plus the eager per-test flush beside the flush I/O it already held. The only remaining cluster large enough to close the gap is the command-hook family (`beforeCommand`/`afterCommand`/`#commandStack`/`#drainAfterLiveCommand`, ~120 logic lines); `before()` is still over the function cap at 51 logic lines. - `packages/nightwatch-devtools/src/index.ts` (783 raw / 676 logic). Cucumber/test/run-lifecycle, session-init, event-hub and now the screencast seam (`plugin-screencast.ts`, 105 raw / 60 logic) are extracted; the remainder is the `PluginInternals` accessor bag plus per-method delegators plus the factory. The bag is deliberately declarative — accept as-is. - `packages/selenium-devtools/src/index.ts` (~644 raw, down from ~758 — the dead `scriptInjected` accessor pair and setter are gone). Session/test-lifecycle **and** the per-test-artifact seam are now extracted: the sink cache + input snapshot + produce/attach flow live in `selenium-devtools/src/test-artifacts.ts` as `SeleniumTestArtifacts` (mirrors Nightwatch's twin — a typed input bag threading the Allure sink + flushed-trace promise), and the plugin keeps only a thin bag-building delegator. Remainder is the `PluginInternals` accessor bag plus onCommand/onDriverCreated wiring. Still over the 500 **raw** soft cap (under the logic-line cap after `skipBlankLines`/`skipComments`); the accessor bag / command wiring is the next extraction candidate if it grows. - `packages/nightwatch-devtools/src/session.ts` (519 raw, under the logic-line cap after `skipBlankLines`/`skipComments`). `captureNetworkFromPerformanceLogs` + `captureBrowserLogs` + `drainCollector` are tightly coupled to NightwatchBrowser state. Coverage at 78% after recent backfill; further extraction would need rewriting the browser-coupling. diff --git a/packages/core/src/screencast.ts b/packages/core/src/screencast.ts index cf439c81..fdf08a7a 100644 --- a/packages/core/src/screencast.ts +++ b/packages/core/src/screencast.ts @@ -337,7 +337,7 @@ export abstract class ScreencastRecorderBase { clearInterval(this.#pollTimer) this.#pollTimer = undefined // A shot issued just before the stop outlives it. Bumping the generation - // keeps that orphan from appending into a later recording or clearing the + // keeps that orphan from appending after the stop or clearing the // successor's latch, and clearing the latch here lets a restart tick // without waiting on it. this.#pollGeneration++ diff --git a/packages/selenium-devtools/tests/screencast.test.ts b/packages/selenium-devtools/tests/screencast.test.ts new file mode 100644 index 00000000..7fd37335 --- /dev/null +++ b/packages/selenium-devtools/tests/screencast.test.ts @@ -0,0 +1,65 @@ +import { describe, it, expect, vi } from 'vitest' +import { ScreencastRecorder } from '../src/screencast.js' +import { getDriverOriginals } from '../src/driverPatcher.js' +import type { SeleniumDriverLike } from '../src/types.js' + +class TestScreencastRecorder extends ScreencastRecorder { + unavailable: unknown[] = [] + + protected override onUnavailable(err: unknown): void { + this.unavailable.push(err) + } +} + +describe('ScreencastRecorder — CDP handshake ceiling', () => { + it('a hung createCDPConnection resolves start and a queued stop at the ceiling, and falls back to polling', async () => { + vi.useFakeTimers() + try { + const createCDPConnection = vi.fn(() => new Promise(() => {})) + // The recorder never calls executeScript; SeleniumDriverLike requires it. + const driver: SeleniumDriverLike = { + executeScript: () => Promise.resolve(null), + createCDPConnection + } + getDriverOriginals().takeScreenshot = () => new Promise(() => {}) + const r = new TestScreencastRecorder({ pollIntervalMs: 50 }) + const starting = r.start(driver) + const stopping = r.stop() + await vi.advanceTimersByTimeAsync(5000) // CDP handshake ceiling + await vi.advanceTimersByTimeAsync(5000) // polling first-shot ceiling + await Promise.all([starting, stopping]) + expect(createCDPConnection).toHaveBeenCalledTimes(1) + expect(r.isRecording).toBe(false) + expect(r.unavailable).toHaveLength(1) + expect((r.unavailable[0] as Error).message).toBe( + 'first screenshot timed out' + ) + } finally { + getDriverOriginals().takeScreenshot = undefined + vi.useRealTimers() + } + }) + + it('a createCDPConnection that resolves without a websocket falls back to polling', async () => { + vi.useFakeTimers() + try { + const createCDPConnection = vi.fn(async () => ({ execute: vi.fn() })) + const driver: SeleniumDriverLike = { + executeScript: () => Promise.resolve(null), + createCDPConnection + } + getDriverOriginals().takeScreenshot = vi.fn(async () => 'frame-1') + const r = new TestScreencastRecorder({ pollIntervalMs: 50 }) + await r.start(driver) + expect(createCDPConnection).toHaveBeenCalledTimes(1) + expect(r.isRecording).toBe(true) + expect(r.frames).toHaveLength(1) + expect(r.frames[0].data).toBe('frame-1') + await r.stop() + expect(r.isRecording).toBe(false) + } finally { + getDriverOriginals().takeScreenshot = undefined + vi.useRealTimers() + } + }) +}) diff --git a/packages/service/src/index.ts b/packages/service/src/index.ts index 7919af6c..0e9f684b 100644 --- a/packages/service/src/index.ts +++ b/packages/service/src/index.ts @@ -81,6 +81,13 @@ export default class DevToolsHookService implements Services.ServiceInstance { #browser?: WebdriverIO.Browser #options: ServiceOptions #actionSnapshots: ActionSnapshot[] = [] + /** The slot `#finalizePerScenario` last captured, so `after()`'s second pass + * does not pay for it again. Tracked rather than scanned from + * #actionSnapshots: the last action's pre-capture holds the same command + * and timestamp whenever the previous action ended in the same + * millisecond, so a scan mistook it for this slot and skipped the only + * capture of the last action's result. */ + #finalizedSlot?: { command: string; timestamp: number } #assertionTracker: AssertionTracker #screencast: ScreencastLifecycle #slices: TraceSliceTracker @@ -564,17 +571,21 @@ export default class DevToolsHookService implements Services.ServiceInstance { // A session with no action has no timestamp of its own to key on, so its // frame is recognised by the marker instead — otherwise `Date.now()` differs // between the per-test finalize and `after()` and both capture. - const alreadyCaptured = lastAction - ? this.#actionSnapshots.some( - (snap) => snap.timestamp === lastAction.timestamp - ) - : this.#actionSnapshots.some( - (snap) => snap.command === FINAL_SNAPSHOT_COMMAND - ) + const command = lastAction?.command ?? FINAL_SNAPSHOT_COMMAND + const timestamp = lastAction?.timestamp ?? Date.now() // `after()` finalizes once more at session end, for the standalone path that // has no per-test hook. On a framework run the test that just ended has // already recorded this slot, and the driver would return the same page a - // second time — capture only when it is still empty. + // second time — capture only when it is still empty. Compared against the + // tracked slot rather than a scan of #actionSnapshots (see #finalizedSlot): + // a scan also matched an assertion row sharing the last action's timestamp, + // whose capture shows the post-action state and is kept by the + // richest-screenshot merge below anyway. + const slot = this.#finalizedSlot + const alreadyCaptured = lastAction + ? slot?.command === lastAction.command && + slot?.timestamp === lastAction.timestamp + : slot?.command === FINAL_SNAPSHOT_COMMAND if (!alreadyCaptured) { await settleAfterLastAction( this.#browser, @@ -583,8 +594,8 @@ export default class DevToolsHookService implements Services.ServiceInstance { ) const snap = await captureActionSnapshot( this.#browser, - lastAction?.command ?? FINAL_SNAPSHOT_COMMAND, - lastAction?.timestamp ?? Date.now(), + command, + timestamp, this.#sessionCapturer.currentContext ) if (snap) { @@ -592,6 +603,7 @@ export default class DevToolsHookService implements Services.ServiceInstance { // have captured too, and resources are named by timestamp — keep only the // richer screenshot so a blank end-of-scenario frame cannot clobber it. upsertRichestSnapshot(this.#actionSnapshots, snap) + this.#finalizedSlot = { command, timestamp } } } } diff --git a/packages/service/src/screencast.ts b/packages/service/src/screencast.ts index 1d529b4a..5a8e4c5b 100644 --- a/packages/service/src/screencast.ts +++ b/packages/service/src/screencast.ts @@ -13,6 +13,7 @@ const CDP_TIMEOUT = Symbol('cdp-timeout') interface CdpSessionLike { send(method: string, params?: Record): Promise on(event: string, handler: (event: unknown) => void | Promise): void + detach?(): Promise } interface PuppeteerPageLike { @@ -101,6 +102,17 @@ export class ScreencastRecorder extends ScreencastRecorderBase { + // A timed-out Page.stopScreencast leaves this session live; frames + // arriving after teardown belong to no recording. + if (this.#cdpSession !== session) { + return + } const event = rawEvent as { data: string metadata: { timestamp: number } diff --git a/packages/service/tests/screencast.test.ts b/packages/service/tests/screencast.test.ts index 5b9fd4da..3830404e 100644 --- a/packages/service/tests/screencast.test.ts +++ b/packages/service/tests/screencast.test.ts @@ -194,7 +194,8 @@ describe('ScreencastRecorder', () => { try { const cdpSession = { send: vi.fn(() => new Promise(() => {})), - on: vi.fn() + on: vi.fn(), + detach: vi.fn().mockResolvedValue(undefined) } const browser = { getPuppeteer: vi.fn().mockResolvedValue({ @@ -217,6 +218,39 @@ describe('ScreencastRecorder', () => { expect.anything() ) expect(cdpSession.on).not.toHaveBeenCalled() + expect(cdpSession.detach).toHaveBeenCalledTimes(1) + expect(recorder.frames).toEqual([]) + } finally { + vi.useRealTimers() + } + }) + + it('a detach that never settles does not park a queued stop', async () => { + vi.useFakeTimers() + try { + const cdpSession = { + send: vi.fn(() => new Promise(() => {})), + on: vi.fn(), + detach: vi.fn(() => new Promise(() => {})) + } + const browser = { + getPuppeteer: vi.fn().mockResolvedValue({ + pages: vi + .fn() + .mockResolvedValue([ + { createCDPSession: vi.fn().mockResolvedValue(cdpSession) } + ]) + }), + takeScreenshot: vi.fn().mockRejectedValue(new Error('no screenshots')) + } as any + const recorder = new ScreencastRecorder() + const starting = recorder.start(browser) + const stopping = recorder.stop() + await vi.advanceTimersByTimeAsync(5000) + await vi.advanceTimersByTimeAsync(5000) + await Promise.all([starting, stopping]) + expect(recorder.isRecording).toBe(false) + expect(cdpSession.detach).toHaveBeenCalledTimes(1) expect(recorder.frames).toEqual([]) } finally { vi.useRealTimers() diff --git a/packages/service/tests/trace-action-capture.test.ts b/packages/service/tests/trace-action-capture.test.ts index e05799f2..16dcbfed 100644 --- a/packages/service/tests/trace-action-capture.test.ts +++ b/packages/service/tests/trace-action-capture.test.ts @@ -222,6 +222,43 @@ describe('trace mode: one capture per action, taken before it', () => { expect(vi.mocked(captureActionSnapshot)).toHaveBeenCalledTimes(2) }) + it('captures the last action when the previous one ended in the same millisecond', async () => { + const browser = nativeBrowser() + const service = new DevToolsHookService({ mode: 'trace' }) + await service.before({} as never, [], browser) + + // Two action commands completing at one logged timestamp: the last one's + // pre-capture is stamped at the previous action's end and carries the + // upcoming command's own name, so it fills the exact command+timestamp + // slot the finalize is about to capture — reading the answer off the + // recorded snapshots (by timestamp or command) mistakes it for the + // finalize's own and the last action's result is never taken. + const sameMs = 42 + const logAtSameMs = () => + vi + .mocked(capturer.afterCommand) + .mockImplementationOnce(async (_browser: unknown, command: string) => { + commandsLog.push({ command, timestamp: sameMs }) + }) + logAtSameMs() + logAtSameMs() + for (const command of ['click', 'setValue']) { + await service.beforeCommand(command as never, []) + await service.afterCommand(command as never, [], undefined) + } + + vi.mocked(captureActionSnapshot).mockClear() + await service.after() + expect(vi.mocked(captureActionSnapshot)).toHaveBeenCalledTimes(1) + expect(namedAt(0)).toBe('setValue') + expect(stampedAt(0)).toBe(sameMs) + + // `after()` re-runs the finalize for the standalone path; the slot the + // first pass recorded keeps the second from paying for it again. + await service.after() + expect(vi.mocked(captureActionSnapshot)).toHaveBeenCalledTimes(1) + }) + it('captures the no-action frame once per session', async () => { const browser = nativeBrowser() const service = new DevToolsHookService({ mode: 'trace' }) From 1387285e1815b4dd56111ae829d5d9450a3878de Mon Sep 17 00:00:00 2001 From: Vince Graics Date: Tue, 22 Sep 2026 17:09:37 +0200 Subject: [PATCH 6/6] fix: clean up CDP sessions and sockets the recordings left open --- .../serialise-screencast-start-and-stop.md | 2 +- CLAUDE.md | 2 +- packages/selenium-devtools/src/screencast.ts | 25 ++++++- .../tests/screencast.test.ts | 74 +++++++++++++++++++ packages/service/src/screencast.ts | 36 ++++++--- packages/service/tests/screencast.test.ts | 38 ++++++++++ 6 files changed, 161 insertions(+), 16 deletions(-) diff --git a/.changeset/serialise-screencast-start-and-stop.md b/.changeset/serialise-screencast-start-and-stop.md index bc981c57..b7b239fb 100644 --- a/.changeset/serialise-screencast-start-and-stop.md +++ b/.changeset/serialise-screencast-start-and-stop.md @@ -9,4 +9,4 @@ Stop a screencast session outliving the recording it was armed for. A `stop()` a The visible consequence of the fix: `stop()` now waits for an in-flight handshake rather than returning immediately — so every driver primitive that handshake awaits is ceilinged. An unbounded one (the service's `getPuppeteer()`/`pages()`/`createCDPSession()`/`Page.startScreencast` and the `session.detach()` its timeout path takes, the polling path's first screenshot, Selenium's `createCDPConnection`) would have parked teardown behind a driver that never answers, turning a leaked session into a hung test run. On the ceiling the handshake gives up and the recorder falls back to polling, or reports the screencast unavailable when polling was what wedged. -Nothing is claimed until the handshake has answered, which is what keeps the ceiling safe: a `Page.startScreencast` that times out leaves no session, no frame listener and no stream behind for teardown to find. The same ceiling covers the stop-side `Page.stopScreencast` send, so a wedged stop cannot block the next recording either. +Nothing is claimed until the handshake has answered, which is what keeps the ceiling safe: a `Page.startScreencast` that times out leaves no session, no frame listener and no stream behind for teardown to find — and a CDP session or connection that completes after the ceiling is detached (or, for Selenium, has its socket closed) when it lands, so no orphan outlives the recording. Selenium's stop closes the socket its recording opened on the success path too: each `createCDPConnection` overwrites the driver's single connection slot and `quit()` closes only the current one, so every recording rotation on one driver would otherwise leak one live websocket for the session's life. The same ceiling covers the stop-side `Page.stopScreencast` send, so a wedged stop cannot block the next recording either. diff --git a/CLAUDE.md b/CLAUDE.md index 5efab78d..953f2050 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -338,7 +338,7 @@ Documented divergences from the conventions above. They exist today as debt to b - **One capture per action means two driver round trips per action, and the platform decides which half is expensive.** Measured on Appium 3.7.0 / UiAutomator2 (emulator-5554, Android API 37, 1080×2424): `GET /screenshot` 1.18–2.22 s (steady ~1.20 s) at 1.86 MB, `GET /source` (page-source XML) 0.09–0.53 s at 40 KB, `window/rect` 0.015 s — the screenshot dominates by ~10× on Android. **iOS is unmeasured**; the issue claims the split inverts there, and the native example (`examples/wdio/mocha/wdio.native.conf.ts`) is what makes it measurable. Measured per action: two captures 2.41 s against one capture 1.19 s; end-to-end on the native example 19.1 s against 12.4 s, with live mode (no per-action capture) at 5.9 s. That is the case for the `beforeCommand` capture, and the reason an eager post-action capture is not worth re-adding: it cost a second capture per action and existed only to be patched by a `readyState` poll that could not tell a document that had not navigated yet from one that was loading. - A filmstrip poll against a native session stacks requests: `setInterval` never waits for its async handler, a native screenshot takes ~1.2 s against the 200 ms default, and a serialised driver serves that queue ahead of the test's own commands — measured, a **15 ms command took 4.5–7.8 s**. `ScreencastRecorderBase`'s `#pollInFlight` latch bounds it to one outstanding shot, and `#pollGeneration` stops a shot orphaned by `stop()` from appending after the stop or clearing its successor's latch. -- **`start()` and `stop()` are serialised against each other, because unserialised neither owns what it arms.** A `stop()` landing mid-handshake returned at its `#isRecording` guard — still false, the handshake not having finished — so it never reached its own CDP teardown, and the `start()` it interrupted then returned on the generation mismatch without stopping what it had armed: the session and its frame listener stayed live after teardown. The frames themselves were moot — every adapter builds a fresh recorder per session (`screencast-lifecycle.ts` does so even across `reloadSession`), so the leaked session and its browser-side stream were the damage, not buffer pollution. The obvious repair — stopping the session on that mismatch path — is wrong, and it is the shape to keep out: it guards a field both CDP overrides write at handshake **start** (`#cdpSession` / `#cdp`) with a flag they set only at handshake **end** (`#cdpActive`), so a start arriving in that window is indistinguishable from no start at all and the stale path tears down the *newer* recording's session instead. Overlapping starts are the adapters' normal mode rather than a corner: Selenium's `driverPatcher` documents the second test's body racing an in-flight `screencast.start()`, and Nightwatch's session rotation is fire-and-forget from a command hook. Queued, a stop always runs against a start that has finished arming and owns what it armed, which makes the mismatch branch unreachable and deleted — the tick-phase generation checks in `#startPolling` are **not**, since a shot orphaned by a stop still lands afterwards. Two consequences: `stop()` now waits on an in-flight handshake, and every awaited driver primitive in that handshake is ceilinged at `SCREENCAST_HANDSHAKE_TIMEOUT_MS` (the service's `getPuppeteer()`/`pages()`/`createCDPSession()`/`Page.startScreencast` and the stop-side `Page.stopScreencast`, Selenium's `createCDPConnection`, the polling path's first screenshot) — a driver that wedges gives up after the ceiling, falls back to polling, or reports the screencast unavailable when polling was what wedged. Nothing is claimed until the handshake has answered, so a timed-out start leaves nothing armed. And a stop landing during a polling session's first screenshot now records that shot before tearing the loop down, where it previously cancelled the start outright; the interval is still never left armed underneath the stop. +- **`start()` and `stop()` are serialised against each other, because unserialised neither owns what it arms.** A `stop()` landing mid-handshake returned at its `#isRecording` guard — still false, the handshake not having finished — so it never reached its own CDP teardown, and the `start()` it interrupted then returned on the generation mismatch without stopping what it had armed: the session and its frame listener stayed live after teardown. The frames themselves were moot — every adapter builds a fresh recorder per session (`screencast-lifecycle.ts` does so even across `reloadSession`), so the leaked session and its browser-side stream were the damage, not buffer pollution. The obvious repair — stopping the session on that mismatch path — is wrong, and it is the shape to keep out: it guards a field both CDP overrides write at handshake **start** (`#cdpSession` / `#cdp`) with a flag they set only at handshake **end** (`#cdpActive`), so a start arriving in that window is indistinguishable from no start at all and the stale path tears down the *newer* recording's session instead. Overlapping starts are the adapters' normal mode rather than a corner: Selenium's `driverPatcher` documents the second test's body racing an in-flight `screencast.start()`, and Nightwatch's session rotation is fire-and-forget from a command hook. Queued, a stop always runs against a start that has finished arming and owns what it armed, which makes the mismatch branch unreachable and deleted — the tick-phase generation checks in `#startPolling` are **not**, since a shot orphaned by a stop still lands afterwards. Two consequences: `stop()` now waits on an in-flight handshake, and every awaited driver primitive in that handshake is ceilinged at `SCREENCAST_HANDSHAKE_TIMEOUT_MS` (the service's `getPuppeteer()`/`pages()`/`createCDPSession()`/`Page.startScreencast` and the stop-side `Page.stopScreencast`, Selenium's `createCDPConnection`, the polling path's first screenshot) — a driver that wedges gives up after the ceiling, falls back to polling, or reports the screencast unavailable when polling was what wedged. Nothing is claimed until the handshake has answered, so a timed-out start leaves nothing armed — and a session or connection that completes after the ceiling is detached (or its socket closed) when it lands, so no orphan outlives the recording. And a stop landing during a polling session's first screenshot now records that shot before tearing the loop down, where it previously cancelled the start outright; the interval is still never left armed underneath the stop. - Residual: **a polling matcher fires one capture per poll** — each poll is a top-level mapped read — so "one capture per action" undercounts a real suite. Pre-existing in `d924a02`, unmeasured on a device, and the likeliest next lever. - The next test's first pre-capture used to be stamped at the previous test's last-action timestamp — the log it scans is run-long, so a test boundary was invisible to it. That slot already holds the previous test's finalize capture, and the richer-screenshot merge could replace it: with a `reloadSession` between the tests the row replayed the post-reload page. The capture now stamps `Date.now()` when the scanned timestamp predates `#currentTestStartWallTime` (0 without per-test hooks, so the standalone path is unchanged) — the same rule that makes a session's first capture its initial frame. Per-test slices were never affected: `flushTest` runs inside `afterTest`, before the next test's commands. diff --git a/packages/selenium-devtools/src/screencast.ts b/packages/selenium-devtools/src/screencast.ts index bfca534a..e80e7aea 100644 --- a/packages/selenium-devtools/src/screencast.ts +++ b/packages/selenium-devtools/src/screencast.ts @@ -20,6 +20,7 @@ const log = logger('@wdio/selenium-devtools:ScreencastRecorder') interface SeleniumCdpWebSocket { on(event: 'message', listener: (data: unknown) => void): void off?: (event: 'message', listener: (data: unknown) => void) => void + close?: () => void } interface SeleniumCdpConnection { _wsConnection?: SeleniumCdpWebSocket @@ -133,11 +134,22 @@ export class ScreencastRecorder extends ScreencastRecorderBase; the // runtime shape is stable across patch releases and captured by // SeleniumCdpConnection above. - return withTimeout( - driver.createCDPConnection('page') as Promise, + const connection = driver.createCDPConnection( + 'page' + ) as Promise + const cdp = await withTimeout( + connection, SCREENCAST_HANDSHAKE_TIMEOUT_MS, undefined ) + if (!cdp) { + // A connection that lands after the ceiling belongs to nobody — close + // its socket when it does, so it cannot outlive the recording. + connection + .then((late) => late?._wsConnection?.close?.()) + .catch(() => undefined) + } + return cdp } protected override async tryStartCdp(): Promise { @@ -219,6 +231,15 @@ export class ScreencastRecorder extends ScreencastRecorderBase { vi.useRealTimers() } }) + + it('stopping a CDP recording closes the connection it opened', async () => { + const close = vi.fn() + const frame = JSON.stringify({ + method: 'Page.screencastFrame', + params: { data: 'aGk=', sessionId: 1, metadata: { timestamp: 1 } } + }) + const cdp = { + execute: vi.fn(), + _wsConnection: { + on: (_event: string, listener: (data: unknown) => void) => { + // Microtask: tryStartCdp arms the first-frame resolver after + // ws.on returns, so a synchronous fire lands before it exists. + queueMicrotask(() => listener(frame)) + }, + off: vi.fn(), + close + } + } + const driver: SeleniumDriverLike = { + executeScript: () => Promise.resolve(null), + createCDPConnection: vi.fn().mockResolvedValue(cdp) + } + const r = new TestScreencastRecorder({ pollIntervalMs: 50 }) + await r.start(driver) + expect(r.isRecording).toBe(true) + expect(cdp.execute).toHaveBeenCalledWith( + 'Page.startScreencast', + expect.anything() + ) + await r.stop() + expect(cdp.execute).toHaveBeenCalledWith('Page.stopScreencast') + expect(cdp._wsConnection.off).toHaveBeenCalledWith( + 'message', + expect.any(Function) + ) + expect(close).toHaveBeenCalledTimes(1) + expect(r.isRecording).toBe(false) + }) + + it('a createCDPConnection that lands after the ceiling has its socket closed', async () => { + vi.useFakeTimers() + try { + const close = vi.fn() + const lateConnection = { + execute: vi.fn(), + _wsConnection: { on: vi.fn(), close } + } + const createCDPConnection = vi.fn( + () => + new Promise((resolve) => + setTimeout(() => resolve(lateConnection), 6000) + ) + ) + const driver: SeleniumDriverLike = { + executeScript: () => Promise.resolve(null), + createCDPConnection + } + getDriverOriginals().takeScreenshot = () => new Promise(() => {}) + const r = new TestScreencastRecorder({ pollIntervalMs: 50 }) + const starting = r.start(driver) + const stopping = r.stop() + await vi.advanceTimersByTimeAsync(11000) + await Promise.all([starting, stopping]) + expect(r.isRecording).toBe(false) + expect(close).toHaveBeenCalledTimes(1) + expect((r.unavailable[0] as Error).message).toBe( + 'first screenshot timed out' + ) + } finally { + getDriverOriginals().takeScreenshot = undefined + vi.useRealTimers() + } + }) }) diff --git a/packages/service/src/screencast.ts b/packages/service/src/screencast.ts index 5a8e4c5b..33ff924a 100644 --- a/packages/service/src/screencast.ts +++ b/packages/service/src/screencast.ts @@ -81,12 +81,14 @@ export class ScreencastRecorder extends ScreencastRecorderBase( - pages[0].createCDPSession(), + sessionPromise, SCREENCAST_HANDSHAKE_TIMEOUT_MS, undefined ) if (!session) { + this.#detachWhenItLands(sessionPromise) return undefined } @@ -102,22 +104,32 @@ export class ScreencastRecorder extends ScreencastRecorderBase { + try { + await withTimeout( + Promise.resolve(session.detach?.()), + SCREENCAST_HANDSHAKE_TIMEOUT_MS, + undefined + ) + } catch { + // best-effort — the session may already be gone + } + } + + /** A session that completes after the ceiling belongs to nobody — detach it + * when it lands so it cannot linger for the page's life. */ + #detachWhenItLands(session: Promise): void { + session.then((late) => late?.detach?.()).catch(() => undefined) + } + protected override async tryStartCdp(): Promise { if (!this.driver) { return false diff --git a/packages/service/tests/screencast.test.ts b/packages/service/tests/screencast.test.ts index 3830404e..44a236d7 100644 --- a/packages/service/tests/screencast.test.ts +++ b/packages/service/tests/screencast.test.ts @@ -256,4 +256,42 @@ describe('ScreencastRecorder', () => { vi.useRealTimers() } }) + + it('a createCDPSession that lands after the ceiling is detached', async () => { + vi.useFakeTimers() + try { + const cdpSession = { + send: vi.fn().mockResolvedValue(undefined), + on: vi.fn(), + detach: vi.fn().mockResolvedValue(undefined) + } + const browser = { + getPuppeteer: vi.fn().mockResolvedValue({ + pages: vi.fn().mockResolvedValue([ + { + createCDPSession: vi.fn( + () => + new Promise((resolve) => + setTimeout(() => resolve(cdpSession), 6000) + ) + ) + } + ]) + }), + takeScreenshot: vi.fn().mockRejectedValue(new Error('no screenshots')) + } as any + const recorder = new ScreencastRecorder() + const starting = recorder.start(browser) + const stopping = recorder.stop() + await vi.advanceTimersByTimeAsync(5000) + await Promise.all([starting, stopping]) + expect(recorder.isRecording).toBe(false) + expect(cdpSession.detach).not.toHaveBeenCalled() + await vi.advanceTimersByTimeAsync(2000) + expect(cdpSession.detach).toHaveBeenCalledTimes(1) + expect(cdpSession.on).not.toHaveBeenCalled() + } finally { + vi.useRealTimers() + } + }) })