From af9f0757f19af37020dc1ff3e4f0948f9311146a Mon Sep 17 00:00:00 2001 From: Tyler Dixon Date: Mon, 10 Aug 2026 13:29:34 -0700 Subject: [PATCH] ci(probe): record emulator health-check durations per iteration The grpc-js override was measured and does not fix the flake (baseline 5/60 vs override 4/60, p = 1.0), so the default arm list drops to baseline alone. The arm stays available as a dispatch input. What replaces it is timing. Firestore's health check is a bare addDoc round trip, and every waitFor in test/firestore.test.tsx uses the 1000ms default, so a slow round trip would explain failures landing at 1058ms and 1142ms. Each iteration now records that duration for firestore, auth and database into probe-iterations.tsv, and the summary compares distributions across outcomes. All three because a slow firestore round trip only explains #776 if firestore is slow specifically; if every emulator is slow together, the cause is runner-wide contention instead. The durations come from vitest's json reporter rather than the log, because the default reporter prints a per-test line only above its 300ms slow threshold: the log drops auth entirely and censors the fast end of the other two, so it cannot support a comparison across outcomes. Extraction is scoped by file path, since all three test files open with a test named "double check - emulator is running". The summary reports each arm separately, gives every duration cell its own count of measured iterations, and takes the mean of the two middle values at even n. Refs #776 --- .github/workflows/flake-probe.yaml | 129 +++++++++++++++++++++++++++-- 1 file changed, 124 insertions(+), 5 deletions(-) diff --git a/.github/workflows/flake-probe.yaml b/.github/workflows/flake-probe.yaml index a9af29cc..7ada538a 100644 --- a/.github/workflows/flake-probe.yaml +++ b/.github/workflows/flake-probe.yaml @@ -16,6 +16,10 @@ # emulators and the whole suite. So the isolated suite does not reproduce either failure # and cannot serve as a control. `full-suite` runs the actual CI workload instead. # +# WHAT IT MEASURES NOW (2026-08-10). The grpc-js override was tested and does not fix the +# flake, so the open question is timing: whether the iterations that fail are the ones +# where the emulators were slow. Each iteration records its health-check durations. +# # Manual only. It never runs on a push, a PR or a schedule, so it costs nothing until # someone asks for it. name: Firestore flake probe @@ -42,7 +46,9 @@ on: arms: description: "JSON array of grpc-js arms: baseline, override, or both" required: false - default: '["baseline", "override"]' + # Baseline alone by default since 2026-08-10: the override was measured and does + # not fix the flake (#776). Kept as an option rather than deleted. + default: '["baseline"]' # Least privilege. This workflow reads the repo and writes nothing back. permissions: @@ -169,6 +175,7 @@ jobs: mkdir -p probe-logs : > probe-counts.tsv : > probe-unmatched.txt + : > probe-iterations.tsv for arm in $ARM_LIST; do echo "::group::Arm: $arm" @@ -198,6 +205,7 @@ jobs: for i in $(seq 1 "$ITERATIONS"); do log="probe-logs/$arm-run-$i.log" + json="probe-logs/$arm-run-$i.json" # A fresh emulator start per iteration, matching how `npm test` runs in CI. # Reusing one emulator across iterations would measure a different thing. @@ -210,12 +218,50 @@ jobs: # classification, no tally for the arm, and an empty or half-written # probe-counts.tsv. It was removed once on the reasoning that the script # never sets `-e` itself, which is true and irrelevant. + # ⚠️ The json reporter is what makes the timing usable; do not read durations + # out of the human log instead. The default reporter prints a per-test line + # only above its 300ms slow threshold, pass or fail, so the log drops auth + # entirely and censors the fast end of firestore and database. A comparison + # across outcomes needs every iteration, not the slow ones. set +e npx firebase emulators:exec $EMULATOR_ARGS --project=rxfire-525a3 \ - "npx vitest run $VITEST_ARGS" > "$log" 2>&1 + "npx vitest run $VITEST_ARGS --reporter=default --reporter=json --outputFile.json=$json" > "$log" 2>&1 rc=$? set -e + # Health-check duration per emulator, in ms: firestore, auth, database. All + # three so a slow firestore round trip can be told apart from a slow runner. + # + # ⚠️ Scoped by FILE, not by test title. All three files open with a test named + # `double check - emulator is running`, so matching the title alone records + # whichever one vitest emitted first. + # + # `na` when the json is missing or unparseable, and for auth and database in + # firestore-only mode. Never read it as a fast run. + health_line="$(node -e ' + const fs = require("fs"); + const p = process.argv[1]; + const files = ["test/firestore.test.tsx", "test/auth.test.tsx", "test/database.test.tsx"]; + const out = files.map(() => "na"); + if (!fs.existsSync(p)) { process.stdout.write(out.join("\t")); process.exit(0); } + let report; + try { report = JSON.parse(fs.readFileSync(p, "utf8")); } + catch { process.stdout.write(out.join("\t")); process.exit(0); } + for (const file of report.testResults || []) { + const idx = files.findIndex((f) => String(file.name || "").includes(f)); + if (idx === -1) continue; + for (const a of file.assertionResults || []) { + if (a.title === "double check - emulator is running" && typeof a.duration === "number") { + out[idx] = String(Math.round(a.duration)); + break; + } + } + } + process.stdout.write(out.join("\t")); + ' "$json" 2>/dev/null || true)" + [ -n "$health_line" ] || health_line="$(printf 'na\tna\tna')" + IFS=$'\t' read -r health_ms health_auth health_db <<< "$health_line" + saw_grpc=0 if grep -q "RESOURCE_EXHAUSTED: Received message larger than max" "$log"; then grpc_err=$((grpc_err + 1)) @@ -238,7 +284,8 @@ jobs: if [ "$rc" -eq 0 ]; then pass=$((pass + 1)) - echo "run $i: PASS" + outcome=pass + echo "run $i: PASS (firestore health check ${health_ms}ms)" elif grep -qE "FAIL.*test/firestore\.test\.tsx.*double check - emulator is running" "$log"; then # `test/{auth,firestore,database}.test.tsx` each open with an emulator # health check. If FIRESTORE's fails, its emulator did not come up and no @@ -253,6 +300,7 @@ jobs: # This must precede the hang check either way: a health check fails BY # timing out, so it would otherwise read as the #776 120s hang. infra=$((infra + 1)) + outcome=infra echo "run $i: INFRA FAILURE (rc=$rc), firestore emulator health check failed, excluded from the rate" tail -20 "$log" elif grep -q "expected 'loading' to deeply equal 'success'" <<< "$fs_fails"; then @@ -263,19 +311,22 @@ jobs: if [ "$saw_grpc" -eq 1 ]; then flake_with_grpc=$((flake_with_grpc + 1)) fi - echo "run $i: FLAKE (rc=$rc)" + outcome=flake + echo "run $i: FLAKE (rc=$rc, firestore health check ${health_ms}ms)" elif grep -qE "Test timed out in [0-9]+ms|Hook timed out in [0-9]+ms" <<< "$fs_fails"; then # #776 also reports a ~120s hang. A hang produces no assertion line, so # without this bucket it would land in `infra` and vanish from the rate. # Scoped like the flake check: a timeout in any other test file is not # the #776 hang and must not be presented as one. hang=$((hang + 1)) - echo "run $i: HANG (rc=$rc)" + outcome=hang + echo "run $i: HANG (rc=$rc, firestore health check ${health_ms}ms)" else # Everything else: emulator start failures, a non-firestore health check, # a failure in another test file. Counted separately because folding them # in previously inflated a local flake-rate estimate by ~50%. infra=$((infra + 1)) + outcome=infra echo "run $i: INFRA FAILURE (rc=$rc), excluded from the rate" # Two ways to land here that must not be silent: vitest rewording the #776 # assertion (which would turn every real flake into an infra failure), and @@ -286,6 +337,14 @@ jobs: fi tail -20 "$log" fi + + # One row per iteration, so the health-check duration can be compared across + # outcomes rather than only totalled. The per-arm counts below stay as they + # were; this is additive. + printf '%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\n' \ + "$NODE_MAJOR" "$arm" "$i" "$outcome" \ + "$health_ms" "$health_auth" "$health_db" "$saw_grpc" \ + >> probe-iterations.tsv done printf '%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\n' \ @@ -360,6 +419,65 @@ jobs: echo "" } >> "$GITHUB_STEP_SUMMARY" + # Firestore's health check is a bare `addDoc` round trip and every `waitFor` in + # test/firestore.test.tsx uses the 1000ms default, so a slow round trip would + # explain the failures. Compares distributions, not flake events: a run yields + # few flakes but records a duration every iteration. It describes; overlapping + # ranges are a real answer, not a failed one. + if [ -s probe-iterations.tsv ]; then + { + echo "### Firestore emulator health check, by outcome" + echo "" + node -e ' + const fs = require("fs"); + const rows = fs.readFileSync("probe-iterations.tsv", "utf8").trim().split("\n").filter(Boolean) + .map((l) => l.split("\t")) + .map(([node, arm, i, outcome, fsMs, authMs, dbMs, grpc]) => ({ arm, outcome, fsMs, authMs, dbMs })); + // Even n takes the mean of the two middle values. Taking the upper made + // the median and max cells print the same number at n = 2, and the flake + // row is where n is smallest. + const median = (a) => { + const m = a.length >> 1; + return a.length % 2 ? a[m] : Math.round((a[m - 1] + a[m]) / 2); + }; + // Each cell carries its own n: the row count includes iterations that + // recorded no duration, so a row of 5 can rest on 2 measurements. + const series = (rs, key) => { + const a = rs.map((r) => Number(r[key])).filter((n) => Number.isFinite(n)).sort((x, y) => x - y); + return a.length ? `${median(a)} / ${a[a.length - 1]} (n=${a.length})` : "-"; + }; + // One table per arm. Pooling them would put baseline and override into one + // distribution while the counts tables above stay per-arm. + const arms = [...new Set(rows.map((r) => r.arm))]; + for (const arm of arms) { + const armRows = rows.filter((r) => r.arm === arm); + if (arms.length > 1) { console.log(`Arm: ${arm}`); console.log(""); } + console.log("Median / max, in ms, with the count of iterations that recorded one."); + console.log(""); + console.log("| Outcome | runs | firestore | auth | database |"); + console.log("| --- | --- | --- | --- | --- |"); + for (const name of ["pass", "flake", "hang", "infra"]) { + const rs = armRows.filter((r) => r.outcome === name); + if (!rs.length) continue; + console.log(`| ${name} | ${rs.length} | ${series(rs, "fsMs")} | ${series(rs, "authMs")} | ${series(rs, "dbMs")} |`); + } + console.log(""); + const missing = armRows.filter((r) => !Number.isFinite(Number(r.fsMs))) + .reduce((m, r) => m.set(r.outcome, (m.get(r.outcome) || 0) + 1), new Map()); + if (missing.size) { + const parts = [...missing].map(([outcome, n]) => `${n} ${outcome}`).join(", "); + console.log(`> No firestore duration recorded for ${parts}, usually because the emulator never came up.`); + console.log(""); + } + } + console.log("> Read the columns against each other. Firestore slow while auth and database"); + console.log("> stay flat points at the Firestore client or its stream; all three rising"); + console.log("> together points at runner-wide contention instead, which is a different bug."); + ' || echo "(could not summarize durations)" + echo "" + } >> "$GITHUB_STEP_SUMMARY" + fi + if [ -s probe-unmatched.txt ]; then { echo "### ⚠️ Unrecognized failures" @@ -392,4 +510,5 @@ jobs: probe-logs/ probe-counts.tsv probe-unmatched.txt + probe-iterations.tsv retention-days: 7