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 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", diff --git a/tests/e2e/cdp-attach.test.ts b/tests/e2e/cdp-attach.test.ts index a4c5d2243..8cfcf0d05 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; @@ -29,6 +32,77 @@ 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('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) { + 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, 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(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 () => { const closed = await freePort(); let startedAt = Date.now(); diff --git a/tests/e2e/lib/cdp.ts b/tests/e2e/lib/cdp.ts index 616a04e84..1d00627b1 100644 --- a/tests/e2e/lib/cdp.ts +++ b/tests/e2e/lib/cdp.ts @@ -5,6 +5,7 @@ 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,31 @@ interface Pending { timer: ReturnType; } +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; + 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; @@ -166,9 +192,25 @@ 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 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 +320,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 +365,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 +379,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. @@ -355,6 +401,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 @@ -389,9 +436,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 }; @@ -571,19 +618,133 @@ 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. + * 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(); + 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 = [ + 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 && again === null) 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, 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 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`; + } 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.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 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.wall ?? null, request.at); + return `${request.url} ${request.answered ? 'answered, body pending' : 'no response'} for ${now - sentAt} ms: ${wire}${server === null ? '' : `; ${server}`}`; + }); + } + + /** 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: { 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; 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 } }[]; + }; + result?: unknown; + error?: { message?: string }; + }; 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') { @@ -592,11 +753,44 @@ 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); + 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'; + 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}`); diff --git a/tests/e2e/lib/ui-requests.ts b/tests/e2e/lib/ui-requests.ts new file mode 100644 index 000000000..cd648ff38 --- /dev/null +++ b/tests/e2e/lib/ui-requests.ts @@ -0,0 +1,88 @@ +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 + * 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 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; + 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. 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: track, + configurePreviewServer: track, +}; + +/** 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 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 | 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; + 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'; + return describe(entry, sentAt, 'it was sent'); +} 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(/\/$/, '');