From 829c0315b4fafe06815b941f697c00ec4d17d67f Mon Sep 17 00:00:00 2001 From: meetsu <96637888+klNuno@users.noreply.github.com> Date: Mon, 19 Oct 2026 17:32:23 +0200 Subject: [PATCH 1/7] test(e2e): say what holds a stalled page, its main thread or its requests A hung evaluate now reports whether the main thread runs JavaScript (Performance.getMetrics answers as a V8 interrupt), the CPU of each browser process and of the runner, and with BOITE_E2E_HANG_STACK=1 the paused stack. Each request in flight says whether the network service sent it or had its headers, and what the in-process UI server did with it. Requests of a document a navigation replaced no longer read as unanswered: Chrome never closes them. --- tests/e2e/lib/cdp.ts | 220 +++++++++++++++++++++++++++++++++-- tests/e2e/lib/ui-requests.ts | 53 +++++++++ tests/e2e/lib/ui.ts | 7 +- tests/e2e/lib/warm.ts | 3 +- 4 files changed, 267 insertions(+), 16 deletions(-) create mode 100644 tests/e2e/lib/ui-requests.ts diff --git a/tests/e2e/lib/cdp.ts b/tests/e2e/lib/cdp.ts index 616a04e84..c4fa8c2e7 100644 --- a/tests/e2e/lib/cdp.ts +++ b/tests/e2e/lib/cdp.ts @@ -1,10 +1,11 @@ import { existsSync, mkdirSync, mkdtempSync, writeFileSync } from 'node:fs'; import { createConnection, createServer } from 'node:net'; -import { tmpdir } from 'node:os'; +import { cpus, tmpdir } from 'node:os'; import { dirname, join } from 'node:path'; import { ONBOARDING_STORAGE_KEY, ONBOARDING_VERSION } from '../../../packages/ui/src/lib/onboarding.ts'; import type { Subprocess } from 'bun'; import { E2E_DIR_PREFIX, killProcessTreeAsync, removeDirectory, watchParentDeath, type ParentDeathWatch } from './cleanup.ts'; +import { uiServerSide } from './ui-requests.ts'; import { TextSocket } from './ws-client.ts'; /** @@ -103,6 +104,28 @@ interface Pending { timer: ReturnType; } +interface InFlight { + url: string; + at: number; + answered: boolean; + frameId?: string; + loaderId?: string; + sent?: number; + headers?: number; + cache?: boolean; +} + +/** One process of `SystemInfo.getProcessInfo`, CPU time in seconds since it started. */ +interface ProcessInfo { type: string; id: number; cpuTime: number } + +/** + * `BOITE_E2E_HANG_STACK=1` turns the debugger on in every page, so a page whose + * main thread runs JavaScript past an evaluate's deadline reports where. Off by + * default: `Debugger.enable` waits for that thread like any other call, so it + * cannot be sent once the page hangs, and on it reports every script parsed. + */ +const HANG_STACK = process.env.BOITE_E2E_HANG_STACK === '1'; + export interface BrowserOptions { url: string; executable?: string; @@ -167,8 +190,18 @@ export class BrowserPage { #pending = new Map(); #closed = false; #pageErrors: string[] = []; - /** Requests the page sent and has not finished loading, reported when a wait times out. */ - #requests = new Map(); + /** + * Requests the page's current documents sent and have not finished loading, + * reported when a wait times out. `sent` and `headers` are the network + * service's own events, which reach devtools from the browser process even + * while the renderer's main thread is blocked and Blink reports nothing. + */ + #requests = new Map(); + /** Network-service events that came before the request they belong to. */ + #early = new Map(); + /** The debugging port of the browser this page runs in, for the processes' CPU. */ + #debugPort: number | null = null; + #paused: ((frames: string) => void) | null = null; /** Completed failures would otherwise disappear from the timeout's in-flight list. */ #networkFailures: string[] = []; errors(): string[] { return [...this.#pageErrors]; } @@ -278,10 +311,12 @@ export class BrowserPage { const target = await waitForPageTarget(port, '', proc, true); const socket = await openSocket(target); page = new BrowserPage(socket, target, proc, ownsUserDataDir ? userDataDir : null, watch); + page.#debugPort = port; open.add(page); await page.send('Page.enable', {}); await page.send('Runtime.enable', {}); await page.send('Network.enable', {}); + await page.#enableHangProbes(); if (options.showTour !== true) await page.send('Page.addScriptToEvaluateOnNewDocument', { source: SEEN_TOUR }); if (options.terminalGpu !== true) { // Only on a fresh profile: a test that turns the GPU on and reloads keeps its choice. @@ -321,6 +356,7 @@ export class BrowserPage { try { const target = await waitForPageTarget(port, urlIncludes); page = new BrowserPage(await openSocket(target), target, null, null); + page.#debugPort = port; return await page.#prepareAttached(); } catch (error) { await page?.close().catch(() => undefined); @@ -334,6 +370,7 @@ export class BrowserPage { async #prepareAttached(): Promise { await this.send('Page.enable', {}); await this.send('Runtime.enable', {}); + await this.#enableHangProbes(); // The page booted before we got here, on a profile as new as the data // directory it sits in: it read "never seen" already. Record the tour and // boot it again, once, so every later reload finds the record too. @@ -389,9 +426,9 @@ export class BrowserPage { if (timeoutMs !== undefined || !(error instanceof Error) || !error.message.includes('timed out')) throw error; const state = await this.send('Runtime.evaluate', { expression: HUNG_PAGE, returnByValue: true, awaitPromise: true }, 3_000) .then((result) => JSON.stringify((result as { result?: { value?: unknown } }).result?.value)) - .catch(() => 'the page did not answer either: its main thread is busy'); + .catch(() => null); throw new Error(`${error.message} -Page: ${state} +Page: ${state === null ? `the page did not answer either: its main thread is busy\n${await this.#busyReport()}` : state} In flight: ${JSON.stringify(this.#inFlight())}`); })) as { result?: { value?: unknown }; @@ -434,8 +471,9 @@ In flight: ${JSON.stringify(this.#inFlight())}`); } if (this.#closed || !this.#socket.open) throw new Error('the browser is closed'); // A separate, bounded grace preserves useful diagnostics after the condition consumes its budget. - const state = await this.evaluate(`({ location: location.origin + location.pathname, ready: document.readyState, title: document.title, text: document.body?.innerText.slice(0, 500) })`, WAIT_DIAGNOSTIC_TIMEOUT_MS).catch(() => 'page diagnostic timed out'); - throw new Error(`waitFor timed out on ${expression}: ${last}\nPage: ${JSON.stringify(state)}\nErrors: ${JSON.stringify(this.#pageErrors)}\nIn flight: ${JSON.stringify(this.#inFlight())}\nFailed requests: ${JSON.stringify(this.#networkFailures)}`); + const state = await this.evaluate(`({ location: location.origin + location.pathname, ready: document.readyState, title: document.title, text: document.body?.innerText.slice(0, 500) })`, WAIT_DIAGNOSTIC_TIMEOUT_MS).catch(() => null); + const page = state === null ? `"page diagnostic timed out"\n${await this.#busyReport()}` : JSON.stringify(state); + throw new Error(`waitFor timed out on ${expression}: ${last}\nPage: ${page}\nErrors: ${JSON.stringify(this.#pageErrors)}\nIn flight: ${JSON.stringify(this.#inFlight())}\nFailed requests: ${JSON.stringify(this.#networkFailures)}`); } async navigate(url: string): Promise { @@ -571,16 +609,112 @@ In flight: ${JSON.stringify(this.#inFlight())}`); else if (this.#userDataDir !== null) await removeDirectory(this.#userDataDir); } + async #enableHangProbes(): Promise { + if (HANG_STACK) await this.send('Debugger.enable', {}); + } + + /** + * What holds a page whose main thread left a call unanswered, asked of what + * still answers. `Performance.getMetrics` is dispatched as a V8 interrupt, so + * it answers while JavaScript runs and waits like any call while the thread + * is in a layout, a synchronous IPC or a native wait (Edge 155, a busy loop + * against a synchronous XHR). The browser endpoint gives each process's CPU. + */ + async #busyReport(): Promise { + const asked = Date.now(); + if (await this.send('Runtime.evaluate', { expression: '1' }, 1_000).then(() => true, () => false)) { + return `Main thread: answered again ${Date.now() - asked} ms later`; + } + const interrupt = Date.now(); + const [inScript, cpu] = await Promise.all([ + this.send('Performance.getMetrics', {}, 1_000).then(() => Date.now() - interrupt, () => null), + this.#processCpu(), + ]); + const lines = [ + inScript === null + ? 'Main thread: not in JavaScript: Performance.getMetrics, a V8 interrupt, got no answer in 1 s either (a layout, a synchronous IPC or a native wait)' + : `Main thread: running JavaScript: Performance.getMetrics, a V8 interrupt, answered in ${inScript} ms`, + `CPU over 1 s: ${cpu}`, + ]; + if (HANG_STACK) lines.push(`Stack: ${await this.#pausedStack()}`); + return lines.join('\n'); + } + + /** Where the running script is, through the debugger `HANG_STACK` turned on at launch. */ + async #pausedStack(): Promise { + const paused = new Promise((resolve) => { this.#paused = resolve; }); + try { + await this.send('Debugger.pause', {}, 1_000); + return await Promise.race([paused, Bun.sleep(1_000).then(() => 'no pause within 1 s')]); + } catch (error) { + return `Debugger.pause failed: ${error instanceof Error ? error.message : String(error)}`; + } finally { + this.#paused = null; + await this.send('Debugger.resume', {}, 1_000).catch(() => undefined); + } + } + + /** CPU seconds per second of each process of the browser and of the runner's cores, over one second. */ + async #processCpu(): Promise { + if (this.#debugPort === null) return 'no browser endpoint'; + let socket: TextSocket | undefined; + try { + const version = await (await fetch(`http://127.0.0.1:${this.#debugPort}/json/version`, { signal: AbortSignal.timeout(1_000) })).json() as { webSocketDebuggerUrl?: string }; + if (version.webSocketDebuggerUrl === undefined) return 'the browser endpoint has no socket'; + const browser = socket = await TextSocket.connect(version.webSocketDebuggerUrl, 1_000); + const replies = new Map void>(); + browser.onMessage((text) => { + const message = JSON.parse(text) as { id?: number; result?: { processInfo?: ProcessInfo[] } }; + if (message.id !== undefined) replies.get(message.id)?.(message.result?.processInfo ?? []); + }); + const processes = (id: number) => new Promise((resolve, reject) => { + const timer = setTimeout(() => reject(new Error('SystemInfo.getProcessInfo timed out')), 1_000); + replies.set(id, (found) => { clearTimeout(timer); resolve(found); }); + browser.send(JSON.stringify({ id, method: 'SystemInfo.getProcessInfo', params: {} })); + }); + const runner = runnerCpu(); + const before = await processes(1); + const started = performance.now(); + await Bun.sleep(1_000); + const after = await processes(2); + const seconds = (performance.now() - started) / 1_000; + const used = after.map((process) => ({ process, rate: (process.cpuTime - (before.find((candidate) => candidate.id === process.id)?.cpuTime ?? 0)) / seconds })); + const busy = used.filter(({ rate }) => rate >= 0.05).map(({ process, rate }) => `${process.type} ${process.id} ${rate.toFixed(2)}`); + return `${busy.join(', ') || 'no process'} at 0.05 s/s or more, ${used.length - busy.length} below; ${await runner}`; + } catch (error) { + return `could not read it: ${error instanceof Error ? error.message : String(error)}`; + } finally { + socket?.close(); + } + } + /** What a stalled page is still waiting on: whether the server never answered or the body never arrived. */ #inFlight(): string[] { const now = Date.now(); - return [...this.#requests.values()].filter((request) => now - request.at > 1_000).slice(0, 10) - .map((request) => `${request.url} ${request.answered ? 'answered, body pending' : 'no response'} for ${now - request.at} ms`); + return [...this.#requests.values()].filter((request) => now - request.at > 1_000).slice(0, 10).map((request) => { + const wire = request.cache ? 'served from the cache' + : request.headers !== undefined ? `the network service had its headers ${request.headers - request.at} ms after it was sent` + : request.sent !== undefined ? 'the network service sent it and has no headers' + : 'nothing from the network service (not sent, or a service worker holds it)'; + const server = uiServerSide(request.url, request.at); + return `${request.url} ${request.answered ? 'answered, body pending' : 'no response'} for ${now - request.at} ms: ${wire}${server === null ? '' : `; ${server}`}`; + }); } #receive(raw: string): void { if (raw === '') return; - let frame: { id?: unknown; method?: string; params?: { exceptionDetails?: { text?: string; exception?: { description?: string } }; requestId?: string; request?: { url?: string }; response?: { status?: number }; errorText?: string }; result?: unknown; error?: { message?: string } }; + let frame: { + id?: unknown; + method?: string; + params?: { + exceptionDetails?: { text?: string; exception?: { description?: string } }; + requestId?: string; frameId?: string; loaderId?: string; request?: { url?: string }; response?: { status?: number }; errorText?: string; + frame?: { id: string; loaderId: string }; + callFrames?: { functionName: string; url: string; location: { lineNumber: number; columnNumber: number } }[]; + }; + result?: unknown; + error?: { message?: string }; + }; try { frame = JSON.parse(raw) as typeof frame; } catch { @@ -592,11 +726,43 @@ In flight: ${JSON.stringify(this.#inFlight())}`); this.#pageErrors.push(detail?.exception?.description ?? detail?.text ?? 'unknown page exception'); if (this.#pageErrors.length > 10) this.#pageErrors.shift(); } + if (frame.method === 'Debugger.paused') { + const frames = (frame.params?.callFrames ?? []).slice(0, 8) + .map((call) => `${call.functionName || '(anonymous)'} ${call.url}:${call.location.lineNumber + 1}:${call.location.columnNumber + 1}`).join(' < '); + // A pause nobody asked for, a `debugger` statement, must not freeze the page. + if (this.#paused !== null) this.#paused(frames || 'paused outside any script'); + else void this.send('Debugger.resume', {}).catch(() => undefined); + return; + } + if (frame.method === 'Page.frameNavigated') { + // Chrome sends nothing more about the requests of a document a + // navigation replaced: they would read as unanswered forever. + const navigated = frame.params?.frame; + if (navigated !== undefined) { + for (const [key, request] of this.#requests) if (request.frameId === navigated.id && request.loaderId !== navigated.loaderId) this.#requests.delete(key); + } + return; + } const id = frame.params?.requestId; if (id !== undefined) { const url = frame.params?.request?.url ?? ''; - if (frame.method === 'Network.requestWillBeSent' && !url.startsWith('data:')) this.#requests.set(id, { url, at: Date.now(), answered: false }); - else if (frame.method === 'Network.responseReceived') { + if (frame.method === 'Network.requestWillBeSent' && !url.startsWith('data:')) { + const early = this.#early.get(id); + this.#early.delete(id); + this.#requests.set(id, { url, at: Date.now(), answered: false, frameId: frame.params?.frameId, loaderId: frame.params?.loaderId, ...early }); + } else if (frame.method === 'Network.requestWillBeSentExtraInfo' || frame.method === 'Network.responseReceivedExtraInfo') { + // The browser process sends these, and not always after Blink's own event. + const step = frame.method === 'Network.requestWillBeSentExtraInfo' ? 'sent' : 'headers'; + const request = this.#requests.get(id); + if (request !== undefined) request[step] ??= Date.now(); + else { + if (this.#early.size > 500) this.#early.clear(); + this.#early.set(id, { ...this.#early.get(id), [step]: Date.now() }); + } + } else if (frame.method === 'Network.requestServedFromCache') { + const request = this.#requests.get(id); + if (request !== undefined) request.cache = true; + } else if (frame.method === 'Network.responseReceived') { const request = this.#requests.get(id); if (request) request.answered = true; if ((frame.params?.response?.status ?? 0) >= 400) this.#recordNetworkFailure(id, `HTTP ${frame.params?.response?.status}`); @@ -624,6 +790,36 @@ In flight: ${JSON.stringify(this.#inFlight())}`); } } +/** How long the runner's CPU reading may take: a cold WMI query took 2 s on a workstation. */ +const RUNNER_CPU_TIMEOUT_MS = 5_000; + +/** + * The runner's CPU over about a second and its busiest processes, another + * browser or a scanner among them. Bun 1.4's `os.cpus()` times do not move on + * Windows, so there they come from WMI's formatted counters. + */ +async function runnerCpu(): Promise { + const cores = cpus().length; + if (process.platform !== 'win32') { + const total = (list: ReturnType) => list.reduce((sum, core) => sum + Object.values(core.times).reduce((a, b) => a + b, 0), 0); + const idle = (list: ReturnType) => list.reduce((sum, core) => sum + core.times.idle, 0); + const before = cpus(); + await Bun.sleep(1_000); + const after = cpus(); + return `runner ${Math.round(100 * (1 - (idle(after) - idle(before)) / Math.max(1, total(after) - total(before))))} % of ${cores} cores`; + } + try { + const query = Bun.spawn(['powershell', '-NoProfile', '-Command', + `$total = (Get-CimInstance Win32_PerfFormattedData_PerfOS_Processor -Filter "Name='_Total'").PercentProcessorTime; $top = Get-CimInstance Win32_PerfFormattedData_PerfProc_Process | Where-Object { $_.Name -notin '_Total', 'Idle' } | Sort-Object PercentProcessorTime -Descending | Select-Object -First 6 | ForEach-Object { "$($_.Name) $($_.PercentProcessorTime) %" }; "runner $total % of ${cores} cores, busiest processes (% of one core): $($top -join ', ')"`, + ], { stdout: 'pipe', stderr: 'pipe', windowsHide: true, timeout: RUNNER_CPU_TIMEOUT_MS }); + const [stdout, stderr] = await Promise.all([new Response(query.stdout).text(), new Response(query.stderr).text(), query.exited]); + if (query.signalCode !== null) return `no runner CPU within ${RUNNER_CPU_TIMEOUT_MS} ms`; + return stdout.trim() || `no runner CPU; powershell said: ${stderr.slice(0, 200)}`; + } catch (error) { + return `no runner CPU: ${error instanceof Error ? error.message : String(error)}`; + } +} + async function waitForPageTarget(port: number, urlIncludes = '', proc?: Subprocess, allowBlank = false): Promise { const started = Date.now(); const deadline = started + CONNECT_TIMEOUT_MS; diff --git a/tests/e2e/lib/ui-requests.ts b/tests/e2e/lib/ui-requests.ts new file mode 100644 index 000000000..d30f65bf0 --- /dev/null +++ b/tests/e2e/lib/ui-requests.ts @@ -0,0 +1,53 @@ +import type { IncomingMessage, ServerResponse } from 'node:http'; + +/** + * What the Vite servers of this test process did with each request, for a + * browser wait that fails with requests still in flight: whether the UI server + * got the request, answered it and when. `lib/ui.ts` and `lib/warm.ts` put + * `requestLog` on every server they start; `BrowserPage` reads `uiServerSide`. + */ +interface Served { port: number; path: string; at: number; status?: number; finished?: number; closed?: number } + +/** The newest requests across every server of the process: a shard's files run in one. */ +const MAX_SERVED = 4_000; +const served: Served[] = []; +const ports = new Set(); + +type Middleware = (req: IncomingMessage, res: ServerResponse, next: () => void) => void; +interface WithMiddlewares { middlewares: { use(handler: Middleware): unknown } } + +function record(req: IncomingMessage, res: ServerResponse, next: () => void): void { + const port = req.socket.localPort ?? 0; + const entry: Served = { port, path: req.url ?? '', at: Date.now() }; + ports.add(port); + served.push(entry); + if (served.length > MAX_SERVED) served.splice(0, served.length - MAX_SERVED); + res.once('finish', () => { entry.finished = Date.now(); entry.status = res.statusCode; }); + res.once('close', () => { entry.closed = Date.now(); }); + next(); +} + +/** Added first, so it sees every request, the ones Vite's own middlewares answer included. */ +export const requestLog = { + name: 'boite-e2e-request-log', + configureServer(server: WithMiddlewares) { server.middlewares.use(record); }, + configurePreviewServer(server: WithMiddlewares) { server.middlewares.use(record); }, +}; + +/** + * The UI server's side of a request the browser sent at `sentAt`, or null when + * no server of this process listens on its port (a core serves that page). + */ +export function uiServerSide(url: string, sentAt: number): string | null { + let parsed: URL; + try { parsed = new URL(url); } catch { return null; } + const port = Number(parsed.port); + if (!ports.has(port)) return null; + const path = parsed.pathname + parsed.search; + // Same process, same clock: the server cannot see it before the browser sent it. + const entry = served.findLast((candidate) => candidate.port === port && candidate.path === path && candidate.at >= sentAt - 5); + if (entry === undefined) return 'the UI server never got it'; + if (entry.finished !== undefined) return `the UI server answered ${entry.status} ${entry.finished - sentAt} ms after it was sent`; + if (entry.closed !== undefined) return `the UI server's connection closed ${entry.closed - sentAt} ms after it was sent, before the answer was written`; + return `the UI server got it ${entry.at - sentAt} ms after it was sent and is still answering`; +} diff --git a/tests/e2e/lib/ui.ts b/tests/e2e/lib/ui.ts index fe046efc4..cc2c988ed 100644 --- a/tests/e2e/lib/ui.ts +++ b/tests/e2e/lib/ui.ts @@ -1,6 +1,7 @@ import { createRequire } from 'node:module'; import { existsSync } from 'node:fs'; import { join, resolve } from 'node:path'; +import { requestLog } from './ui-requests.ts'; const root = join(import.meta.dir, '../../../packages/ui'); const requireUi = createRequire(join(root, 'package.json')); @@ -25,14 +26,14 @@ export async function startUi(port: number, options: { development?: boolean } = if (shared && !options.development) { // Built once by `lib/warm.ts` before a parallel run. if (!existsSync(join(shared, 'index.html'))) throw new Error(`BOITE_E2E_FAKE_UI=${shared} holds no index.html; build it with bun tests/e2e/lib/warm.ts ${shared}`); - return preview({ root, build: { outDir: resolve(shared) }, preview: address, clearScreen: false }); + return preview({ root, plugins: [requestLog], build: { outDir: resolve(shared) }, preview: address, clearScreen: false }); } if (process.env.BOITE_E2E_PREBUILT_UI === '1' && !options.development) { // Production intentionally excludes ?fake=1. This separate test bundle // enables it without changing the UI staged in the installer. fixtureBuild ??= build({ root, plugins: [fixtureBridge], define: { 'import.meta.env.DEV': 'true' }, build: { outDir: fixtureDir, emptyOutDir: true }, logLevel: 'warn' }); await fixtureBuild; - return preview({ root, build: { outDir: fixtureDir }, preview: address, clearScreen: false }); + return preview({ root, plugins: [requestLog], build: { outDir: fixtureDir }, preview: address, clearScreen: false }); } return startDevUi(port); } @@ -45,7 +46,7 @@ export async function startUi(port: number, options: { development?: boolean } = * hook gets. */ export async function startDevUi(port: number): Promise<{ close(): Promise }> { - const server = await createServer({ root, plugins: [fixtureBridge], server: { host: '127.0.0.1', port, strictPort: true }, clearScreen: false }); + const server = await createServer({ root, plugins: [fixtureBridge, requestLog], server: { host: '127.0.0.1', port, strictPort: true }, clearScreen: false }); try { await server.listen(); await transformAll(server, '/src/main.ts'); diff --git a/tests/e2e/lib/warm.ts b/tests/e2e/lib/warm.ts index 481cad074..9e3976637 100644 --- a/tests/e2e/lib/warm.ts +++ b/tests/e2e/lib/warm.ts @@ -40,6 +40,7 @@ async function prepare(): Promise { const { build, createServer } = await preparationStep('load Vite', () => import(createRequire(join(root, 'package.json')).resolve('vite'))); const { fixtureBridge } = await preparationStep('load fixture bridge', () => import('./ui.ts')); + const { requestLog } = await import('./ui-requests.ts'); const buildFakeUi = () => preparationStep('build fake UI', async () => { await build({ root, plugins: [fixtureBridge], define: { 'import.meta.env.DEV': 'true' }, build: { outDir: resolve(outDir!), emptyOutDir: true }, logLevel: 'warn' }); }); @@ -50,7 +51,7 @@ async function prepare(): Promise { // Match startDevUi's plugins: Vite hashes them into the optimized-dependency cache. const server = await preparationStep('create dev server', async () => - createServer({ root, plugins: [fixtureBridge], server: { host: '127.0.0.1', port: await freePort(), strictPort: true }, clearScreen: false })); + createServer({ root, plugins: [fixtureBridge, requestLog], server: { host: '127.0.0.1', port: await freePort(), strictPort: true }, clearScreen: false })); try { await preparationStep('listen', () => server.listen()); const base = server.resolvedUrls?.local[0]?.replace(/\/$/, ''); From 581bad5cb4273c40a420dce485c8af45c4fc4e28 Mon Sep 17 00:00:00 2001 From: meetsu <96637888+klNuno@users.noreply.github.com> Date: Mon, 19 Oct 2026 18:33:46 +0200 Subject: [PATCH 2/7] test(e2e): fail CDP calls at once on a devtools message that is not JSON Bun's WebSocket client, once misaligned, handed over pieces of frames. #receive dropped them in silence, so the replies and network events inside never came: the call and its probe timed out, the page read as "main thread busy" and its lazy chunks as "no response". Now the first such message fails what waits and every later call with its content, and hangs up. --- tests/e2e/cdp-attach.test.ts | 28 ++++++++++++++++++++++++++++ tests/e2e/lib/cdp.ts | 24 ++++++++++++++++++++++++ 2 files changed, 52 insertions(+) diff --git a/tests/e2e/cdp-attach.test.ts b/tests/e2e/cdp-attach.test.ts index a4c5d2243..f477a45f1 100644 --- a/tests/e2e/cdp-attach.test.ts +++ b/tests/e2e/cdp-attach.test.ts @@ -29,6 +29,34 @@ test.each(['ready', 'delayed', 'explicit-blank'] as const)('attach chooses the r } finally { await page?.close(); await server.stop(true); } }); +test('a devtools message that is not JSON fails the waiting call at once and every later one, naming it', async () => { + // What Bun's WebSocket client handed over once it lost frame alignment: a + // piece of a frame. Dropped in silence, the reply inside it never came and + // the call waited out its 20 s like a page with a busy main thread. + const server = Bun.serve({ hostname: '127.0.0.1', port: 0, + fetch(request, self) { + if (new URL(request.url).pathname === '/json/list') return Response.json([{ type: 'page', url: 'http://tauri.localhost/', webSocketDebuggerUrl: `ws://127.0.0.1:${self.port}/app` }]); + return self.upgrade(request) ? undefined : new Response('upgrade required'); + }, websocket: { + message(socket, raw) { + const frame = JSON.parse(String(raw)) as { id: number; method: string; params?: { expression?: string } }; + if (frame.params?.expression === 'garbled') socket.send(`{"id":${frame.id},"result":{"res`); + else socket.send(JSON.stringify({ id: frame.id, result: frame.method === 'Runtime.evaluate' ? { result: { value: false } } : {} })); + }, + }, + }); + let page: BrowserPage | undefined; + try { + page = await BrowserPage.attach(server.port!); + const started = performance.now(); + const failure = await page.evaluate('garbled').then(() => 'answered', (error: unknown) => String(error)); + expect(failure).toContain('devtools sent a message that is not JSON ('); + expect(failure).toContain('{\\"res'); + expect(performance.now() - started).toBeLessThan(2_000); + expect(await page.evaluate('1').then(() => 'answered', (error: unknown) => String(error))).toContain('not JSON'); + } finally { await page?.close(); await server.stop(true); } +}, 10_000); + test('the failure probe tells a closed port at once from one that accepts and never answers', async () => { const closed = await freePort(); let startedAt = Date.now(); diff --git a/tests/e2e/lib/cdp.ts b/tests/e2e/lib/cdp.ts index c4fa8c2e7..a2feeec6b 100644 --- a/tests/e2e/lib/cdp.ts +++ b/tests/e2e/lib/cdp.ts @@ -189,6 +189,12 @@ export class BrowserPage { #nextId = 1; #pending = new Map(); #closed = false; + /** + * Set once devtools sent a message that is not JSON. Chrome never does: the + * socket lost its frame alignment, so replies may be gone and every later + * call fails with this instead of waiting out its timeout. + */ + #fault: string | null = null; #pageErrors: string[] = []; /** * Requests the page's current documents sent and have not finished loading, @@ -392,6 +398,7 @@ export class BrowserPage { /** The one place raw devtools JSON is handled. */ send(method: string, params: Record, timeoutMs = CALL_TIMEOUT_MS): Promise { if (this.#closed) return Promise.reject(new Error('the browser is closed')); + if (this.#fault !== null) return Promise.reject(new Error(this.#fault)); // A send on a closed socket is dropped without an error, and each call then // waited out its whole timeout: after `bun test` killed the browser of a // file whose test timed out, every later test of that file spent 20 s on a @@ -701,6 +708,18 @@ In flight: ${JSON.stringify(this.#inFlight())}`); }); } + /** Fails what waits and what comes next with the message devtools sent, then hangs up. */ + #protocolFault(raw: string): void { + if (this.#fault !== null) return; + this.#fault = `devtools sent a message that is not JSON (${raw.length} chars: ${JSON.stringify(raw.slice(0, 120))}): the socket lost its frames, so replies and network events may be missing`; + for (const pending of this.#pending.values()) { + clearTimeout(pending.timer); + pending.reject(new Error(this.#fault)); + } + this.#pending.clear(); + this.#socket.close(1002); + } + #receive(raw: string): void { if (raw === '') return; let frame: { @@ -718,6 +737,11 @@ In flight: ${JSON.stringify(this.#inFlight())}`); try { frame = JSON.parse(raw) as typeof frame; } catch { + // Bun's WebSocket client did this on the E2E runner: misaligned, it handed + // over pieces of frames, and dropping them silently lost the replies and + // network events inside. Each call then timed out, its probe too, and the + // page read as "main thread busy" with its lazy chunks "no response". + this.#protocolFault(raw); return; } if (typeof frame.id !== 'number') { From 90a646cd3d4974115608d6e6ae22ca7259a40fa3 Mon Sep 17 00:00:00 2001 From: meetsu <96637888+klNuno@users.noreply.github.com> Date: Mon, 19 Oct 2026 18:33:46 +0200 Subject: [PATCH 3/7] ci: take coordination-bridge-live out of quarantine Its two failures, "the browser is closed" and the hung settings click with lazy chunks unanswered, came from Bun's WebSocket client (#650). On windows-2025 with the Bun.connect client it passed 40 of 40 (run 39261835228) and 200 of 200 (run 39278866794). --- scripts/ci/quarantine.json | 5 ----- 1 file changed, 5 deletions(-) diff --git a/scripts/ci/quarantine.json b/scripts/ci/quarantine.json index 6c348312b..2c1fe433c 100644 --- a/scripts/ci/quarantine.json +++ b/scripts/ci/quarantine.json @@ -35,11 +35,6 @@ "test": "thread jobs of forgotten threads > an id minted per call leaves no Job Object behind once the registry forgets it", "reason": "failed 4 first attempts that passed on rerun (Windows), 2026-10-16 to 10-18" }, - { - "file": "tests/e2e/coordination-bridge-live.test.ts", - "test": "the owner app relays signed reads, preserves directional grants on reload, and displays actual turn activity", - "reason": "failed 8 first attempts that passed on rerun, its lazy UI chunks getting no response for 15 s, 2026-10-16 to 10-18" - }, { "file": "tests/e2e/drafts-overlays.test.ts", "test": "drafts survive reload and composer menus stay above the chrome", From bb99663174ddb647428c1c8be2d218f7977b800a Mon Sep 17 00:00:00 2001 From: meetsu <96637888+klNuno@users.noreply.github.com> Date: Mon, 19 Oct 2026 19:04:39 +0200 Subject: [PATCH 4/7] test(e2e): keep a waitFor's diagnostic within its 250 ms grace The busy report ran there too and its WMI query took the blocked-renderer case of browser-deadlines.test.ts from under 1 s to 6.4 s (run 39288422031). waitFor is back to main's bounded probe; evaluate's report runs its probes side by side, without the runner's CPU, and adds about 1 s. --- tests/e2e/lib/cdp.ts | 62 +++++++++++--------------------------------- 1 file changed, 15 insertions(+), 47 deletions(-) diff --git a/tests/e2e/lib/cdp.ts b/tests/e2e/lib/cdp.ts index a2feeec6b..0e3b2527d 100644 --- a/tests/e2e/lib/cdp.ts +++ b/tests/e2e/lib/cdp.ts @@ -1,6 +1,6 @@ import { existsSync, mkdirSync, mkdtempSync, writeFileSync } from 'node:fs'; import { createConnection, createServer } from 'node:net'; -import { cpus, tmpdir } from 'node:os'; +import { tmpdir } from 'node:os'; import { dirname, join } from 'node:path'; import { ONBOARDING_STORAGE_KEY, ONBOARDING_VERSION } from '../../../packages/ui/src/lib/onboarding.ts'; import type { Subprocess } from 'bun'; @@ -478,9 +478,8 @@ In flight: ${JSON.stringify(this.#inFlight())}`); } if (this.#closed || !this.#socket.open) throw new Error('the browser is closed'); // A separate, bounded grace preserves useful diagnostics after the condition consumes its budget. - const state = await this.evaluate(`({ location: location.origin + location.pathname, ready: document.readyState, title: document.title, text: document.body?.innerText.slice(0, 500) })`, WAIT_DIAGNOSTIC_TIMEOUT_MS).catch(() => null); - const page = state === null ? `"page diagnostic timed out"\n${await this.#busyReport()}` : JSON.stringify(state); - throw new Error(`waitFor timed out on ${expression}: ${last}\nPage: ${page}\nErrors: ${JSON.stringify(this.#pageErrors)}\nIn flight: ${JSON.stringify(this.#inFlight())}\nFailed requests: ${JSON.stringify(this.#networkFailures)}`); + const state = await this.evaluate(`({ location: location.origin + location.pathname, ready: document.readyState, title: document.title, text: document.body?.innerText.slice(0, 500) })`, WAIT_DIAGNOSTIC_TIMEOUT_MS).catch(() => 'page diagnostic timed out'); + throw new Error(`waitFor timed out on ${expression}: ${last}\nPage: ${JSON.stringify(state)}\nErrors: ${JSON.stringify(this.#pageErrors)}\nIn flight: ${JSON.stringify(this.#inFlight())}\nFailed requests: ${JSON.stringify(this.#networkFailures)}`); } async navigate(url: string): Promise { @@ -626,24 +625,24 @@ In flight: ${JSON.stringify(this.#inFlight())}`); * it answers while JavaScript runs and waits like any call while the thread * is in a layout, a synchronous IPC or a native wait (Edge 155, a busy loop * against a synchronous XHR). The browser endpoint gives each process's CPU. + * The probes run side by side, so the report adds about a second. */ async #busyReport(): Promise { const asked = Date.now(); - if (await this.send('Runtime.evaluate', { expression: '1' }, 1_000).then(() => true, () => false)) { - return `Main thread: answered again ${Date.now() - asked} ms later`; - } - const interrupt = Date.now(); - const [inScript, cpu] = await Promise.all([ - this.send('Performance.getMetrics', {}, 1_000).then(() => Date.now() - interrupt, () => null), + const [again, inScript, cpu] = await Promise.all([ + this.send('Runtime.evaluate', { expression: '1' }, 1_000).then(() => Date.now() - asked, () => null), + this.send('Performance.getMetrics', {}, 1_000).then(() => Date.now() - asked, () => null), this.#processCpu(), ]); const lines = [ - inScript === null - ? 'Main thread: not in JavaScript: Performance.getMetrics, a V8 interrupt, got no answer in 1 s either (a layout, a synchronous IPC or a native wait)' - : `Main thread: running JavaScript: Performance.getMetrics, a V8 interrupt, answered in ${inScript} ms`, + again !== null + ? `Main thread: answered again ${again} ms later` + : inScript === null + ? 'Main thread: not in JavaScript: Performance.getMetrics, a V8 interrupt, got no answer in 1 s either (a layout, a synchronous IPC or a native wait)' + : `Main thread: running JavaScript: Performance.getMetrics, a V8 interrupt, answered in ${inScript} ms`, `CPU over 1 s: ${cpu}`, ]; - if (HANG_STACK) lines.push(`Stack: ${await this.#pausedStack()}`); + if (HANG_STACK && again === null) lines.push(`Stack: ${await this.#pausedStack()}`); return lines.join('\n'); } @@ -661,7 +660,7 @@ In flight: ${JSON.stringify(this.#inFlight())}`); } } - /** CPU seconds per second of each process of the browser and of the runner's cores, over one second. */ + /** CPU seconds per second of each process of the browser, over one second. */ async #processCpu(): Promise { if (this.#debugPort === null) return 'no browser endpoint'; let socket: TextSocket | undefined; @@ -679,7 +678,6 @@ In flight: ${JSON.stringify(this.#inFlight())}`); replies.set(id, (found) => { clearTimeout(timer); resolve(found); }); browser.send(JSON.stringify({ id, method: 'SystemInfo.getProcessInfo', params: {} })); }); - const runner = runnerCpu(); const before = await processes(1); const started = performance.now(); await Bun.sleep(1_000); @@ -687,7 +685,7 @@ In flight: ${JSON.stringify(this.#inFlight())}`); const seconds = (performance.now() - started) / 1_000; const used = after.map((process) => ({ process, rate: (process.cpuTime - (before.find((candidate) => candidate.id === process.id)?.cpuTime ?? 0)) / seconds })); const busy = used.filter(({ rate }) => rate >= 0.05).map(({ process, rate }) => `${process.type} ${process.id} ${rate.toFixed(2)}`); - return `${busy.join(', ') || 'no process'} at 0.05 s/s or more, ${used.length - busy.length} below; ${await runner}`; + return `${busy.join(', ') || 'no process'} at 0.05 s/s or more, ${used.length - busy.length} below`; } catch (error) { return `could not read it: ${error instanceof Error ? error.message : String(error)}`; } finally { @@ -814,36 +812,6 @@ In flight: ${JSON.stringify(this.#inFlight())}`); } } -/** How long the runner's CPU reading may take: a cold WMI query took 2 s on a workstation. */ -const RUNNER_CPU_TIMEOUT_MS = 5_000; - -/** - * The runner's CPU over about a second and its busiest processes, another - * browser or a scanner among them. Bun 1.4's `os.cpus()` times do not move on - * Windows, so there they come from WMI's formatted counters. - */ -async function runnerCpu(): Promise { - const cores = cpus().length; - if (process.platform !== 'win32') { - const total = (list: ReturnType) => list.reduce((sum, core) => sum + Object.values(core.times).reduce((a, b) => a + b, 0), 0); - const idle = (list: ReturnType) => list.reduce((sum, core) => sum + core.times.idle, 0); - const before = cpus(); - await Bun.sleep(1_000); - const after = cpus(); - return `runner ${Math.round(100 * (1 - (idle(after) - idle(before)) / Math.max(1, total(after) - total(before))))} % of ${cores} cores`; - } - try { - const query = Bun.spawn(['powershell', '-NoProfile', '-Command', - `$total = (Get-CimInstance Win32_PerfFormattedData_PerfOS_Processor -Filter "Name='_Total'").PercentProcessorTime; $top = Get-CimInstance Win32_PerfFormattedData_PerfProc_Process | Where-Object { $_.Name -notin '_Total', 'Idle' } | Sort-Object PercentProcessorTime -Descending | Select-Object -First 6 | ForEach-Object { "$($_.Name) $($_.PercentProcessorTime) %" }; "runner $total % of ${cores} cores, busiest processes (% of one core): $($top -join ', ')"`, - ], { stdout: 'pipe', stderr: 'pipe', windowsHide: true, timeout: RUNNER_CPU_TIMEOUT_MS }); - const [stdout, stderr] = await Promise.all([new Response(query.stdout).text(), new Response(query.stderr).text(), query.exited]); - if (query.signalCode !== null) return `no runner CPU within ${RUNNER_CPU_TIMEOUT_MS} ms`; - return stdout.trim() || `no runner CPU; powershell said: ${stderr.slice(0, 200)}`; - } catch (error) { - return `no runner CPU: ${error instanceof Error ? error.message : String(error)}`; - } -} - async function waitForPageTarget(port: number, urlIncludes = '', proc?: Subprocess, allowBlank = false): Promise { const started = Date.now(); const deadline = started + CONNECT_TIMEOUT_MS; From db6a0de2a45088a5d3557163daa3dd5369146562 Mon Sep 17 00:00:00 2001 From: meetsu <96637888+klNuno@users.noreply.github.com> Date: Mon, 19 Oct 2026 19:36:51 +0200 Subject: [PATCH 5/7] test(e2e): match UI server requests on Chrome's send time, not devtools delivery --- tests/e2e/cdp-attach.test.ts | 42 +++++++++++++++++++++++++++++++++++- tests/e2e/lib/cdp.ts | 20 +++++++++++------ tests/e2e/lib/ui-requests.ts | 36 ++++++++++++++++++++++++------- 3 files changed, 82 insertions(+), 16 deletions(-) diff --git a/tests/e2e/cdp-attach.test.ts b/tests/e2e/cdp-attach.test.ts index f477a45f1..9a90ef024 100644 --- a/tests/e2e/cdp-attach.test.ts +++ b/tests/e2e/cdp-attach.test.ts @@ -1,6 +1,9 @@ -import { createServer, type Socket } from 'node:net'; +import { createServer as createHttpServer, type IncomingMessage, type ServerResponse } from 'node:http'; +import { createServer, type AddressInfo, type Socket } from 'node:net'; +import type { ServerWebSocket } from 'bun'; import { expect, test } from 'bun:test'; import { BrowserPage, freePort, probeDebuggingPort } from './lib/cdp.ts'; +import { requestLog } from './lib/ui-requests.ts'; test.each(['ready', 'delayed', 'explicit-blank'] as const)('attach chooses the requested committed target (%s)', async mode => { let lists = 0; @@ -57,6 +60,43 @@ test('a devtools message that is not JSON fails the waiting call at once and eve } finally { await page?.close(); await server.stop(true); } }, 10_000); +test('a request the UI server answered before its devtools event arrived is reported answered, from its send time', async () => { + let middleware: ((request: IncomingMessage, response: ServerResponse, next: () => void) => void) | undefined; + requestLog.configureServer({ middlewares: { use(handler) { middleware = handler; } } }); + const ui = createHttpServer((request, response) => middleware!(request, response, () => response.end('export {}'))); + await new Promise((resolve) => ui.listen(0, '127.0.0.1', resolve)); + const base = `http://127.0.0.1:${(ui.address() as AddressInfo).port}`; + let devtools: ServerWebSocket | undefined; + const server = Bun.serve({ hostname: '127.0.0.1', port: 0, + fetch(request, self) { + if (new URL(request.url).pathname === '/json/list') return Response.json([{ type: 'page', url: 'http://tauri.localhost/', webSocketDebuggerUrl: `ws://127.0.0.1:${self.port}/app` }]); + return self.upgrade(request) ? undefined : new Response('upgrade required'); + }, websocket: { + open(socket) { devtools = socket; }, + message(socket, raw) { + const frame = JSON.parse(String(raw)) as { id: number; method: string }; + socket.send(JSON.stringify({ id: frame.id, result: frame.method === 'Runtime.evaluate' ? { result: { value: false } } : {} })); + }, + }, + }); + let page: BrowserPage | undefined; + try { + page = await BrowserPage.attach(server.port!); + const sent = Date.now(); + for (const chunk of ['RightPanel.js', 'CommandPalette.js']) expect(await (await fetch(`${base}/assets/${chunk}`)).text()).toBe('export {}'); + // A loaded runner: the server answered both before devtools reported them. + await Bun.sleep(30); + const willBeSent = (requestId: string, chunk: string, wallTime?: number) => JSON.stringify({ method: 'Network.requestWillBeSent', params: { requestId, loaderId: 'l', frameId: 'f', wallTime, request: { url: `${base}/assets/${chunk}` } } }); + devtools!.send(willBeSent('1', 'RightPanel.js', sent / 1_000)); + devtools!.send(willBeSent('2', 'CommandPalette.js')); + const failure = await page.waitFor('false', 1_300).then(() => 'answered', (error: unknown) => String(error)); + const line = (chunk: string) => failure.split('","').find((entry) => entry.includes(chunk)) ?? `no line for ${chunk} in ${failure}`; + expect(line('RightPanel.js')).toMatch(/; the UI server answered 200 \d+ ms after it was sent/); + expect(line('CommandPalette.js')).toMatch(/; no send time; newest record: the UI server answered 200 \d+ ms before devtools reported it/); + expect(failure).not.toContain('never got it'); + } finally { await page?.close(); await server.stop(true); ui.close(); } +}, 10_000); + test('the failure probe tells a closed port at once from one that accepts and never answers', async () => { const closed = await freePort(); let startedAt = Date.now(); diff --git a/tests/e2e/lib/cdp.ts b/tests/e2e/lib/cdp.ts index 0e3b2527d..1d00627b1 100644 --- a/tests/e2e/lib/cdp.ts +++ b/tests/e2e/lib/cdp.ts @@ -106,7 +106,10 @@ interface Pending { interface InFlight { url: string; + /** When its devtools event reached us, which can be after the server answered it. */ at: number; + /** When Chrome sent it (`wallTime`), on the same clock as `Date.now()`. */ + wall?: number; answered: boolean; frameId?: string; loaderId?: string; @@ -625,7 +628,8 @@ In flight: ${JSON.stringify(this.#inFlight())}`); * it answers while JavaScript runs and waits like any call while the thread * is in a layout, a synchronous IPC or a native wait (Edge 155, a busy loop * against a synchronous XHR). The browser endpoint gives each process's CPU. - * The probes run side by side, so the report adds about a second. + * The probes run side by side: about a second, up to 5 s when the browser + * endpoint answers slowly (its fetch, upgrade and two calls have 1 s each). */ async #busyReport(): Promise { const asked = Date.now(); @@ -696,13 +700,14 @@ In flight: ${JSON.stringify(this.#inFlight())}`); /** What a stalled page is still waiting on: whether the server never answered or the body never arrived. */ #inFlight(): string[] { const now = Date.now(); - return [...this.#requests.values()].filter((request) => now - request.at > 1_000).slice(0, 10).map((request) => { + return [...this.#requests.values()].filter((request) => now - (request.wall ?? request.at) > 1_000).slice(0, 10).map((request) => { + const sentAt = request.wall ?? request.at; const wire = request.cache ? 'served from the cache' - : request.headers !== undefined ? `the network service had its headers ${request.headers - request.at} ms after it was sent` + : request.headers !== undefined ? `the network service had its headers by ${request.headers - sentAt} ms after it was sent` : request.sent !== undefined ? 'the network service sent it and has no headers' : 'nothing from the network service (not sent, or a service worker holds it)'; - const server = uiServerSide(request.url, request.at); - return `${request.url} ${request.answered ? 'answered, body pending' : 'no response'} for ${now - request.at} ms: ${wire}${server === null ? '' : `; ${server}`}`; + const server = uiServerSide(request.url, request.wall ?? null, request.at); + return `${request.url} ${request.answered ? 'answered, body pending' : 'no response'} for ${now - sentAt} ms: ${wire}${server === null ? '' : `; ${server}`}`; }); } @@ -725,7 +730,7 @@ In flight: ${JSON.stringify(this.#inFlight())}`); method?: string; params?: { exceptionDetails?: { text?: string; exception?: { description?: string } }; - requestId?: string; frameId?: string; loaderId?: string; request?: { url?: string }; response?: { status?: number }; errorText?: string; + requestId?: string; frameId?: string; loaderId?: string; wallTime?: number; request?: { url?: string }; response?: { status?: number }; errorText?: string; frame?: { id: string; loaderId: string }; callFrames?: { functionName: string; url: string; location: { lineNumber: number; columnNumber: number } }[]; }; @@ -771,7 +776,8 @@ In flight: ${JSON.stringify(this.#inFlight())}`); if (frame.method === 'Network.requestWillBeSent' && !url.startsWith('data:')) { const early = this.#early.get(id); this.#early.delete(id); - this.#requests.set(id, { url, at: Date.now(), answered: false, frameId: frame.params?.frameId, loaderId: frame.params?.loaderId, ...early }); + const wallTime = frame.params?.wallTime; + this.#requests.set(id, { url, at: Date.now(), wall: typeof wallTime === 'number' ? wallTime * 1_000 : undefined, answered: false, frameId: frame.params?.frameId, loaderId: frame.params?.loaderId, ...early }); } else if (frame.method === 'Network.requestWillBeSentExtraInfo' || frame.method === 'Network.responseReceivedExtraInfo') { // The browser process sends these, and not always after Blink's own event. const step = frame.method === 'Network.requestWillBeSentExtraInfo' ? 'sent' : 'headers'; diff --git a/tests/e2e/lib/ui-requests.ts b/tests/e2e/lib/ui-requests.ts index d30f65bf0..e4e2727aa 100644 --- a/tests/e2e/lib/ui-requests.ts +++ b/tests/e2e/lib/ui-requests.ts @@ -34,20 +34,40 @@ export const requestLog = { configurePreviewServer(server: WithMiddlewares) { server.middlewares.use(record); }, }; +/** Chrome's `wallTime` and `Date.now()` read the same system clock, in ticks that can be coarse on Windows. */ +const CLOCK_SLACK_MS = 50; + +function relative(time: number, reference: number, what: string): string { + const ms = time - reference; + return `${Math.abs(ms)} ms ${ms < 0 ? 'before' : 'after'} ${what}`; +} + +function describe(entry: Served, reference: number, what: string): string { + if (entry.finished !== undefined) return `the UI server answered ${entry.status} ${relative(entry.finished, reference, what)}`; + if (entry.closed !== undefined) return `the UI server's connection closed ${relative(entry.closed, reference, what)}, before the answer was written`; + return `the UI server got it ${relative(entry.at, reference, what)} and is still answering`; +} + /** - * The UI server's side of a request the browser sent at `sentAt`, or null when - * no server of this process listens on its port (a core serves that page). + * The UI server's side of a request Chrome sent at `sentAt` (its `wallTime`), + * or null when no server of this process listens on its port (a core serves + * that page). Without a send time, only the newest record of the path can be + * told, against `receivedAt`, when its devtools event reached us: that event + * can come after the server answered, so no window can rule the server out. */ -export function uiServerSide(url: string, sentAt: number): string | null { +export function uiServerSide(url: string, sentAt: number | null, receivedAt: number): string | null { let parsed: URL; try { parsed = new URL(url); } catch { return null; } const port = Number(parsed.port); if (!ports.has(port)) return null; const path = parsed.pathname + parsed.search; - // Same process, same clock: the server cannot see it before the browser sent it. - const entry = served.findLast((candidate) => candidate.port === port && candidate.path === path && candidate.at >= sentAt - 5); + if (sentAt === null) { + const newest = served.findLast((candidate) => candidate.port === port && candidate.path === path); + if (newest === undefined) return 'the UI server has no record of it'; + return `no send time; newest record: ${describe(newest, receivedAt, 'devtools reported it')}`; + } + // The server cannot see it before Chrome sent it. + const entry = served.findLast((candidate) => candidate.port === port && candidate.path === path && candidate.at >= sentAt - CLOCK_SLACK_MS); if (entry === undefined) return 'the UI server never got it'; - if (entry.finished !== undefined) return `the UI server answered ${entry.status} ${entry.finished - sentAt} ms after it was sent`; - if (entry.closed !== undefined) return `the UI server's connection closed ${entry.closed - sentAt} ms after it was sent, before the answer was written`; - return `the UI server got it ${entry.at - sentAt} ms after it was sent and is still answering`; + return describe(entry, sentAt, 'it was sent'); } From 951b0f1537d3ed9ebcd4ebf3fb8abe54360c891d Mon Sep 17 00:00:00 2001 From: meetsu <96637888+klNuno@users.noreply.github.com> Date: Mon, 19 Oct 2026 19:36:52 +0200 Subject: [PATCH 6/7] docs(ci): CodeRabbit reviews drafts --- docs/ci.md | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/docs/ci.md b/docs/ci.md index ee545298b..e3634788a 100644 --- a/docs/ci.md +++ b/docs/ci.md @@ -467,9 +467,10 @@ domain's DNS names `beboite.github.io`. ## Pull request reviews -`.coderabbit.yaml` enables advisory reviews and chat replies, excluding drafts -and generated artifacts. CodeRabbit is not a required check. Its installed App, -plan eligibility and quotas are external prerequisites. +`.coderabbit.yaml` enables advisory reviews and chat replies, drafts included +(`auto_review.drafts`), and skips generated artifacts. CodeRabbit is not a +required check. Its installed App, plan eligibility and quotas are external +prerequisites. Follow the [PR rules](../AGENTS.md#follow-through-on-pull-requests): inspect CI and review findings together, verify and group fixes before pushing, and report From e030538611c0c09d09cbf3d8f3b59ca59677a393 Mon Sep 17 00:00:00 2001 From: meetsu <96637888+klNuno@users.noreply.github.com> Date: Mon, 19 Oct 2026 19:51:55 +0200 Subject: [PATCH 7/7] test(e2e): know a UI server's port once it listens, not at its first request --- tests/e2e/cdp-attach.test.ts | 18 ++++++++++++------ tests/e2e/lib/ui-requests.ts | 23 +++++++++++++++++++---- 2 files changed, 31 insertions(+), 10 deletions(-) diff --git a/tests/e2e/cdp-attach.test.ts b/tests/e2e/cdp-attach.test.ts index 9a90ef024..8cfcf0d05 100644 --- a/tests/e2e/cdp-attach.test.ts +++ b/tests/e2e/cdp-attach.test.ts @@ -60,12 +60,17 @@ test('a devtools message that is not JSON fails the waiting call at once and eve } finally { await page?.close(); await server.stop(true); } }, 10_000); -test('a request the UI server answered before its devtools event arrived is reported answered, from its send time', async () => { +test('requests in flight say what each UI server did with them, timed from when Chrome sent them', async () => { let middleware: ((request: IncomingMessage, response: ServerResponse, next: () => void) => void) | undefined; requestLog.configureServer({ middlewares: { use(handler) { middleware = handler; } } }); const ui = createHttpServer((request, response) => middleware!(request, response, () => response.end('export {}'))); await new Promise((resolve) => ui.listen(0, '127.0.0.1', resolve)); const base = `http://127.0.0.1:${(ui.address() as AddressInfo).port}`; + // A second UI server that never gets its request: known from the moment it listens. + const idle = createHttpServer((_request, response) => response.end()); + requestLog.configurePreviewServer({ middlewares: { use() {} }, httpServer: idle }); + await new Promise((resolve) => idle.listen(0, '127.0.0.1', resolve)); + const idleBase = `http://127.0.0.1:${(idle.address() as AddressInfo).port}`; let devtools: ServerWebSocket | undefined; const server = Bun.serve({ hostname: '127.0.0.1', port: 0, fetch(request, self) { @@ -86,15 +91,16 @@ test('a request the UI server answered before its devtools event arrived is repo for (const chunk of ['RightPanel.js', 'CommandPalette.js']) expect(await (await fetch(`${base}/assets/${chunk}`)).text()).toBe('export {}'); // A loaded runner: the server answered both before devtools reported them. await Bun.sleep(30); - const willBeSent = (requestId: string, chunk: string, wallTime?: number) => JSON.stringify({ method: 'Network.requestWillBeSent', params: { requestId, loaderId: 'l', frameId: 'f', wallTime, request: { url: `${base}/assets/${chunk}` } } }); - devtools!.send(willBeSent('1', 'RightPanel.js', sent / 1_000)); - devtools!.send(willBeSent('2', 'CommandPalette.js')); + const willBeSent = (requestId: string, url: string, wallTime?: number) => JSON.stringify({ method: 'Network.requestWillBeSent', params: { requestId, loaderId: 'l', frameId: 'f', wallTime, request: { url } } }); + devtools!.send(willBeSent('1', `${base}/assets/RightPanel.js`, sent / 1_000)); + devtools!.send(willBeSent('2', `${base}/assets/CommandPalette.js`)); + devtools!.send(willBeSent('3', `${idleBase}/assets/SettingsShell.js`, sent / 1_000)); const failure = await page.waitFor('false', 1_300).then(() => 'answered', (error: unknown) => String(error)); const line = (chunk: string) => failure.split('","').find((entry) => entry.includes(chunk)) ?? `no line for ${chunk} in ${failure}`; expect(line('RightPanel.js')).toMatch(/; the UI server answered 200 \d+ ms after it was sent/); expect(line('CommandPalette.js')).toMatch(/; no send time; newest record: the UI server answered 200 \d+ ms before devtools reported it/); - expect(failure).not.toContain('never got it'); - } finally { await page?.close(); await server.stop(true); ui.close(); } + expect(line('SettingsShell.js')).toMatch(/; the UI server never got it/); + } finally { await page?.close(); await server.stop(true); ui.close(); idle.close(); } }, 10_000); test('the failure probe tells a closed port at once from one that accepts and never answers', async () => { diff --git a/tests/e2e/lib/ui-requests.ts b/tests/e2e/lib/ui-requests.ts index e4e2727aa..cd648ff38 100644 --- a/tests/e2e/lib/ui-requests.ts +++ b/tests/e2e/lib/ui-requests.ts @@ -1,4 +1,5 @@ import type { IncomingMessage, ServerResponse } from 'node:http'; +import type { AddressInfo } from 'node:net'; /** * What the Vite servers of this test process did with each request, for a @@ -14,7 +15,8 @@ const served: Served[] = []; const ports = new Set(); type Middleware = (req: IncomingMessage, res: ServerResponse, next: () => void) => void; -interface WithMiddlewares { middlewares: { use(handler: Middleware): unknown } } +interface Listening { listening: boolean; address(): AddressInfo | string | null; once(event: 'listening', listener: () => void): unknown } +interface WithMiddlewares { middlewares: { use(handler: Middleware): unknown }; httpServer?: Listening | null } function record(req: IncomingMessage, res: ServerResponse, next: () => void): void { const port = req.socket.localPort ?? 0; @@ -27,11 +29,24 @@ function record(req: IncomingMessage, res: ServerResponse, next: () => void): vo next(); } -/** Added first, so it sees every request, the ones Vite's own middlewares answer included. */ +/** + * Added first, so it sees every request, the ones Vite's own middlewares answer + * included. The port is known once the server listens, not at its first + * request: a server that got nothing yet is still told apart from a core. + */ +function track(server: WithMiddlewares): void { + server.middlewares.use(record); + const http = server.httpServer; + if (!http) return; + const register = () => { const address = http.address(); if (address !== null && typeof address === 'object') ports.add(address.port); }; + if (http.listening) register(); + else http.once('listening', register); +} + export const requestLog = { name: 'boite-e2e-request-log', - configureServer(server: WithMiddlewares) { server.middlewares.use(record); }, - configurePreviewServer(server: WithMiddlewares) { server.middlewares.use(record); }, + configureServer: track, + configurePreviewServer: track, }; /** Chrome's `wallTime` and `Date.now()` read the same system clock, in ticks that can be coarse on Windows. */