fix(nightwatch-devtools): read the performance log off the command queue

.changeset/nightwatch-perf-log-off-queue.md

@@ -0,0 +1,7 @@
+---
+'@wdio/nightwatch-devtools': patch
+---
+
+On a session without BiDi that requests Chrome's performance log, the plugin reads that log over the WebDriver HTTP transport rather than with `browser.getLog`, so the read no longer joins Nightwatch's command queue and cannot make a test command such as `setValue` or `click` resolve before it has finished.
+
+Every read the plugin makes over that transport (the performance log, the collector drains, the snapshot probes and screenshots) now uses the connection Nightwatch itself is configured with: https when `webdriver.ssl` is set, or when it is unset and the port is 443, and basic auth from `webdriver.username` and `webdriver.access_key`. Against a remote grid on https or behind credentials, those reads previously went out as plain http without credentials and failed.

CLAUDE.md

@@ -331,7 +331,7 @@ Documented divergences from the conventions above. They exist today as debt to b
   - **A preload dies with its session, and Nightwatch replaces sessions without saying so.** Registration used to run once at bringup, so a mid-run `browser.end()` left sessions 2..N with neither preload nor BiDi: measured 1 registration and 1 attach for a whole run, 4-6 `Collector missing … re-injecting` recoveries, and — because `bidiActive` stayed `true` from the dead session and gates the perf-log fallback off — **zero network capture after the rotation** (75 requests in session 1, 0 in session 2). `session-init.ts` `rearmCaptureForSession` re-arms both off the same command-hook detection the screencast rotation uses (`armedSessionId`, stamped before the first await so the command flood latches out), clearing `preloadRegistered`/`bidiActive` at detection so the fallbacks are open in the gap. After: 2 registrations, 2 attaches, 0-1 recoveries, 125 network entries (75 + 50), and the accumulated stream untouched — 21 action rows split 12/9 across the two sessions, identical to before. It deliberately does **not** rebuild the `SessionCapturer` — see the entry below, which made that the rule for every path rather than just this one.
     - The preload registers **before** the BiDi attach, sequentially: behind the attach it lost the race it exists to win (the network subscribe took 6.2 s while the triggering command navigated, so registration landed after its own document was born), and `Promise.all` races selenium-webdriver's unsynchronized `getBidi()` cache into two websockets of which `quit()` closes one.
     - Residual: detection is at command invocation and chromedriver serialises the handshake behind the in-flight command, so the **first navigation after a rotation** can still land before registration and falls back to `<script>` injection (1 recovery in 3 of 4 runs, 0 in the fourth). Nightwatch exposes no pre-test session hook to a plugin.
