diff --git a/.github/workflows/flake-loop.yml b/.github/workflows/flake-loop.yml new file mode 100644 index 000000000..d8e19aace --- /dev/null +++ b/.github/workflows/flake-loop.yml @@ -0,0 +1,152 @@ +name: flake-loop + +# Runs flaky tests many times on the runners where they fail, with timing +# traces, to find a cause and to prove a fix (docs/ci.md#checks). A pull +# request runs it once it carries the `flake-loop` label. +on: + pull_request: + types: [opened, synchronize, reopened, labeled] + workflow_dispatch: + inputs: + runs: + description: Runs per job. + type: number + default: 10 + +permissions: + contents: read + +concurrency: + group: flake-loop-${{ github.event.pull_request.number || github.ref }} + # A loop already running keeps its data; a newer head waits for it. + cancel-in-progress: false + +env: + RUNS: ${{ inputs.runs || 10 }} + +jobs: + browser: + name: Core browser files (${{ matrix.name }}, ${{ matrix.parallel }} at once, temp on ${{ matrix.temp }}) + if: false + strategy: + fail-fast: false + matrix: + include: + # Chromium stopped answering with its processes idle and a load of 9 to 29: + # does the runner's disk stall it? The same loop with the temp folder in RAM. + - { os: macos-15, name: macOS arm64, parallel: 4, temp: disk } + - { os: macos-15, name: macOS arm64, parallel: 4, temp: ram } + runs-on: ${{ matrix.os }} + timeout-minutes: 75 + env: + BOITE_CDP_TRACE: '1' + FLAKE_LOOP_TITLE: Core browser files, ${{ matrix.name }}, ${{ matrix.parallel }} at once, temp on ${{ matrix.temp }} + steps: + - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 + with: + persist-credentials: false + - uses: ./.github/actions/setup + - name: Temp folder in RAM + if: matrix.temp == 'ram' + run: | + # 2 GiB in 512-byte sectors. + device=$(hdiutil attach -nomount ram://4194304 | tr -d '[:space:]') + diskutil erasevolume APFS boite-ram "$device" + mkdir -p /Volumes/boite-ram/tmp + echo "TMPDIR=/Volumes/boite-ram/tmp/" >> "$GITHUB_ENV" + - run: | + mkdir -p flake-loop + # Disk throughput and load each second, to line a stall up with the disk. + (while true; do echo "$(date -u +%H:%M:%S) $(iostat -d -c 2 -w 1 disk0 | tail -1) $(sysctl -n vm.loadavg)"; done > flake-loop/iostat.txt 2>&1 &) + bun scripts/ci/flake-loop.ts --runs "$RUNS" --parallel ${{ matrix.parallel }} --cwd packages/core --out flake-loop test/browser-sharing.test.ts test/browser.test.ts test/browser-sleep.test.ts test/browser-profile-lifecycle.test.ts + - uses: ./.github/actions/upload-artifact + if: always() + with: + name: flake-loop-browser-${{ matrix.os }}-${{ matrix.parallel }}-${{ matrix.temp }} + path: flake-loop/ + + cli: + name: cli.test.ts (${{ matrix.name }}) + if: false + strategy: + fail-fast: false + matrix: + include: + - { os: ubuntu-24.04, name: Linux x64 } + - { os: macos-15, name: macOS arm64 } + - { os: windows-2025, name: Windows x64 } + runs-on: ${{ matrix.os }} + timeout-minutes: 30 + env: + FLAKE_LOOP_TITLE: cli.test.ts, ${{ matrix.name }} + steps: + - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 + with: + persist-credentials: false + - uses: ./.github/actions/setup + # Four copies at once load the runner as the core suite's four workers do. + - shell: bash + run: bun scripts/ci/flake-loop.ts --runs "$((RUNS * 2))" --parallel 4 --cwd packages/core --out flake-loop test/cli.test.ts test/cli.test.ts test/cli.test.ts test/cli.test.ts + - uses: ./.github/actions/upload-artifact + if: always() + with: + name: flake-loop-cli-${{ matrix.os }} + path: flake-loop/ + + e2e: + name: E2E ${{ matrix.mode }} + if: github.event_name == 'workflow_dispatch' || contains(github.event.pull_request.labels.*.name, 'flake-loop') + strategy: + fail-fast: false + matrix: + mode: [alone] + runs-on: windows-2025 + timeout-minutes: 90 + env: + BOITE_E2E_PREBUILT_UI: '1' + BOITE_E2E_FAKE_UI: tests/e2e/.artifacts/fake-ui + BOITE_E2E_TRACE: '1' + FLAKE_LOOP_TITLE: E2E ${{ matrix.mode }} + steps: + - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 + with: + persist-credentials: false + - uses: ./.github/actions/setup + - run: bun run build:ui + - run: bun tests/e2e/lib/warm.ts --build-only $env:BOITE_E2E_FAKE_UI + # Same temp drive as the E2E job in ci.yml. + - name: Prepare end-to-end tests + env: + TEMP: ${{ runner.temp }} + TMP: ${{ runner.temp }} + run: bun tests/e2e/lib/warm.ts --prebuilt $env:BOITE_E2E_FAKE_UI + - name: Loop + env: + TEMP: ${{ runner.temp }} + TMP: ${{ runner.temp }} + MODE: ${{ matrix.mode }} + run: | + if ($env:MODE -eq 'alone') { + $files = @('tests/e2e/machines.test.ts'); $runs = [int]$env:RUNS * 4; $together = @() + } else { + $shard = $env:MODE.Split(' ')[1] + $files = @(bun scripts/ci/e2e-shards.ts $shard 3) + if ($LASTEXITCODE -ne 0 -or $files.Count -eq 0) { throw "No E2E files for $env:MODE" } + $runs = [math]::Max(1, [int]([int]$env:RUNS / 2)); $together = @('--together') + } + New-Item -ItemType Directory -Force flake-loop/devtools | Out-Null + $env:BOITE_E2E_TRACE_DIR = (Resolve-Path flake-loop/devtools).Path + # A page stall lines up with these: is the disk under Chrome's profile slow then, and is Defender scanning it? + Get-MpComputerStatus | Select-Object RealTimeProtectionEnabled, OnAccessProtectionEnabled, BehaviorMonitorEnabled | Format-List | Out-File flake-loop/defender.txt + (Get-MpPreference).ExclusionPath | Out-File -Append flake-loop/defender.txt + Get-Content flake-loop/defender.txt + $perf = Start-Process typeperf -ArgumentList @('\PhysicalDisk(*)\Avg. Disk sec/Transfer', '\PhysicalDisk(*)\Current Disk Queue Length', '\Processor(_Total)\% Processor Time', '\Process(MsMpEng)\% Processor Time', '-si', '1', '-f', 'CSV', '-o', (Join-Path $PWD 'flake-loop/perf.csv'), '-y') -PassThru -WindowStyle Hidden + bun scripts/ci/flake-loop.ts --runs $runs --out flake-loop @together @files + $code = $LASTEXITCODE + Stop-Process -Id $perf.Id -ErrorAction SilentlyContinue + exit $code + - uses: ./.github/actions/upload-artifact + if: always() + with: + name: flake-loop-e2e-${{ matrix.mode == 'alone' && 'alone' || format('shard{0}', strategy.job-index) }} + path: flake-loop/ diff --git a/docs/ci.md b/docs/ci.md index 1d8d9f1e9..efe03d7f5 100644 --- a/docs/ci.md +++ b/docs/ci.md @@ -126,6 +126,26 @@ crash, a timed-out file or any other failing test fails at once. The list started on 2026-10-18 from the 80 runs that passed on rerun since 2026-10-16: tests that failed at least three first attempts. A fixed test leaves the list; `flaky.test.ts` fails when an entry no longer exists in its file. +The `flake-loop` workflow measures a flaky test before and after its fix. It +runs on a pull request that carries the `flake-loop` label, or by hand: the +quarantined browser files four at a time on macOS arm64, once with the temp +folder on the disk and once on a RAM disk, with disk throughput logged each +second (`iostat.txt`), `cli.test.ts` four copies at a time on every OS, and +`coordination-bridge-live.test.ts` and `machines.test.ts` alone and each E2E +shard whole on Windows, with the runner's disk latency, queue length and +Defender CPU logged every second (`perf.csv`). +`scripts/ci/flake-loop.ts` counts each test's passes and failures over the +runs, prints the error of each failure and writes a table to the job summary. +`BOITE_CDP_TRACE=1` makes a core DevTools timeout say how many bytes of the +browser's answers sat unread, the load and whether `Browser.getVersion` still +answered; `BOITE_E2E_TRACE=1` makes an E2E timeout or lost browser say how the +devtools socket closed, whether Chrome still ran, the test process's event +loop delays and what the UI server still owed. It also passes each devtools +socket through a loopback relay (`tests/e2e/lib/ws-relay.ts`) that checks +every frame Chrome sends, and on a 1002 close keeps Chrome's bytes and read +lengths in `BOITE_E2E_TRACE_DIR` for a replay against Bun's client. There +Chrome also writes a net log, kept for a page whose failure printed a trace, +and a stalled request says whether its headers ever reached the wire. `scripts/ci/hdiutil-retry.ts` bundles the macOS application again, three attempts at most, when hdiutil reports `Resource busy`. That runner fault (actions/runner-images#7522) failed the Apple Silicon DMG of nightly diff --git a/packages/core/src/browser/cdp.ts b/packages/core/src/browser/cdp.ts index c955eadd6..78fd81d7f 100644 --- a/packages/core/src/browser/cdp.ts +++ b/packages/core/src/browser/cdp.ts @@ -10,12 +10,19 @@ */ import { fstatSync } from 'node:fs'; +import { loadavg } from 'node:os'; type Listener = (params: Record, sessionId: string | undefined) => void; interface Waiting { resolve(value: Record): void; reject(error: Error): void; timer: ReturnType; method: string } /** What a command may take before the page is called stuck. */ const COMMAND_TIMEOUT_MS = 30_000; +/** + * `BOITE_CDP_TRACE=1` (CI flake loops): a timed-out command also says how many + * bytes of the browser's answers sit unread on the replies descriptor, the + * machine's load, and whether the browser still answers `Browser.getVersion`. + */ +const TRACE = process.env.BOITE_CDP_TRACE === '1'; export class CdpError extends Error {} @@ -26,6 +33,10 @@ export class Cdp { #waiting = new Map(); #listeners = new Map>(); #closed: Error | null = null; + /** When the last message from the browser arrived, for a timeout to say how long it has been quiet. */ + #heardAt = performance.now(); + /** Bytes waiting unread on the replies descriptor, under `BOITE_CDP_TRACE` and the pipe only. */ + #unread: (() => number | null) | null = null; readonly closed: Promise; private constructor(write: (text: string) => void, stop: () => void) { @@ -88,6 +99,7 @@ export class Cdp { writer = await connect({ fd: commands, socket: { data() {}, drain: flush, close: ended, error: ended } }); } catch (error) { reader.end(); throw error; } flush(writer); + if (TRACE) cdp.#unread = await unreadBytes(replies); return cdp; } @@ -123,7 +135,10 @@ export class Cdp { return new Promise((resolve, reject) => { const timer = setTimeout(() => { this.#waiting.delete(id); - reject(new CdpError(`the browser did not answer ${method} within ${Math.round(timeoutMs / 1000)} seconds`)); + const quiet = `the last message from the browser came ${Math.round(performance.now() - this.#heardAt)} ms ago`; + const error = (detail: string) => new CdpError(`the browser did not answer ${method} within ${Math.round(timeoutMs / 1000)} seconds; ${quiet}${detail}`); + if (!TRACE || method === 'Browser.getVersion') { reject(error('')); return; } + void this.#trace().then(detail => reject(error(detail))); }, timeoutMs); this.#waiting.set(id, { resolve: resolve as (value: Record) => void, reject, timer, method }); this.#write(JSON.stringify({ id, method, params, ...(sessionId ? { sessionId } : {}) })); @@ -143,7 +158,19 @@ export class Cdp { this.#stop(); } + /** What `BOITE_CDP_TRACE` adds to a timeout: unread bytes, load, and a browser-level probe. */ + async #trace(): Promise { + const unread = this.#unread?.(); + const started = performance.now(); + const probe = await this.send('Browser.getVersion', {}, undefined, 5_000) + .then(() => `answered in ${Math.round(performance.now() - started)} ms`, (error: Error) => error.message.split(';')[0]); + const after = this.#unread?.(); + const bytes = unread === undefined || unread === null ? 'unread bytes unknown' : `${unread} bytes unread before the probe, ${after} after`; + return `; trace: ${bytes}, load ${loadavg().map(n => n.toFixed(1)).join(' ')}, Browser.getVersion ${probe}; busiest: ${busiest()}`; + } + #receive(text: string): void { + this.#heardAt = performance.now(); let message: { id?: number; method?: string; params?: Record; result?: Record; error?: { message?: string }; sessionId?: string }; try { message = JSON.parse(text); } catch { return; } if (typeof message.id === 'number') { @@ -168,6 +195,34 @@ export class Cdp { } } +/** The ten processes using the most CPU, with their state and memory, and how many Chromium processes run. */ +function busiest(): string { + if (process.platform === 'win32') return 'not read on Windows'; + const ps = Bun.spawnSync(['ps', '-A', '-o', 'pid=,pcpu=,rss=,state=,comm='], { stdout: 'pipe', stderr: 'ignore' }); + const rows = ps.stdout.toString().trim().split('\n').map(line => line.trim().split(/\s+/)) + .map(([pid, cpu, rss, state, ...command]) => ({ pid, cpu: Number(cpu), rss: Math.round(Number(rss) / 1024), state, name: command.join(' ').split('/').pop() ?? '' })); + const chromium = rows.filter(row => /chrom/i.test(row.name)).length; + return `${chromium} Chromium processes; ` + rows.sort((a, b) => b.cpu - a.cpu).slice(0, 10).map(row => `${row.name} ${row.pid} ${row.cpu}% ${row.rss} MB ${row.state}`).join(', '); +} + +/** + * Peeks the bytes a socket holds without reading them, `recv(MSG_PEEK | + * MSG_DONTWAIT)` through libc. Bytes there while a command times out mean the + * browser answered and nobody read it; none mean the browser stayed silent. + */ +async function unreadBytes(fd: number): Promise<(() => number | null) | null> { + if (process.platform !== 'darwin' && process.platform !== 'linux') return null; + try { + const { dlopen, FFIType, ptr } = await import('bun:ffi'); + const libc = dlopen(process.platform === 'darwin' ? '/usr/lib/libSystem.B.dylib' : 'libc.so.6', { + recv: { args: [FFIType.i32, FFIType.ptr, FFIType.u64, FFIType.i32], returns: FFIType.i64 }, + }); + const buffer = new Uint8Array(1 << 20); + const flags = 0x2 | (process.platform === 'darwin' ? 0x80 : 0x40); + return () => { const n = Number(libc.symbols.recv(fd, ptr(buffer), buffer.length, flags)); return n < 0 ? 0 : n; }; + } catch { return null; } +} + function concat(parts: Uint8Array[], size: number): Uint8Array { const whole = new Uint8Array(size); let at = 0; diff --git a/packages/core/src/client.ts b/packages/core/src/client.ts index 8b2567b58..310c0696a 100644 --- a/packages/core/src/client.ts +++ b/packages/core/src/client.ts @@ -91,6 +91,8 @@ export async function connect(url: string, token: string, options: ConnectOption const listeners = new Map void>>(); let nextId = 1; let closed = false; + /** Why the socket closed, so a later call names the code instead of only saying it is closed. */ + let closedBy: SocketClosedError | null = null; const send = (method: string, params: unknown, waitMs = options.requestTimeoutMs ?? 120_000): Promise => { const id = nextId; @@ -143,6 +145,7 @@ export async function connect(url: string, token: string, options: ConnectOption socket.addEventListener('close', (event: CloseEvent) => { closed = true; const error = new SocketClosedError(event.code, event.reason); + if (!ownerClosed) closedBy = error; for (const waiter of pending.values()) waiter.reject(error); pending.clear(); for (const watcher of [...watchers]) { @@ -200,7 +203,7 @@ export async function connect(url: string, token: string, options: ConnectOption threadId: hello.threadId ?? null, device: hello.device ?? null, async call(method: M, params: RpcMethods[M]['params']): Promise { - if (closed) throw new Error('the client is closed'); + if (closed) throw new Error(closedBy ? `the client is closed: ${closedBy.message}` : 'the client is closed'); const wait = method === 'delegation.wait' && options.requestTimeoutMs === undefined ? Math.min(3_600_000, Math.max(0, (params as RpcMethods['delegation.wait']['params']).timeoutMs ?? 600_000)) + 5000 : undefined; @@ -222,7 +225,7 @@ export async function connect(url: string, token: string, options: ConnectOption ): Promise { return new Promise((resolve, reject) => { if (closed) { - reject(new Error('the client is closed')); + reject(new Error(closedBy ? `the client is closed: ${closedBy.message}` : 'the client is closed')); return; } const watcher = { diff --git a/packages/core/test/waits.test.ts b/packages/core/test/waits.test.ts index 341de57ff..a1334f27e 100644 --- a/packages/core/test/waits.test.ts +++ b/packages/core/test/waits.test.ts @@ -55,4 +55,6 @@ test('a core that goes away rejects a pending event wait at once', async () => { await wait; expect((caught as Error).message).toStartWith('the socket closed'); expect(Date.now() - started).toBeLessThan(4000); + // A later call names how the core hung up, not only that the client is closed. + await expect(client.call('threads.list', {})).rejects.toThrow('the client is closed: the socket closed (1001: "core stopping")'); }); diff --git a/packages/ui/src/lib/connection-group.svelte.ts b/packages/ui/src/lib/connection-group.svelte.ts index 610713f53..7bd202af2 100644 --- a/packages/ui/src/lib/connection-group.svelte.ts +++ b/packages/ui/src/lib/connection-group.svelte.ts @@ -69,6 +69,7 @@ export class ConnectionGroup { if (!current(source, client) || !current(target, remote) || source.store.group?.id !== groupId) return false; target.store.group = group; target.store.groupKnown = true; + target.store.ungrouped = group === null; if (group === null) this.#attempted.delete(remote); if (group?.id === groupId && this.#adoptMember(group, target, groupId)) { this.errors = this.errors.filter(error => !error.startsWith(`${target.label}:`)); diff --git a/packages/ui/src/lib/connection-group.test.ts b/packages/ui/src/lib/connection-group.test.ts index 9fe0a9b7d..e7e2730e7 100644 --- a/packages/ui/src/lib/connection-group.test.ts +++ b/packages/ui/src/lib/connection-group.test.ts @@ -159,3 +159,16 @@ test('reopening after an interrupted admission records membership and respects a await new ConnectionGroup(workspace).merge(); expect(target.store.group).toBeNull(); }); + +test('a machine keeps its last word of being in no group until it answers with one', async () => { + const { source } = await setup(); + expect(source.store.ungrouped).toBe(true); + await source.store.createGroup('Home'); + expect(source.store.ungrouped).toBe(false); + await source.store.leaveGroup(); + expect(source.store.ungrouped).toBe(true); + // A new connection forgets what the group was, not what the machine last said of it. + source.store.groupKnown = false; + await source.store.loadGroup(); + expect(source.store.ungrouped).toBe(true); +}); diff --git a/packages/ui/src/lib/group-links.svelte.ts b/packages/ui/src/lib/group-links.svelte.ts index 2e1d013db..df85872ed 100644 --- a/packages/ui/src/lib/group-links.svelte.ts +++ b/packages/ui/src/lib/group-links.svelte.ts @@ -437,10 +437,11 @@ export class GroupLinks { if (signs === undefined) continue; const groupId = machine.store.group?.id; const listedBy = (other: Machine): boolean => other.store.group!.cores.some((core) => core.coreId === signs); - // Its own group, as another machine of it says; or, refused there with the group it was in unknown, none of the device's groups lists it. + // Its own group, as another machine of it says; or, refused there or out of every group by its own word, none of the device's groups lists it. + // Removed, a machine may say it is in no group before the others drop it from their roster, then tell this device's hellos to come back. const delisted = groupId !== undefined ? signed.some((other) => other !== machine && other.store.group!.id === groupId && !listedBy(other)) - : machine.store.pairingRequired && signed.length > 0 && !signed.some((other) => other !== machine && listedBy(other)); + : (machine.store.pairingRequired || machine.store.ungrouped) && signed.length > 0 && !signed.some((other) => other !== machine && listedBy(other)); if (delisted) await this.#drop(machine, false); } } diff --git a/packages/ui/src/lib/group-links.test.ts b/packages/ui/src/lib/group-links.test.ts index d158893df..90b61c74f 100644 --- a/packages/ui/src/lib/group-links.test.ts +++ b/packages/ui/src/lib/group-links.test.ts @@ -13,6 +13,7 @@ interface FakeStore { client: { call: ReturnType } | null; group: Group | null; groupKnown: boolean; + ungrouped?: boolean; endpointUrl: string | null; loadGroup: ReturnType; } @@ -693,4 +694,31 @@ describe('a machine the device key opens', () => { expect(GroupLinks.coreOf(asleep)).toBe('a'.repeat(64)); localStorage.clear(); }); + + it('leaves once it said it is in no group and the device\'s group stopped listing it, even if it said so first', async () => { + const [selfA, selfB, selfC] = ['a'.repeat(64), 'b'.repeat(64), 'c'.repeat(64)]; + localStorage.setItem(ENVIRONMENTS_STORAGE_KEY, JSON.stringify([ + { url: 'http://a.test', label: 'A', token: '', paired: true, signs: selfA }, + { url: 'http://b.test', label: 'B', token: '', paired: true, signs: selfB }, + { url: 'http://c.test', label: 'C', token: '', paired: true, signs: selfC } + ])); + const both = [core(selfA, ['http://a.test']), core(selfB, ['http://b.test'])]; + const a = machine('http://a.test', { group: group(selfA, both) }); + const b = machine('http://b.test', { group: group(selfB, both) }); + // A machine of another group, not reached yet since the page opened: it has said nothing. + const c = machine('http://c.test', { connection: 'connecting', groupKnown: false }); + const { workspace: ws, removed } = workspace([a, b, c]); + const links = new GroupLinks(ws, { reach: vi.fn(async () => null), secure: () => false }); + // Removed, B says it is in no group before A's roster says it left; then it closes the socket, and its + // hellos are told to come back, as it has no roster to find the device in. + Object.assign(storeOf(b), { group: null, ungrouped: true }); + await links.reconcile(); + expect(removed).toEqual([]); + Object.assign(storeOf(b), { connection: 'connecting', groupKnown: false }); + await links.reconcile(); + storeOf(a).group = group(selfA, [both[0]!]); + await links.reconcile(); + expect(removed).toEqual(['http://b.test']); + localStorage.clear(); + }); }); diff --git a/packages/ui/src/lib/store.svelte.ts b/packages/ui/src/lib/store.svelte.ts index 70abd453e..7437006e2 100644 --- a/packages/ui/src/lib/store.svelte.ts +++ b/packages/ui/src/lib/store.svelte.ts @@ -263,6 +263,8 @@ export class Store { set group(value) { this.#ctx.pairing.group = value; } get groupKnown() { return this.#ctx.pairing.groupKnown; } set groupKnown(value) { this.#ctx.pairing.groupKnown = value; } + get ungrouped() { return this.#ctx.pairing.ungrouped; } + set ungrouped(value) { this.#ctx.pairing.ungrouped = value; } loadGroup(...args: Parameters) { return this.#ctx.pairing.loadGroup(...args); } createGroup(...args: Parameters) { return this.#ctx.pairing.createGroup(...args); } renameGroup(...args: Parameters) { return this.#ctx.pairing.renameGroup(...args); } diff --git a/packages/ui/src/lib/store/connection.svelte.ts b/packages/ui/src/lib/store/connection.svelte.ts index 915c4b0f8..06fc9e6d0 100644 --- a/packages/ui/src/lib/store/connection.svelte.ts +++ b/packages/ui/src/lib/store/connection.svelte.ts @@ -335,6 +335,7 @@ export class Connection { s.sessions = []; s.group = null; s.groupKnown = false; + s.ungrouped = false; s.projects = []; s.threads = []; // What the next core answers replaces these; one that cannot answer must not show the last one's. diff --git a/packages/ui/src/lib/store/pairing.svelte.ts b/packages/ui/src/lib/store/pairing.svelte.ts index 86afe6a08..0ce1cb88c 100644 --- a/packages/ui/src/lib/store/pairing.svelte.ts +++ b/packages/ui/src/lib/store/pairing.svelte.ts @@ -15,6 +15,8 @@ export class Pairing { group = $state(null); /** The core answered `group.get` at least once on this connection: null then means no group, not no answer yet. */ groupKnown = $state(false); + /** The core last answered that it is in no group. A new connection that has not answered yet does not take that back. */ + ungrouped = false; constructor(private readonly ctx: StoreContext) {} /** @@ -85,6 +87,7 @@ export class Pairing { if ((group?.cores.length ?? 0) + (group?.devices.length ?? 0) > (this.group?.cores.length ?? 0) + (this.group?.devices.length ?? 0) && this.group !== null) this.closeDeviceInvite(); this.group = group; this.groupKnown = true; + this.ungrouped = group === null; } catch (error) { if (client !== this.ctx.client) return; if (error instanceof RpcFailure && error.code === RpcErrorCode.MethodNotFound) { @@ -109,6 +112,7 @@ export class Pairing { // The store moved to another core meanwhile: this answer, or this refusal, is about the one it left. if (client !== this.ctx.client) return false; this.group = group; + this.ungrouped = group === null; return true; } catch (error) { if (client === this.ctx.client) this.ctx.fail(error); diff --git a/scripts/ci/flake-loop.test.ts b/scripts/ci/flake-loop.test.ts new file mode 100644 index 000000000..53e2edc5c --- /dev/null +++ b/scripts/ci/flake-loop.test.ts @@ -0,0 +1,45 @@ +import { expect, test } from 'bun:test'; +import { failureBlock, results, summary } from './flake-loop.ts'; + +const output = [ + '(pass) first [12.50ms]', + 'error: the client is closed: the socket closed (1002)', + ' at call (client.ts:203:29)', + '(fail) group > second [1.20s]', + '(pass) third', +].join('\n'); + +const junit = ` + + + + + + + + + + + +`; + +test('results reads each test the report names, its outcome and its duration, skipped ones left out', () => { + expect(results(junit)).toEqual([ + { file: 'a.test.ts', name: 'first', passed: true, ms: 12.5 }, + { file: 'a.test.ts', name: 'group > second "quoted"', passed: false, ms: 1200 }, + ]); +}); + +test('a failure block runs from the end of the test before to its fail line', () => { + expect(failureBlock(output, 'group > second')).toBe('error: the client is closed: the socket closed (1002)\n at call (client.ts:203:29)\n(fail) group > second [1.20s]'); + expect(failureBlock(output, 'missing')).toBe(''); +}); + +test('the summary puts the most failed test first and counts every failure', () => { + const table = summary(new Map([ + ['a.test.ts: steady', { pass: 3, fail: 0, ms: [10, 20, 30] }], + ['a.test.ts: flaky | piped', { pass: 1, fail: 2, ms: [5, 50, 500] }], + ]), 3); + expect(table.split('\n')[2]).toBe('| a.test.ts: flaky \\| piped | 2 | 1 | 50 | 500 | 500 |'); + expect(table).toEndWith('3 runs, 2 failures'); +}); diff --git a/scripts/ci/flake-loop.ts b/scripts/ci/flake-loop.ts new file mode 100644 index 000000000..ddc7fa4f3 --- /dev/null +++ b/scripts/ci/flake-loop.ts @@ -0,0 +1,135 @@ +import { appendFileSync, mkdirSync, readFileSync, rmSync, writeFileSync } from 'node:fs'; +import { basename, resolve } from 'node:path'; + +// Runs test files again and again on one runner and counts, per test, how many +// runs passed and failed, to measure a flaky test before and after its fix. +// Each run starts every file in a fresh `bun test` process, `--parallel` at a +// time, as `packages/core/bin/test.ts` does. A failed file's whole output is +// kept in `--out`; the error block of each failed test is printed as it ends. +// +// Usage: bun scripts/ci/flake-loop.ts --runs 20 [--parallel 4] [--cwd packages/core] +// [--pattern ] [--out ] [--together] +const ROOT = resolve(import.meta.dir, '../..'); +/** A file that stops answering is ended, as the core runner's file deadline does. */ +const FILE_DEADLINE_MS = 300_000; + +export interface Tally { pass: number; fail: number; ms: number[] } + +const unescape = (text: string) => text.replace(/&(quot|apos|lt|gt|amp);/g, (_, entity: string) => ({ quot: '"', apos: "'", lt: '<', gt: '>', amp: '&' })[entity]!); + +/** + * The tests a `bun test --reporter=junit` file names, skipped ones left out. + * The console prints `(pass)` lines only in some environments; the report lists every test. + */ +export function results(junit: string): { file: string; name: string; passed: boolean; ms: number }[] { + return [...junit.matchAll(/]*?(?:\/>|>([\s\S]*?)<\/testcase>)/g)] + .filter(match => !match[5]?.includes(' ({ + file: basename(unescape(match[4]!).replaceAll('\\', '/')), + name: match[2] ? `${unescape(match[2])} > ${unescape(match[1]!)}` : unescape(match[1]!), + passed: !match[5]?.includes(' line.startsWith(`(fail) ${name}`)); + if (end < 0) return ''; + let start = end - 1; + while (start >= 0 && !/^\((pass|fail|skip|todo)\) /.test(lines[start]!)) start--; + return lines.slice(start + 1, end + 1).join('\n'); +} + +function percentile(values: number[], p: number): number { + if (!values.length) return 0; + const sorted = [...values].sort((a, b) => a - b); + return sorted[Math.min(sorted.length - 1, Math.floor(p * sorted.length))]!; +} + +export function summary(tallies: Map, runs: number): string { + const rows = [...tallies.entries()].sort(([, a], [, b]) => b.fail - a.fail); + return [ + `| test | failed | passed | median ms | p95 ms | max ms |`, + `|---|---|---|---|---|---|`, + ...rows.map(([name, t]) => `| ${name.replaceAll('|', '\\|')} | ${t.fail} | ${t.pass} | ${Math.round(percentile(t.ms, 0.5))} | ${Math.round(percentile(t.ms, 0.95))} | ${Math.round(Math.max(0, ...t.ms))} |`), + '', + `${runs} runs, ${rows.reduce((sum, [, t]) => sum + t.fail, 0)} failures`, + ].join('\n'); +} + +async function main(args: string[]): Promise { + const option = (name: string, fallback?: string) => { + const at = args.indexOf(name); + if (at < 0) return fallback; + const [, value] = args.splice(at, 2); + if (value === undefined) throw new Error(`${name}: expected a value`); + return value; + }; + const runs = Number(option('--runs', '10')); + const parallel = Number(option('--parallel', '1')); + const cwd = resolve(ROOT, option('--cwd', '.')!); + const pattern = option('--pattern'); + const out = resolve(ROOT, option('--out', 'flake-loop')!); + const together = args.includes('--together'); + if (together) args.splice(args.indexOf('--together'), 1); + if (!Number.isInteger(runs) || runs < 1) throw new Error(`--runs: expected a positive integer, received ${runs}`); + if (!Number.isInteger(parallel) || parallel < 1 || parallel > 8) throw new Error(`--parallel: expected 1 to 8, received ${parallel}`); + const files = args; + if (!files.length) throw new Error('expected at least one test file'); + mkdirSync(out, { recursive: true }); + + // `--together` runs every file in one process, as an E2E shard does. + const groups = together ? [files] : files.map(file => [file]); + const tallies = new Map(); + const count = (key: string, passed: boolean, ms: number) => { + const tally = tallies.get(key) ?? { pass: 0, fail: 0, ms: [] }; + tallies.set(key, tally); + if (passed) tally.pass++; else tally.fail++; + tally.ms.push(ms); + }; + const started = performance.now(); + for (let run = 1; run <= runs; run++) { + let next = 0; + await Promise.all(Array.from({ length: Math.min(parallel, groups.length) }, async () => { + for (let index = next++; index < groups.length; index = next++) { + const group = groups[index]!, label = `run-${run}-${index}-${basename(group[0]!)}`; + const report = resolve(out, `${label}.xml`); + const child = Bun.spawn([process.execPath, 'test', ...group, '--timeout', '60000', '--reporter=junit', `--reporter-outfile=${report}`, ...(pattern ? ['-t', pattern] : [])], { + cwd, stdin: 'ignore', stdout: 'pipe', stderr: 'pipe', windowsHide: true, + env: { ...process.env, NO_COLOR: '1', FORCE_COLOR: '0' }, + }); + const deadline = setTimeout(() => child.kill(), FILE_DEADLINE_MS * group.length); + const [stdout, stderr, code] = await Promise.all([new Response(child.stdout).text(), new Response(child.stderr).text(), child.exited]); + clearTimeout(deadline); + const output = `${stdout}\n${stderr}`; + let junit = ''; + try { junit = readFileSync(report, 'utf8'); rmSync(report); } catch { /* killed before it wrote one */ } + const found = results(junit); + for (const { file, name, passed, ms } of found) { + const key = `${file}: ${name}`; + count(key, passed, ms); + if (!passed) console.log(`::group::run ${run} ${key}\n${failureBlock(output, name)}\n::endgroup::`); + } + if (code !== 0) { + writeFileSync(resolve(out, `${label}.log`), output); + if (!found.some(result => !result.passed)) { + const key = `${basename(group[0]!)}${group.length > 1 ? ` and ${group.length - 1} more` : ''}: (exit ${code ?? 'killed'} with no named failure)`; + count(key, false, 0); + console.log(`::group::run ${run} ${key}\n${output.slice(-4000)}\n::endgroup::`); + } + } + } + })); + const failed = [...tallies.values()].reduce((sum, t) => sum + t.fail, 0); + console.log(`run ${run}/${runs}: ${failed} failures so far, ${Math.round((performance.now() - started) / 1000)} s`); + } + const table = summary(tallies, runs); + console.log(`\n${table}`); + writeFileSync(resolve(out, 'summary.md'), table); + if (process.env.GITHUB_STEP_SUMMARY) appendFileSync(process.env.GITHUB_STEP_SUMMARY, `\n### ${process.env.FLAKE_LOOP_TITLE ?? files.join(' ')}\n\n${table}\n`); + return [...tallies.values()].some(t => t.fail > 0) ? 1 : 0; +} + +if (import.meta.main) process.exitCode = await main(process.argv.slice(2)); diff --git a/scripts/ci/ws-relay.test.ts b/scripts/ci/ws-relay.test.ts new file mode 100644 index 000000000..7e6465ab2 --- /dev/null +++ b/scripts/ci/ws-relay.test.ts @@ -0,0 +1,59 @@ +import { expect, test } from 'bun:test'; +import { mkdtempSync, readFileSync, rmSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join as joinPath } from 'node:path'; +import { FrameCheck } from '../../tests/e2e/lib/ws-relay.ts'; + +const handshake = new TextEncoder().encode('HTTP/1.1 101 Switching Protocols\r\nUpgrade: websocket\r\n\r\n'); +function frame(opcode: number, length: number, fin = true): Uint8Array { + const head = length < 126 ? [length] : length < 65536 ? [126, length >> 8, length & 255] : [127, 0, 0, 0, 0, (length >>> 24) & 255, (length >> 16) & 255, (length >> 8) & 255, length & 255]; + const out = new Uint8Array(1 + head.length + length).fill(0x78); + out[0] = (fin ? 0x80 : 0) | opcode; out.set(head, 1); + return out; +} +function join(parts: Uint8Array[]): Uint8Array { + const out = new Uint8Array(parts.reduce((sum, part) => sum + part.length, 0)); + let at = 0; + for (const part of parts) { out.set(part, at); at += part.length; } + return out; +} + +test('the relay check reads a well-formed browser stream however the reads cut it', () => { + const stream = join([handshake, frame(1, 5), frame(1, 126), frame(1, 70_000), frame(9, 0), frame(1, 0, false), frame(0, 3)]); + for (const cut of [1, 2, 3, 7, 125, 4096, stream.length]) { + const check = new FrameCheck(); + for (let at = 0; at < stream.length; at += cut) check.push(stream.subarray(at, at + cut)); + expect(check.report()).toStartWith(`browser stream (extensions none) well-formed over 6 frames, 4 messages and ${stream.length} bytes`); + } +}); + +test('the relay check names the first byte a malformed stream breaks at', () => { + const fragmented = new FrameCheck(); + fragmented.push(join([handshake, frame(1, 10), frame(9, 2, false)])); + expect(fragmented.report()).toStartWith(`browser stream (extensions none) malformed: a fragmented or long control frame at byte ${handshake.length + 12}`); + const opcode = new FrameCheck(); + opcode.push(join([handshake, frame(3, 1)])); + expect(opcode.report()).toStartWith(`browser stream (extensions none) malformed: opcode 3 at byte ${handshake.length}`); +}); + +test('the relay check lets a deflated message set RSV1 only once the browser accepted permessage-deflate', () => { + const deflated = frame(1, 4); deflated[0] = deflated[0]! | 0x40; + const accepted = new FrameCheck(); + accepted.push(join([new TextEncoder().encode('HTTP/1.1 101 Switching Protocols\r\nSec-WebSocket-Extensions: permessage-deflate; client_max_window_bits=15\r\n\r\n'), deflated])); + expect(accepted.report()).toContain('well-formed over 1 frames'); + const refused = new FrameCheck(); + refused.push(join([handshake, deflated])); + expect(refused.report()).toContain(`malformed: reserved bits set at byte ${handshake.length}`); +}); + +test('the relay check keeps the browser bytes and read lengths for a replay', () => { + const dir = mkdtempSync(joinPath(tmpdir(), 'ws-relay-')); + try { + const check = new FrameCheck(); + const stream = join([handshake, frame(1, 300)]); + check.push(stream.subarray(0, 40)); check.push(stream.subarray(40)); + expect(check.dump(joinPath(dir, 'devtools'))).toEndWith(`(${stream.length} of ${stream.length} bytes)`); + expect(new Uint8Array(readFileSync(joinPath(dir, 'devtools.bin')))).toEqual(stream); + expect(JSON.parse(readFileSync(joinPath(dir, 'devtools.reads.json'), 'utf8'))).toEqual([40, stream.length - 40]); + } finally { rmSync(dir, { recursive: true, force: true }); } +}); diff --git a/tests/e2e/lib/cdp.ts b/tests/e2e/lib/cdp.ts index f03659017..d04d26a24 100644 --- a/tests/e2e/lib/cdp.ts +++ b/tests/e2e/lib/cdp.ts @@ -1,10 +1,12 @@ import { existsSync, mkdirSync, mkdtempSync, writeFileSync } from 'node:fs'; +import { rm } from 'node:fs/promises'; import { createConnection, createServer } from 'node:net'; 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'; import { E2E_DIR_PREFIX, killProcessTreeAsync, removeDirectory, watchParentDeath, type ParentDeathWatch } from './cleanup.ts'; +import { relay } from './ws-relay.ts'; /** * Marks the tour seen before any script of the page runs, and only where no @@ -25,6 +27,23 @@ const PROBE_TIMEOUT_MS = 5_000; /** How long a failed attach waits for its launcher's diagnosis. */ const DIAGNOSIS_TIMEOUT_MS = 20_000; const WAIT_DIAGNOSTIC_TIMEOUT_MS = 250; +/** + * `BOITE_E2E_TRACE=1` (CI flake loops): a timeout or a lost browser also says + * when devtools last spoke, how the socket closed, whether Chrome still runs, + * how late this process's event loop ran and what the UI server still owes. + */ +const TRACE = process.env.BOITE_E2E_TRACE === '1'; +/** Event loop delays over 50 ms in this process, as [when, ms], the last 30 s kept. */ +const loopLag: [number, number][] = []; +if (TRACE) { + let last = performance.now(); + setInterval(() => { + const now = performance.now(), late = now - last - 100; + last = now; + if (late > 50) loopLag.push([now, Math.round(late)]); + while (loopLag.length > 0 && now - loopLag[0]![0] > 30_000) loopLag.shift(); + }, 100).unref(); +} /** What a page that left an evaluate hanging is doing: frames drawn in a second, fonts and animations still pending. */ const HUNG_PAGE = `new Promise((resolve) => { let frames = 0; @@ -163,9 +182,22 @@ export class BrowserPage { #nextId = 1; #pending = new Map(); #closed = false; + /** When devtools last sent anything, and how its socket closed. */ + #heardAt = performance.now(); + #closedBy: string | null = null; + /** Messages Bun handed over, and those that were not devtools JSON: a lost frame shows as a gap with the relay's count. */ + #heard = 0; + #unread = 0; + #firstUnread = ''; + #stderr: () => string = () => ''; #pageErrors: string[] = []; /** Requests the page sent and has not finished loading, reported when a wait times out. */ #requests = new Map(); + /** Requests whose headers the network stack put on the wire (`requestWillBeSentExtraInfo`, which may come first). */ + #sent = new Set(); + /** Under `BOITE_E2E_TRACE_DIR`, Chrome's net log, kept only for a page whose failure printed a trace. */ + #netlog: string | null = null; + #keepNetlog = false; /** Completed failures would otherwise disappear from the timeout's in-flight list. */ #networkFailures: string[] = []; errors(): string[] { return [...this.#pageErrors]; } @@ -182,7 +214,8 @@ export class BrowserPage { socket.addEventListener('message', (event: MessageEvent) => { this.#receive(typeof event.data === 'string' ? event.data : ''); }); - socket.addEventListener('close', () => { + socket.addEventListener('close', (event: CloseEvent) => { + this.#closedBy = `code ${event.code}${event.reason ? ` ${JSON.stringify(event.reason)}` : ''}, ${Math.round(performance.now() - this.#heardAt)} ms after the last message`; for (const pending of this.#pending.values()) { clearTimeout(pending.timer); pending.reject(new Error('the devtools socket closed, the browser exited or was killed (bun test kills every process a file started when one of its tests or hooks times out)')); @@ -215,6 +248,8 @@ export class BrowserPage { const userDataDir = options.userDataDir ?? mkdtempSync(join(tmpdir(), `${E2E_DIR_PREFIX}browser-`)); const port = options.debugPort ?? (await freePort()); const size = options.windowSize ?? { width: 1440, height: 900 }; + // Where each request waited (cache, socket pool, connection, server) when a page stalls. + const netlog = TRACE && process.env.BOITE_E2E_TRACE_DIR ? join(process.env.BOITE_E2E_TRACE_DIR, `netlog-${port}-${Date.now()}.json`) : null; const proc = Bun.spawn({ cmd: [ @@ -246,6 +281,7 @@ export class BrowserPage { `--window-size=${size.width},${size.height}`, `--user-data-dir=${userDataDir}`, `--remote-debugging-port=${port}`, + ...(netlog ? [`--log-net-log=${netlog}`, '--net-log-capture-mode=Default'] : []), ...(options.args ?? []), 'about:blank', ], @@ -274,6 +310,8 @@ export class BrowserPage { const target = await waitForPageTarget(port, '', proc, true); const socket = await openSocket(target); page = new BrowserPage(socket, proc, ownsUserDataDir ? userDataDir : null, watch); + page.#stderr = () => stderr; + page.#netlog = netlog; open.add(page); await page.send('Page.enable', {}); await page.send('Runtime.enable', {}); @@ -387,7 +425,7 @@ export class BrowserPage { .catch(() => 'the page did not answer either: its main thread is busy'); throw new Error(`${error.message} Page: ${state} -In flight: ${JSON.stringify(this.#inFlight())}`); +In flight: ${JSON.stringify(this.#inFlight())}${this.#trace()}`); })) as { result?: { value?: unknown }; exceptionDetails?: { @@ -415,7 +453,7 @@ In flight: ${JSON.stringify(this.#inFlight())}`); const deadline = Date.now() + timeoutMs; let last = ''; while (Date.now() < deadline) { - if (this.#closed || this.#socket.readyState !== WebSocket.OPEN) throw new Error('the browser is closed'); + if (this.#closed || this.#socket.readyState !== WebSocket.OPEN) throw new Error(`the browser is closed${this.#trace()}`); try { const remaining = Math.max(1, deadline - Date.now()); const ok = await this.evaluate(`(async () => !!(await (${expression})))()`, Math.min(CALL_TIMEOUT_MS, remaining)); @@ -427,10 +465,10 @@ In flight: ${JSON.stringify(this.#inFlight())}`); } await Bun.sleep(Math.min(POLL_MS, Math.max(0, deadline - Date.now()))); } - if (this.#closed || this.#socket.readyState !== WebSocket.OPEN) throw new Error('the browser is closed'); + if (this.#closed || this.#socket.readyState !== WebSocket.OPEN) throw new Error(`the browser is closed${this.#trace()}`); // 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)}`); + 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)}${this.#trace()}`); } async navigate(url: string): Promise { @@ -564,21 +602,44 @@ In flight: ${JSON.stringify(this.#inFlight())}`); open.delete(this); if (this.#proc !== null) await stopBrowser(this.#proc, this.#userDataDir, this.#watch); else if (this.#userDataDir !== null) await removeDirectory(this.#userDataDir); + if (this.#netlog !== null && !this.#keepNetlog) await rm(this.#netlog, { force: true }).catch(() => undefined); + } + + /** What `BOITE_E2E_TRACE` adds to a failure, on its own lines; empty without it. */ + #trace(): string { + if (!TRACE) return ''; + const now = performance.now(); + const lags = loopLag.filter(([at]) => now - at < 30_000).map(([at, ms]) => `${ms} ms ${Math.round((now - at) / 1000)} s ago`); + const ui = (globalThis as { __boiteUiTrace?: () => string }).__boiteUiTrace?.() ?? 'not traced'; + this.#keepNetlog = true; + const stderr = this.#stderr().trim().split('\n').slice(-12).join('\n'); + return `\nTrace: last devtools message ${Math.round(now - this.#heardAt)} ms ago; socket ${this.#closedBy ?? `state ${this.#socket.readyState}`}; browser ${this.#proc === null ? 'attached' : this.#proc.exitCode === null ? `pid ${this.#proc.pid} running` : `exited ${this.#proc.exitCode} (signal ${this.#proc.signalCode})`} +Messages: ${this.#heard} delivered, ${this.#unread} unreadable${this.#firstUnread ? ` (first ${this.#firstUnread})` : ''} +Test loop delays over 50 ms in 30 s: ${lags.length ? lags.slice(-8).join(', ') : 'none'} +UI server: ${ui} +Relay: ${relays.get(this.#socket)?.report() ?? 'none'} +Net log: ${this.#netlog ?? 'none'} +Browser stderr tail: +${stderr || '(empty)'}`; } /** 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.entries()].filter(([, request]) => now - request.at > 1_000).slice(0, 10) + .map(([id, request]) => `${request.url} ${request.answered ? 'answered, body pending' : TRACE ? `no response, ${this.#sent.has(id) ? 'headers sent' : 'headers never sent'}` : 'no response'} for ${now - request.at} ms`); } #receive(raw: string): void { - if (raw === '') return; + this.#heardAt = performance.now(); + this.#heard++; + if (raw === '') { this.#unread++; this.#firstUnread ||= 'a binary or empty message'; 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 } }; try { frame = JSON.parse(raw) as typeof frame; } catch { + this.#unread++; + this.#firstUnread ||= JSON.stringify(raw.slice(0, 80)); return; } if (typeof frame.id !== 'number') { @@ -591,6 +652,7 @@ In flight: ${JSON.stringify(this.#inFlight())}`); 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.requestWillBeSentExtraInfo') this.#sent.add(id); else if (frame.method === 'Network.responseReceived') { const request = this.#requests.get(id); if (request) request.answered = true; @@ -598,6 +660,7 @@ In flight: ${JSON.stringify(this.#inFlight())}`); } else if (frame.method === 'Network.loadingFinished' || frame.method === 'Network.loadingFailed') { if (frame.method === 'Network.loadingFailed') this.#recordNetworkFailure(id, frame.params?.errorText ?? 'loading failed'); this.#requests.delete(id); + this.#sent.delete(id); } } return; @@ -706,11 +769,24 @@ export async function probeDebuggingPort(port: number): Promise { } } -function openSocket(target: TargetInfo): Promise { +/** Under `BOITE_E2E_TRACE`, each devtools socket's relay, which checks the frames the browser sent. */ +const relays = new WeakMap(); + +async function openSocket(target: TargetInfo): Promise { const url = target.webSocketDebuggerUrl; if (url === undefined) throw new Error('the page target has no debugger url'); + const traced = TRACE ? await relay(url) : null; return new Promise((resolve, reject) => { - const socket = new WebSocket(url); + const socket = new WebSocket(traced?.url ?? url); + if (traced) { + relays.set(socket, traced); + socket.addEventListener('close', (event) => { + // A protocol error keeps the browser's bytes for a replay against Bun's client (`BOITE_E2E_TRACE_DIR`). + const dir = process.env.BOITE_E2E_TRACE_DIR; + if (event.code === 1002 && dir) console.warn(`[e2e] devtools socket closed 1002, kept ${traced.dump(join(dir, `devtools-${Date.now()}`))}`); + setTimeout(() => traced.close(), 100); + }, { once: true }); + } // A socket that never opened is closed with its refusal: nothing else // holds it, and a late open would keep its connection for the whole run. const fail = (message: string) => { diff --git a/tests/e2e/lib/ui.ts b/tests/e2e/lib/ui.ts index fe046efc4..1214aa19f 100644 --- a/tests/e2e/lib/ui.ts +++ b/tests/e2e/lib/ui.ts @@ -18,6 +18,38 @@ export const fixtureBridge = { }, }; +/** + * `BOITE_E2E_TRACE=1`: the preview server times every request, and a failing + * page's trace (`lib/cdp.ts`) says which ones it still owes and which took + * over a second, to tell a server that never answered from a browser that + * never read the answer. + */ +const traced = { open: new Map(), slow: [] as string[], next: 0, served: 0 }; +const requestTrace = { + name: 'boite-e2e-request-trace', + configurePreviewServer(server: { middlewares: { use(handler: (req: { url?: string }, res: { once(event: 'close', listener: () => void): void }, next: () => void) => void): void } }) { + server.middlewares.use((req, res, next) => { + const id = traced.next++, at = Date.now(), url = req.url ?? '?'; + traced.open.set(id, { url, at }); + res.once('close', () => { + traced.open.delete(id); + traced.served++; + const ms = Date.now() - at; + if (ms > 1_000) { traced.slow.push(`${url} ${ms} ms`); if (traced.slow.length > 10) traced.slow.shift(); } + }); + next(); + }); + }, +}; +if (process.env.BOITE_E2E_TRACE === '1') { + (globalThis as { __boiteUiTrace?: () => string }).__boiteUiTrace = () => { + const now = Date.now(); + const open = [...traced.open.values()].map(request => `${request.url} for ${now - request.at} ms`).slice(0, 8); + return `${traced.served} served; open: ${open.length ? open.join(', ') : 'none'}; over 1 s: ${traced.slow.length ? traced.slow.join(', ') : 'none'}`; + }; +} +const previewPlugins = process.env.BOITE_E2E_TRACE === '1' ? [requestTrace] : []; + /** Build fake-client fixtures once in CI, keeping cold transforms outside browser interaction deadlines. */ export async function startUi(port: number, options: { development?: boolean } = {}): Promise<{ close(): Promise }> { const address = { host: '127.0.0.1', port, strictPort: true }; @@ -25,14 +57,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: previewPlugins, 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: previewPlugins, build: { outDir: fixtureDir }, preview: address, clearScreen: false }); } return startDevUi(port); } diff --git a/tests/e2e/lib/ws-relay.ts b/tests/e2e/lib/ws-relay.ts new file mode 100644 index 000000000..218e25237 --- /dev/null +++ b/tests/e2e/lib/ws-relay.ts @@ -0,0 +1,164 @@ +/* + * `BOITE_E2E_TRACE=1` (CI flake loops): a loopback relay between the test's + * devtools WebSocket and the browser. It checks every frame the browser sends + * against RFC 6455 as the bytes pass, so a socket Bun closes with 1002 + * ("control frame is fragmented", "unexpected opcode") can be told apart: a + * malformed stream from the browser, or a well-formed one Bun misread. + */ + +import { writeFileSync } from 'node:fs'; + +/** A devtools stream past this stops being kept for a replay; the check goes on. */ +const KEEP_BYTES = 64 << 20; + +interface Frame { at: number; opcode: number; fin: boolean; compressed: boolean; length: number } + +/** Reads frame headers as bytes arrive and skips payloads; keeps the first error and the last frames and reads. */ +export class FrameCheck { + #buffer = new Uint8Array(0); + #skip = 0; + /** Stream bytes before the buffer, skipped payloads included, and all bytes seen. */ + #offset = 0; + #total = 0; + #handshake = true; + /** The `Sec-WebSocket-Extensions` the browser accepted; `permessage-deflate` lets a message's first frame set RSV1. */ + #extensions = ''; + #frames = 0; + /** Complete data messages, to compare with what the test's socket delivered. */ + #messages = 0; + #recent: Frame[] = []; + #chunks: Array<{ at: number; length: number; ms: number }> = []; + #error: string | null = null; + #started = performance.now(); + /** Every read as it arrived, up to `KEEP_BYTES`, for `dump` to replay. */ + #kept: Uint8Array[] = []; + #keptBytes = 0; + + push(bytes: Uint8Array): void { + this.#chunks.push({ at: this.#total, length: bytes.length, ms: Math.round(performance.now() - this.#started) }); + this.#total += bytes.length; + if (this.#keptBytes + bytes.length <= KEEP_BYTES) { this.#kept.push(bytes); this.#keptBytes += bytes.length; } + if (this.#chunks.length > 12) this.#chunks.shift(); + if (this.#error) return; + let data = bytes; + if (this.#skip > 0) { + const used = Math.min(this.#skip, data.length); + this.#skip -= used; this.#offset += used; data = data.subarray(used); + } + const joined = new Uint8Array(this.#buffer.length + data.length); + joined.set(this.#buffer); joined.set(data, this.#buffer.length); + let at = 0; + if (this.#handshake) { + const end = indexOfHeaderEnd(joined); + if (end === -1) { this.#buffer = joined; return; } + at = end; this.#handshake = false; + this.#extensions = /^sec-websocket-extensions:\s*(.*)$/im.exec(new TextDecoder().decode(joined.subarray(0, end)))?.[1]?.trim() ?? ''; + } + while (!this.#error) { + const rest = joined.length - at; + if (rest < 2) break; + const first = joined[at]!, second = joined[at + 1]!; + let length = second & 0x7f, header = 2; + if (length === 126) { if (rest < 4) break; length = (joined[at + 2]! << 8) | joined[at + 3]!; header = 4; } + else if (length === 127) { + if (rest < 10) break; + length = 0; + for (let i = 2; i < 10; i++) length = length * 256 + joined[at + i]!; + header = 10; + } + const frame = { at: this.#offset + at, opcode: first & 0x0f, fin: (first & 0x80) !== 0, compressed: (first & 0x40) !== 0, length }; + this.#error = problem(first, second, frame, this.#extensions.includes('permessage-deflate')); + this.#frames++; + if (frame.fin && frame.opcode <= 2) this.#messages++; + this.#recent.push(frame); + if (this.#recent.length > 12) this.#recent.shift(); + const payload = Math.min(length, rest - header); + at += header + payload; + if (payload < length) { this.#skip = length - payload; break; } + } + this.#offset += at; + this.#buffer = joined.slice(at); + } + + /** What the browser sent, as one file of bytes and one of read lengths, so a replay cuts it the same way. */ + dump(path: string): string { + const whole = new Uint8Array(this.#keptBytes); + let at = 0; + for (const part of this.#kept) { whole.set(part, at); at += part.length; } + writeFileSync(`${path}.bin`, whole); + writeFileSync(`${path}.reads.json`, JSON.stringify(this.#kept.map(part => part.length))); + return `${path}.bin (${whole.length} of ${this.#total} bytes)`; + } + + report(): string { + const frames = this.#recent.map(frame => `${frame.at}:op${frame.opcode}${frame.compressed ? ' deflated' : ''}${frame.fin ? '' : ' unfinished'} ${frame.length} B`).join(', '); + const reads = this.#chunks.map(chunk => `${chunk.at}+${chunk.length} at ${chunk.ms} ms`).join(', '); + return `browser stream (extensions ${this.#extensions || 'none'}) ${this.#error ? `malformed: ${this.#error}` : 'well-formed'} over ${this.#frames} frames, ${this.#messages} messages and ${this.#total} bytes; last frames ${frames || 'none'}; last reads ${reads}`; + } +} + +function problem(first: number, second: number, frame: Frame, deflate: boolean): string | null { + if (first & (deflate && (frame.opcode === 1 || frame.opcode === 2) ? 0x30 : 0x70)) return `reserved bits set at byte ${frame.at}`; + if (second & 0x80) return `a masked server frame at byte ${frame.at}`; + if (![0, 1, 2, 8, 9, 10].includes(frame.opcode)) return `opcode ${frame.opcode} at byte ${frame.at}`; + if (frame.opcode >= 8 && (!frame.fin || frame.length > 125)) return `a fragmented or long control frame at byte ${frame.at}`; + return null; +} + +function indexOfHeaderEnd(bytes: Uint8Array): number { + for (let i = 3; i < bytes.length; i++) if (bytes[i - 3] === 13 && bytes[i - 2] === 10 && bytes[i - 1] === 13 && bytes[i] === 10) return i + 1; + return -1; +} + +/** Each side writes what fits now and the rest once it drains, in order. */ +function sender(): { write(socket: { write(bytes: Uint8Array): number }, bytes: Uint8Array): void; drain(socket: { write(bytes: Uint8Array): number }): void } { + const queue: Uint8Array[] = []; + const drain = (socket: { write(bytes: Uint8Array): number }) => { + while (queue.length) { + const chunk = queue[0]!, written = socket.write(chunk); + if (written < 0) { queue.length = 0; return; } + if (written < chunk.length) { queue[0] = chunk.subarray(written); return; } + queue.shift(); + } + }; + return { write: (socket, bytes) => { queue.push(bytes); if (queue.length === 1) drain(socket); }, drain }; +} + +/** A `ws://` url on a loopback relay to `url`, and the check of what the browser sent through it. */ +export async function relay(url: string): Promise<{ url: string; report(): string; dump(path: string): string; close(): void }> { + const target = new URL(url); + const check = new FrameCheck(); + const toBrowser = sender(), toTest = sender(); + let upstream: Bun.Socket | null = null; + let early: Uint8Array[] = []; + let test: Bun.Socket | null = null; + const server = Bun.listen({ + hostname: '127.0.0.1', port: 0, + socket: { + async open(socket) { + test = socket; + upstream = await Bun.connect({ + hostname: target.hostname, port: Number(target.port), + socket: { + data(_upstream, bytes) { const copy = bytes.slice(); check.push(copy); toTest.write(socket, copy); }, + drain(own) { toBrowser.drain(own); }, + close() { socket.end(); }, + error() { socket.end(); }, + }, + }); + for (const bytes of early) toBrowser.write(upstream, bytes); + early = []; + }, + data(_socket, bytes) { const copy = bytes.slice(); if (upstream) toBrowser.write(upstream, copy); else early.push(copy); }, + drain(socket) { toTest.drain(socket); }, + close() { upstream?.end(); }, + error() { upstream?.end(); }, + }, + }); + return { + url: `ws://127.0.0.1:${server.port}${target.pathname}`, + report: () => check.report(), + dump: path => check.dump(path), + close: () => { test?.end(); upstream?.end(); server.stop(true); }, + }; +} diff --git a/tests/e2e/machines.test.ts b/tests/e2e/machines.test.ts index b97b7e358..ff3cebfc3 100644 --- a/tests/e2e/machines.test.ts +++ b/tests/e2e/machines.test.ts @@ -398,12 +398,37 @@ test('one invitation groups two real cores: the page connects the second by itse return { workspace, firstGroup: group(firstGroup), secondGroup: group(secondGroup), sessions: sessions.map(session => ({ id: session.id, role: session.role, group: session.group })) }; }; + // SCRATCH timeline: each machine's store every 100 ms, with which store object it is and what this device's storage says. + const t0 = Date.now(); + const timeline: string[] = []; + let polling = true; + const probe = `(() => { const tags = globalThis.__tags ??= new WeakMap(); let n = globalThis.__tagN ??= 0; + const tag = (s) => { if (!tags.has(s)) { globalThis.__tagN = ++n; tags.set(s, n); } return tags.get(s); }; + return JSON.stringify({ m: globalThis.__boiteTest.workspace.machines.map(m => [m.id.slice(-5), m.coreId ? 'brought' : '-', tag(m.store), m.store.connection, + m.store.groupKnown, m.store.group === null ? null : m.store.group?.cores.length, m.store.ungrouped, m.store.pairingRequired, m.store.error ?? null]), + envs: JSON.parse(localStorage.getItem('boite.envs') ?? '[]').map(e => [e.url.slice(-5), !!e.signs, !!e.token]), + core: (JSON.parse(localStorage.getItem('boite.core') ?? 'null') ?? {}).url?.slice(-5) ?? null }); })()`; + let previous = ''; + const poll = (async () => { + while (polling) { + const now = String(await page.evaluate(probe).catch((error) => `probe failed: ${error}`)); + if (now !== previous) timeline.push(`${Date.now() - t0} ${now}`); + previous = now; + await Bun.sleep(100); + } + })(); await a.call('group.remove', { coreId: joined.self }); try { await page.waitFor(`globalThis.__boiteTest.workspace.machines.length === 1`, 20_000); } catch (error) { console.error('Group removal state:', JSON.stringify(await removalState().catch(() => 'group diagnostics unavailable'))); + polling = false; + await poll; + console.error(`Removal timeline:\n${timeline.join('\n')}`); throw error; + } finally { + polling = false; + await poll; } expect(await b.call('group.get', {})).toBeNull(); expect((await b.call('sessions.list', {})).filter((session) => session.group)).toEqual([]);