ci(F-870): measure Chrome's cold start on every gate run; finding for the POSIX 'Failed to connect to browser' family - #107
Merged
Conversation
A real spawn_browser on a GitHub-hosted Linux or macOS runner intermittently fails with nodriver's "Failed to connect to browser" although Chrome launched and is still running. Five occurrences in 107 completed runs (~4%); Windows control is 0 of 27 failed cells. Oldest occurrence 2026-07-31 - six weeks unfiled, and it costs a full gate rerun each time. Mechanism, measured to 18 ms: nodriver 0.47 hardcodes its connect patience at 0.25 s + 5 x 0.5 s = 2.75 s (core/browser.py:411-435, no Config knob), and all five launch->raise spans measure 2.768-2.803 s. The caller's budget is SPAWN_TIMEOUT = 120 s, so ~117 s of allowance is never spent and no code here can spend it: uc.start() owns the launch and the connect as one await. Cause narrowed by the decisive observation that the install-smoke log could not show: in run 34911829422 the job's FIRST FOUR Chrome launches fail across three different profile directories and the FIFTH succeeds 5.5 s later, followed by ~170 successful spawns. That rules out the port race, a wedged Chrome, and any per-profile or reaper-race explanation, and leaves a cold-start cost. It also means the existing test-side warmups are the warmup succeeding - each failed attempt still pages Chrome in, but each retry is measured against the same wall. Not fixed, deliberately: nobody has ever measured Chrome actual first-launch time-to-DevTools, because the F-860 reaper kills it at 2.8 s and nodriver discards Chrome stderr, so any wait we shipped today would be a guessed constant. The finding records the four fix candidates with verdicts, the two hazards in the attach path, and the one product-free CI experiment that sizes the wait. The macOS headed hit is recorded as a separate, unexplained sub-shape. Also documents an undocumented downstream defect: F-860 reaper kills the process but leaves SingletonLock, so _next_available_explicit_dir silently walks a named profile to -2 - a user-visible identity change with nothing in the answer to announce it. Finding only; no product change, so no CHANGELOG entry.
F-870 proved the POSIX gate's intermittent "Failed to connect to browser" is nodriver spending its hardcoded 2.75 s connect window in full against a Chrome that is alive and not listening yet. It could not prove the CAUSE, because the one number that would settle it has never been measured: how long Chrome's first launch on these images actually takes to open its DevTools endpoint. Two things destroy that evidence on every occurrence - F-860's reaper kills the browser 2.8 s in, and nodriver pipes Chrome's stderr and never reads it, so "DevTools listening on ws://" appears in ZERO of ~100 sampled job logs. tools/chrome_cold_start_probe.py is that measurement, product-free: stdlib only, imports no part of the package (pinned by a test that asserts it in a subprocess), never goes through nodriver. It launches Chrome twice back to back on a fresh profile each time and records ms_to_active_port, ms_to_json_version, the port Chrome actually bound, whether that port is the one requested, the exit code if it died, and a tail of the output. The launch #1 vs #2 delta is what separates a cold page-in cost from machine contention (finding section 3.4). Wired into integration, transport, offline-stealth and install-smoke, placed after the frozen identity resolve (so Chrome cannot be swapped under the measurement) and before the first product Chrome launch (so launch #1 sits where the product's first spawn would). It rides the existing evidence mechanism as a new artifact kind rather than a parallel layout, and it cannot redden a gate: the script exits 0 on every path, so no continue-on-error is needed or used. Three forks worth recording. It calls resolve_chrome._resolve_path(), not the public resolve_chrome(), because the latter shells out for --version and that subprocess pages the binary in, warming the exact thing being timed. Output goes to a temporary file, not a pipe (whose buffer can fill and block the child, so the probe would measure its own deadlock) and not DEVNULL (banned repo-wide for precisely the habit this finding is about). It runs on Windows too: Windows is the control, and "0 of 27 failed cells" is absence of evidence where a measured number is evidence of absence - locally it reads 384 ms then 306 ms against a 2750 ms budget, the first direct explanation of why Windows never shows this. The hermetic test drives a real fake-browser subprocess that writes DevToolsActivePort after a configurable delay and serves /json/version on loopback - a process rather than a mock, because a double that returned the answer directly would prove nothing about polling a file that is not there yet. No real Chrome in the unit lane. CI only; no product code changed.
BLOCKING. http.client.HTTPException is NOT an OSError and urllib does not wrap it, so a socket that accepts and then answers with a non-HTTP line raised BadStatusLine straight out of getresponse() and escaped the probe entirely - reachable in exactly the case this probe studies. Added to the narrow catch, and main() now has ONE outer guard so anything that escapes still writes a record naming it and still returns 0. TemporaryDirectory gets ignore_cleanup_errors because Windows cells run this and Chrome can hold a handle briefly after taskkill /T /F. Readiness signal replaced, on measurement rather than opinion. The first real run returned a null port for every launch while Chrome was demonstrably listening: with a FIXED --remote-debugging-port - which is what the product passes - Chrome does not write DevToolsActivePort at all; that file is a port-discovery mechanism for port 0. The probe now reads Chrome's own "DevTools listening on ws://127.0.0.1:<port>/" banner, which works under both idioms, is Chrome's own statement that the endpoint is up, and carries the port Chrome actually bound. Fields renamed to match: ms_to_devtools_banner, port_from_banner. Flags now mirror nodriver exactly. NODRIVER_DEFAULT_ARGS is 0.47.0's _default_browser_args verbatim and chrome_command reproduces Config.__call__ for the gate's headless/no-sandbox spawn - so NO --disable-gpu (nodriver never passes it) and --password-store=basic and --no-pings ARE passed, without which headless Linux probes the keyring and does GCM registration work the product's Chrome never does. Two tests compare against a real nodriver.Config, so a nodriver bump fails there rather than silently re-defining what is measured. Ports now use nodriver's own idiom (bind :0, close, pass the number), so port_matches_request is a real boolean and H2 is SIZED rather than asserted; verified locally: req=6783 banner=6783 match=True. Also: output excerpt keeps head 2000 + tail 2000, because the banner is among the FIRST lines and a tail-only excerpt discarded exactly the line this finding is about; /json/version timeout 2.0 -> 0.25 s, since a 2 s stall is most of the 2750 ms window being measured; the log is opened twice, once for the child and once by name for us, because a dup SHARES the file offset and seeking a handle the child writes through would corrupt the evidence; probe JSON added to the three human-artifact uploads. Finding amended: the placement decision is now stated once and honestly. The step stays AFTER the identity resolve (the product's own first spawn is also after it, and --freeze-updater has run), and the cost is recorded rather than hidden - resolve_chrome execs the binary on Linux only, so binary_prewarmed is true there and launch #1 is a FLOOR on the cold cost, not the cold cost. The local Windows number is labelled n=1 on one machine, not a property of Windows. Tests: 15, all hermetic, no real Chrome.
…er is not a launch Six review nits on c83cb76, as one commit. 1. `probe` is a generator and `main` appends each finished launch into the list already inside the record. Collecting both and assigning the pair at the end threw launch #1 — the COLD one, the whole point of the measurement — away on exactly the runs where a crash made it interesting. Pinned by a new test that yields one record and then raises. 2. A squatter on the reserved port can no longer score as a launch. Readiness now requires Chrome's banner AND an answer on the port the banner names; an answer on the reserved port before any banner is recorded as `json_answered_before_banner` and never counted. Otherwise the H2 race the probe exists to SIZE would enter the data as a fast successful launch and drag the distribution the wrong way. `listening` restates the invariant so no consumer can read `listening: true` beside a null `port_from_banner`. 3. The two nodriver pins compare ORDERED LISTS, not sets, and import nodriver outright rather than through `importorskip`. `Config.__call__` appends `--disable-session-crashed-bubble` a second time; a set comparison accepted losing that duplicate, and a skip would have let the whole pin vanish in the one environment where the drift is cheapest to notice. 4. `binary_prewarmed` mirrors `resolve_chrome._read_version`'s own branching ("not Windows and not Darwin") instead of naming Linux, so a future POSIX cell is reported correctly rather than silently as `false`. Docstring cites `:118-127` and names the fall-through. 5. `chrome_command`'s docstring no longer claims to reproduce "the launch the PRODUCT makes": it reproduces `nodriver.Config.__call__` for the gate's spawn shape, and says why the product's own `merge_browser_args` `--user-agent` (F-806) is deliberately absent from a product-free probe. 6. The workflow comment's cost figure is labelled as what it is: n=2 on one Windows machine, not a property of Windows. The gate will produce the distribution.
CHANGELOG: the F-870 entry is placed between the F-868 and F-872 entries; every Unreleased entry from main is kept.
Merged
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What this is (F-870): a finding and a measurement, not a product fix
The finding. On GitHub's Linux (and once macOS) runners, a real
spawn_browserintermittently fails with nodriver'sFailed to connect to browseralthough Chrome launched (the F-860 reaper finds and kills the pids). Rate, from two independent censuses that agree on every shared cell: 5 occurrences in 107 completed runs (~4%), all on attempt 1, Windows 0 of 27 failed cells, canary 0 of 40. Root cause proven to 18 ms: nodriver 0.47 hardcodes its connect patience at 0.25 + 5 × 0.5 = 2.75 s (core/browser.py:411-435, no knob), every measured failure raised at 2.77 to 2.80 s, and in run 34911829422 four launches failed across three different profile dirs before the fifth succeeded 5.5 s later. That rules out the port race, a wedged Chrome, and every per-profile explanation, leaving a time-bounded cold-start cost that nobody has ever measured because Chrome is killed at 2.8 s. Full write-up:audit/stage2/finding_F870_posix_ci_nodriver_connect_failures.md. It also traced the-2profile walk seen in the same logs, which is F-871 (PR #105).Why no product change here. The wait cannot be sized without the number; a guessed wait is a knob by another name.
The measurement, now on every gate run.
tools/chrome_cold_start_probe.py(stdlib-only, product-free) launches the gate's Chrome twice back-to-back with nodriver's default argument list reproduced verbatim (pinned against the installednodriver.Config, order-sensitive, so a nodriver bump goes red), reads Chrome's ownDevTools listening on ws://banner and then/json/versionon the port the banner names, and recordsms_to_devtools_banner,ms_to_json_version,port_matches_request(the lost-port race, sized rather than assumed),binary_prewarmed(true on Linux, where the identity step already execschrome --version, so launch 1's number there is a floor), and a head+tail excerpt of Chrome's output (closing the evidence gap: nodriver pipes Chrome's stderr and never relays it). It never fails a job: every path, including an escape from the poller, writes a record naming what happened and exits 0. The step runs on all four real-Chrome jobs including the Windows cells as the control; the JSON rides as a newchrome-cold-startevidence artifact.Evidence
gen_release_contract.py --checkclean; workflow test pins unchanged./json/version340/322 and 379/333 ms, against nodriver's 2750 ms window.What remains