-  - **The perf-log fallback only runs when the session asked for a perf log** (`SessionCapturer.perfLogsRequested`, set from `goog:loggingPrefs.performance` at session init — the same reading that already warns "Network tab will be empty"). Without the capability the log cannot exist, so every per-command fetch is a round trip that can only fail, and Nightwatch's transport prints each failure: measured on an iOS Safari session, 21 error blocks in a two-test run that passed, 257 log lines and 12.3 s against 66 and 5.9 s once gated. A runtime latch cannot do this job — `await browser.getLog(...)` yields `undefined` in this Nightwatch version rather than the 500's body, so the refusal is invisible to the caller (the same quirk as `browser.elements()`). XCUITest is why it has to be the capability and not a "is this Chrome" test: it lists `performance` among its supported types and then serves none of it.
+  - **The perf-log fallback only runs when the session asked for a perf log** (`SessionCapturer.perfLogsRequested`, set from `goog:loggingPrefs.performance` at session init — the same reading that already warns "Network tab will be empty"). Without the capability the log cannot exist, so every per-command fetch is a round trip that can only fail, and Nightwatch's transport prints each failure: measured on an iOS Safari session, 21 error blocks in a two-test run that passed, 257 log lines and 12.3 s against 66 and 5.9 s once gated. Those numbers were taken when the read was `browser.getLog`; it now goes over the raw WebDriver transport (`POST /session/:id/se/log`, the route selenium-webdriver, and so Nightwatch, sends), because the read is issued from the fire-and-forget drain and the navigation poll, and a queued command issued while the test's next command runs becomes that command's child and resolves its await early. Over HTTP a refusal resolves null without a printed error, but the gate still saves a round trip per command, and a runtime latch still cannot replace it: `browser.getLog(...)` yielded `undefined` rather than the 500's body, and the transport's null is equally indistinguishable from an empty log. XCUITest is why it has to be the capability and not a "is this Chrome" test: it lists `performance` among its supported types and then serves none of it.
   - Deliberately **not** gated on Nightwatch's `bidi` option. That option exists to avoid double-reporting console/network against the perf-log path; preload registration needs nothing but a session created with `webSocketUrl: true`, and gating DOM capture on an unrelated opt-in that defaults to `false` would leave the race in place for nearly every user. `ScriptManager.init` throws without that capability, so the helper self-degrades to the `<script>` path and returns false.
   - The fallback path is kept and still works, but is strictly lower fidelity: measured with `bidi:false`, 0 rows without DOM but the per-action field-state mutations don't survive and a navigating click keeps the ~5 ms residual. Prefer `webSocketUrl: true`.
   - **The collector's bootstrap must not wait for an animation frame when the body already exists.** `utils.ts` `waitForBody` always waited for a `requestAnimationFrame` (or `DOMContentLoaded`), which a document-start preload needs but a `<script>` appended to a loaded document does not: Safari's automation window paints only when something forces it, so on desktop Safari the injected collector sat in the page with no anchor, no MutationObserver and no `input` listener until a screenshot happened to force a frame, and a live run replayed the bare anchor on every row with empty fields. Measured with the adapter in trace mode, 8 keystrokes typed after injection reached the document's own listeners every time and the collector 0 of them with per-command screenshots off, 8 with them on. The body is now checked synchronously first.
