ci: loop flaky tests on their runners with timing traces

.github/workflows/flake-loop.yml

@@ -0,0 +1,154 @@
+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, Spotlight ${{ matrix.spotlight }})
+    # Parked while the cli loop runs alone after #635: set the FLAKE_LOOP_ALL variable to 1 to run it.
+    if: vars.FLAKE_LOOP_ALL == '1'
+    strategy:
+      fail-fast: false
+      matrix:
+        include:
+          # Chromium stopped answering at a load of 25 to 53, with Spotlight's mdworker_shared and mds
+          # the busiest processes, temp folder on disk or in RAM alike (run 39197082818). The same loop
+          # with indexing off.
+          - { os: macos-15, name: macOS arm64, parallel: 4, spotlight: on }
+          - { os: macos-15, name: macOS arm64, parallel: 4, spotlight: off }
+    runs-on: ${{ matrix.os }}
+    timeout-minutes: 75
+    env:
+      BOITE_CDP_TRACE: '1'
+      FLAKE_LOOP_TITLE: Core browser files, ${{ matrix.name }}, ${{ matrix.parallel }} at once, Spotlight ${{ matrix.spotlight }}
+    steps:
+      - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1
+        with:
+          persist-credentials: false
+      - uses: ./.github/actions/setup
+      - name: Spotlight off
+        if: matrix.spotlight == 'off'
+        run: |
+          sudo mdutil -a -i off
+          mdutil -a -s
+      - 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 &)
+          # The five busiest processes every 5 s, to see what indexes or scans while Chromium stalls.
+          (while true; do echo "== $(date -u +%H:%M:%S)"; ps -Aro pcpu,rss,comm | head -6; sleep 5; done > flake-loop/top.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 }}-spotlight-${{ matrix.spotlight }}
+          path: flake-loop/
+
+  cli:
+    name: cli.test.ts (${{ matrix.name }}, Bun ${{ matrix.bun }})
+    if: github.event_name == 'workflow_dispatch' || contains(github.event.pull_request.labels.*.name, 'flake-loop')
+    strategy:
+      fail-fast: false
+      matrix:
+        # The 1002 closes on macOS, 200 runs four at a time: 5 with #623, 11 (as 1006) on Bun canary.
+        # The same loop once #623 is reverted (#635).
+        include:
+          - { os: macos-15, name: macOS arm64, bun: pinned }
+    runs-on: ${{ matrix.os }}
+    timeout-minutes: 45
+    env:
+      FLAKE_LOOP_TITLE: cli.test.ts, ${{ matrix.name }}, Bun ${{ matrix.bun }}
+    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 * 20))" --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 }}-${{ matrix.bun }}
+          path: flake-loop/
+
+  e2e:
+    name: E2E ${{ matrix.mode }}
+    # Parked while the cli loop runs alone after #635: set the FLAKE_LOOP_ALL variable to 1 to run it.
+    if: vars.FLAKE_LOOP_ALL == '1'
+    strategy:
+      fail-fast: false
+      matrix:
+        mode: [alone, shard 1, shard 2, shard 3]
+    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/coordination-bridge-live.test.ts', 'tests/e2e/machines.test.ts'); $runs = [int]$env:RUNS * 2; $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/

docs/ci.md

@@ -121,6 +121,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 Spotlight
+indexing and once without, with disk throughput and load logged each second
+(`iostat.txt`) and the busiest processes every 5 s (`top.txt`), `cli.test.ts` four copies at a time on macOS (the browser and E2E jobs run only with the `FLAKE_LOOP_ALL` variable set to 1), 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

packages/core/src/browser/cdp.ts

@@ -10,12 +10,19 @@
  */
 
 import { fstatSync } from 'node:fs';
+import { loadavg } from 'node:os';
 
 type Listener = (params: Record<string, unknown>, sessionId: string | undefined) => void;
 interface Waiting { resolve(value: Record<string, unknown>): void; reject(error: Error): void; timer: ReturnType<typeof setTimeout>; 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<number, Waiting>();
   #listeners = new Map<string, Set<Listener>>();
   #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<void>;
 
   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<T>((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<string, unknown>) => 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<string> {
+    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<string, unknown>; result?: Record<string, unknown>; 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;

packages/core/src/client.ts

@@ -91,6 +91,8 @@
   const listeners = new Map<string, Set<(payload: unknown) => 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<unknown> => {
     const id = nextId;
@@ -143,6 +145,7 @@
   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 @@
     threadId: hello.threadId ?? null,
     device: hello.device ?? null,
     async call<M extends RpcMethodName>(method: M, params: RpcMethods[M]['params']): Promise<RpcMethods[M]['result']> {
-      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 @@
     ): Promise<RpcEvents[E]> {
       return new Promise<RpcEvents[E]>((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 = {

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")');
 });

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 = `<testsuites>
+  <testsuite name="a.test.ts">
+    <testcase name="first" classname="" time="0.0125" file="a.test.ts" line="1" assertions="1" />
+    <testsuite name="group">
+      <testcase name="second &quot;quoted&quot;" classname="group" time="1.2" file="a.test.ts" line="5" assertions="0">
+        <failure type="AssertionError" />
+      </testcase>
+    </testsuite>
+    <testcase name="filtered" classname="" time="0" file="a.test.ts" line="9" assertions="0">
+      <skipped />
+    </testcase>
+  </testsuite>
+</testsuites>`;
+
+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');
+});