@@ -394,7 +394,7 @@ Most entries below don't trigger the `max-lines` lint rule after `skipBlankLines
 - `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.
+- `packages/nightwatch-devtools/src/session.ts` (519 raw, under the logic-line cap after `skipBlankLines`/`skipComments`). `captureNetworkFromPerformanceLogs` + `drainCollector` are tightly coupled to NightwatchBrowser state. Coverage at 78% after recent backfill; further extraction would need rewriting the browser-coupling.
 - `packages/selenium-devtools-py/src/selenium_devtools/instrumentation.py` (975 raw). Every seam here reads the module-level `_state` bag — the per-action snapshot capture, its two accessors and the element-scripts handoff all key off `trace`/`a11y`/`element_scripts` alongside the screencast and session entries — so an extraction is a move of state ownership, not a lift of a function. The next change that touches `_state` itself should split it per concern first; `action_snapshot.py` is then a clean lift.
 
 ### Test coverage gaps (worst-risk-first)

packages/nightwatch-devtools/src/helpers/perfLogs.ts

@@ -11,9 +11,10 @@ import { getRequestType } from './utils.js'
 const RESOURCE_TIMING_MATCH_MS = 2000
 
 /**
- * Pure parsers for Chrome's `performance` log (the format `browser.getLog('performance')`
- * returns). Separated from the SessionCapturer so they're testable and the
- * capture method stays focused on state + I/O.
+ * Pure parsers for Chrome's `performance` log (the entries
+ * `POST /session/:id/se/log` returns for `{ type: 'performance' }`). Separated
+ * from the SessionCapturer so they're testable and the capture method stays
+ * focused on state + I/O.
  */
 
 export interface PerfLogEntry {

packages/nightwatch-devtools/src/helpers/webdriverHttp.ts

@@ -41,12 +41,17 @@ const firstDefined = (obj: unknown, ...keys: string[]): unknown => {
   return undefined
 }
 
-/** The driver settings as configured, with no defaults applied. */
-function configuredWebDriver(browser: NightwatchBrowser): {
+interface ConfiguredWebDriver {
   host: unknown
   port: unknown
   pathPrefix: unknown
-} {
+  ssl: unknown
+  username: unknown
+  accessKey: unknown
+}
+
+/** The driver settings as configured, with no defaults applied. */
+function configuredWebDriver(browser: NightwatchBrowser): ConfiguredWebDriver {
   const transportSettings =
     getPath(browser, 'transport', 'settings', 'webdriver') ||
     getPath(browser, 'queue', 'transport', 'settings', 'webdriver') ||
@@ -68,12 +73,38 @@ function configuredWebDriver(browser: NightwatchBrowser): {
     getProp(opts, 'webdriver'),
     getProp(nightwatchSettings, 'webdriver')
   ]
-  const pick = (...keys: string[]) =>
-    sources.map((source) => firstDefined(source, ...keys)).find(Boolean)
+  const values = (...keys: string[]) =>
+    sources.map((source) => firstDefined(source, ...keys))
+  const pick = (...keys: string[]) => values(...keys).find(Boolean)
   return {
     host: pick('host', 'server_address'),
     port: pick('port'),
-    pathPrefix: pick('default_path_prefix')
+    pathPrefix: pick('default_path_prefix'),
+    // `ssl: false` is a setting, not an absence, so it must not fall through to a later source.
+    ssl: values('ssl').find((v) => v !== undefined),
+    username: pick('username'),
+    accessKey: values('access_key').find((v) => v !== undefined)
+  }
+}
+
+/** Nightwatch's own connection settings (`settings.js` `setWebdriverSettings`, `client.js` `setHttpOptions`): https when `ssl` is set or, unset, when the port is 443; basic auth when both `username` and `access_key` are. */
+function connection(
+  configured: ConfiguredWebDriver,
+  hostname: string,
+  port: number
+): WebDriverAddress {
+  const { pathPrefix, ssl, username, accessKey } = configured
+  const secure = ssl === undefined ? port === 443 : Boolean(ssl)
+  const hasCredentials = Boolean(username) && accessKey !== undefined
+  return {
+    hostname,
+    port,
+    protocol: secure ? 'https' : 'http',
+    path: typeof pathPrefix === 'string' ? pathPrefix : undefined,
+    ...(hasCredentials
+      ? { user: String(username), key: String(accessKey) }
+      : {}),
+    onWarn: (message: string) => log.warn(message)
   }
 }
 
@@ -93,17 +124,10 @@ export function resolveWebDriverAddress(browser: NightwatchBrowser): {
   }
 }
 
-/** The core transport's address, plus this adapter's logger. Nightwatch always
- *  speaks plain http to a local driver — it has no cloud-grid path of its own. */
+/** The core transport's address: the connection Nightwatch itself uses, plus this adapter's logger. */
 function address(browser: NightwatchBrowser): WebDriverAddress {
   const { driverHost, driverPort } = resolveWebDriverAddress(browser)
-  const { pathPrefix } = configuredWebDriver(browser)
-  return {
-    hostname: driverHost,
-    port: driverPort,
-    path: typeof pathPrefix === 'string' ? pathPrefix : undefined,
-    onWarn: (message: string) => log.warn(message)
-  }
+  return connection(configuredWebDriver(browser), driverHost, driverPort)
 }
 
 function sessionId(browser: NightwatchBrowser): string | undefined {
@@ -136,17 +160,16 @@ export function sessionExecutor(
   browser: NightwatchBrowser
 ): InterceptorExecute | undefined {
   const id = sessionId(browser)
-  const { host, port, pathPrefix } = configuredWebDriver(browser)
+  const configured = configuredWebDriver(browser)
   // No default port here: guessing chromedriver's would blame a missing plugin for a wrong address.
-  if (!id || !port) {
+  if (!id || !configured.port) {
     return undefined
   }
-  const at: WebDriverAddress = {
-    hostname: String(host || 'localhost'),
-    port: Number(port),
-    path: typeof pathPrefix === 'string' ? pathPrefix : undefined,
-    onWarn: (message: string) => log.warn(message)
-  }
+  const at = connection(
+    configured,
+    String(configured.host || 'localhost'),
+    Number(configured.port)
+  )
   return (script, args) => coreExecute(at, id, script, args)
 }
 

packages/nightwatch-devtools/src/session.ts

@@ -8,7 +8,6 @@ import {
   drainCollectorWithRecovery,
   errorMessage,
   loadInjectableScript,
-  mapChromeBrowserLogs,
   mapCommandToAction,
   NativeNetworkCapture,
   pollUntilReady,
@@ -29,7 +28,11 @@ import {
   type NetworkEntry,
   type PerfLogEntry
 } from './helpers/perfLogs.js'
-import { webdriverExecute, webdriverGet } from './helpers/webdriverHttp.js'
+import {
+  webdriverExecute,
+  webdriverGet,
+  webdriverPost
+} from './helpers/webdriverHttp.js'
 import type {
   ActionSnapshot,
   CommandCaptureMeta,
@@ -41,18 +44,6 @@ import type {
 
 const log = logger('@wdio/nightwatch-devtools:SessionCapturer')
 
-/**
- * WebDriver responses are sometimes wrapped as `{ value: T }` (the W3C
- * protocol shape) and sometimes flat. This helper unwraps the value field
- * if present, otherwise returns the input as-is.
- */
-function unwrapDriverValue<T = unknown>(result: unknown): T {
-  if (result && typeof result === 'object' && 'value' in result) {
-    return (result as { value: T }).value
-  }
-  return result as T
-}
-
 export class SessionCapturer extends SessionCapturerBase {
   #browser: NightwatchBrowser | undefined
 
@@ -461,32 +452,6 @@ export class SessionCapturer extends SessionCapturerBase {
     }
   }
 
-  /**
-   * Capture Chrome DevTools browser console logs via WebDriver log API.
-   * Requires loggingPrefs: { browser: 'ALL' } in Chrome capabilities.
-   */
-  async captureBrowserLogs(browser: NightwatchBrowser) {
-    try {
-      const rawLogs = await (
-        browser as unknown as Record<string, (type: string) => Promise<unknown>>
-      ).getLog('browser')
-      const logs =
-        unwrapDriverValue<
-          Array<{ level: string; message: string; timestamp: number }>
-        >(rawLogs)
-
-      if (!Array.isArray(logs) || logs.length === 0) {
-        return
-      }
-
-      const entries = mapChromeBrowserLogs(logs)
-      this.consoleLogs.push(...entries)
-      this.sendUpstream('consoleLogs', entries)
-    } catch {
-      // Browser log capture not available (loggingPrefs not set or not supported)
-    }
-  }
-
   /**
    * Parse Chrome performance logs to extract network request entries.
    * Requires loggingPrefs: { performance: 'ALL' } in Chrome capabilities.
@@ -496,26 +461,16 @@ export class SessionCapturer extends SessionCapturerBase {
     if (this.bidiActive || !this.perfLogsRequested) {
       return
     }
-    try {
-      const rawLogs = await (
-        browser as unknown as Record<string, (type: string) => Promise<unknown>>
-      ).getLog('performance')
-      const logs = unwrapDriverValue<PerfLogEntry[]>(rawLogs)
-
-      if (!Array.isArray(logs) || logs.length === 0) {
-        return
-      }
-
-      const networkEntries = parseNetworkFromPerfLogs(logs)
-      if (networkEntries.length > 0) {
-        this.#ingestPerfLogEntries(networkEntries)
-      }
-    } catch (err) {
-      const msg = errorMessage(err) ?? ''
-      // Silently skip when performance logging was not enabled in capabilities
-      if (!msg.includes('log type') && !msg.includes('performance')) {
-        log.warn(`Performance log capture failed: ${msg}`)
-      }
+    // Off the queue: a queued `getLog` issued mid-command becomes that command's child and resolves its await early.
+    const logs = await webdriverPost<PerfLogEntry[]>(browser, 'se/log', {
+      type: 'performance'
+    })
+    if (!Array.isArray(logs) || logs.length === 0) {
+      return
+    }
+    const networkEntries = parseNetworkFromPerfLogs(logs)
+    if (networkEntries.length > 0) {
+      this.#ingestPerfLogEntries(networkEntries)
     }
   }