diff --git a/.github/workflows/flake-probe.yaml b/.github/workflows/flake-probe.yaml deleted file mode 100644 index 7ada538a..00000000 --- a/.github/workflows/flake-probe.yaml +++ /dev/null @@ -1,514 +0,0 @@ -# Measures the `test/firestore.test.tsx` flake rate (#776) in CI rather than locally. -# -# Every measurement of this flake so far has been on a laptop, where the failure looks -# like a plain `waitFor` timeout. In CI it comes with a gRPC framing desync -# (`RESOURCE_EXHAUSTED: Received message larger than max`), which may mean the two are -# not the same bug. This runs both `@grpc/grpc-js` arms on both Node versions under CI -# conditions so the comparison is made where the failure actually happens. -# -# Both arms run inside a single job, sequentially on the same runner. They are -# deliberately NOT a matrix dimension: the whole premise is that the machine matters, -# so splitting the arms across two runners would reintroduce the variable being tested. -# -# WORKLOAD. The first run of this probe (2026-08-07) came back 120/120 clean in -# `firestore-only` mode, with zero `RESOURCE_EXHAUSTED`. That configuration runs one -# emulator and one test file, while the failures in #776 come from `npm run test`: five -# 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 - -on: - workflow_dispatch: - inputs: - workload: - description: "Which workload to run each iteration" - required: false - type: choice - default: "full-suite" - options: - - "full-suite" - - "firestore-only" - iterations: - description: "Test runs per arm (full-suite ~23s each, firestore-only ~8s each)" - required: false - default: "30" - node_versions: - description: "JSON array of Node majors to probe" - required: false - default: '["22", "24"]' - arms: - description: "JSON array of grpc-js arms: baseline, override, or both" - required: false - # 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: - contents: read - -jobs: - probe: - runs-on: ubuntu-latest - # Sized 2026-08-07 on the `Run tests` step of the real CI job (not the whole job, - # which is ~57s including install and setup). - # - # ⚠️ Do NOT size this on a single figure. Across recent CI runs that step lands - # anywhere from 20 to 31 seconds, and a timeout cares about the slow tail, not the - # median. At 31s the 200 cap wants ~207 minutes, which a flat-23s estimate (~153) - # would have put comfortably inside 180. And if #776's reported ~120s hang ever - # reproduces, those iterations cost far more than any of this. - # - # The default 30 per arm is ~28-38 minutes full-suite and is safe under any reading. - # This ceiling exists for the 200 cap, so it is set past the pessimistic figure - # rather than the average one. The `always()` summary step means a run that does hit - # the wall still reports the arms that finished. - timeout-minutes: 240 - strategy: - matrix: - node: ${{ fromJSON(inputs.node_versions) }} - fail-fast: false - name: Probe Node ${{ matrix.node }} - steps: - - name: Checkout - uses: actions/checkout@11d5960a326750d5838078e36cf38b85af677262 # v4.4.0 - with: - persist-credentials: false - - - name: Setup node - uses: actions/setup-node@49933ea5288caeca8642d1e84afbd3f7d6820020 # v4.4.0 - with: - node-version: ${{ matrix.node }} - check-latest: true - cache: 'npm' - - - name: Setup Java - uses: actions/setup-java@c1e323688fd81a25caa38c78aa6df2d33d3e20d9 # v4.8.0 - with: - distribution: 'temurin' - java-version: '21' - - - name: Firebase emulator cache - uses: actions/cache@0057852bfaa89a56745cba8c7296529d2fc39830 # v4.3.0 - with: - path: ~/.cache/firebase/emulators - key: firebase_emulators - - - name: Install deps - run: npm ci - - # The full suite starts the functions emulator, which will not come up without - # these. `test.yaml` does the same thing before `npm run test`. Skipped in - # firestore-only mode, where no functions emulator is started. - - name: Install deps for functions - if: ${{ inputs.workload == 'full-suite' }} - run: npm install --no-audit --no-fund - working-directory: ./functions - - # Inputs and matrix values are passed through `env` rather than interpolated into - # the script body, so nothing from the dispatch form can be executed as shell. - # - # Counts are appended to `probe-counts.tsv` as each arm finishes, and the summary - # is rendered by a separate `always()` step. If the job hits its timeout partway - # through, whatever was measured before the wall still gets reported. - - name: Run the probe - env: - ITERATIONS: ${{ inputs.iterations }} - ARMS: ${{ inputs.arms }} - WORKLOAD: ${{ inputs.workload }} - NODE_MAJOR: ${{ matrix.node }} - run: | - # ⚠️ errexit is ON here even though nothing below turns it on: GitHub runs an - # undeclared `run:` step as `bash -e {0}`, and `set -uo pipefail` does not - # disable it. Every command that is ALLOWED to fail therefore has to say so. - # Getting this wrong means the step dies on the first failing iteration and - # the probe can only ever report a clean table, which is the one failure mode - # that makes the whole workflow useless. See the loop below. - set -uo pipefail - - # Guard against a non-numeric or absurd `iterations` before it reaches the loop. - case "$ITERATIONS" in - ''|*[!0-9]*) echo "iterations must be a positive integer, got '$ITERATIONS'"; exit 1 ;; - esac - if [ "$ITERATIONS" -lt 1 ] || [ "$ITERATIONS" -gt 200 ]; then - echo "iterations must be between 1 and 200, got '$ITERATIONS'" - exit 1 - fi - - # `full-suite` reproduces what `npm run test` does in CI: every emulator in - # firebase.json, every test file. `firestore-only` is the narrower original, - # kept because it isolates the Firestore client and is ~3x faster per run. - case "$WORKLOAD" in - full-suite) - EMULATOR_ARGS="" - VITEST_ARGS="" - ;; - firestore-only) - EMULATOR_ARGS="--only firestore" - VITEST_ARGS="firestore" - ;; - *) - echo "workload must be full-suite or firestore-only, got '$WORKLOAD'" - exit 1 - ;; - esac - echo "Workload: $WORKLOAD" - - # Validate the arm list rather than trusting the dispatch form, and normalize - # it to a space-separated list. Order is forced baseline-then-override because - # applying the override mutates node_modules for everything after it. - ARM_LIST="$(node -e ' - const arms = JSON.parse(process.env.ARMS); - if (!Array.isArray(arms) || arms.length === 0) throw new Error("arms must be a non-empty JSON array"); - const allowed = ["baseline", "override"]; - for (const a of arms) if (!allowed.includes(a)) throw new Error("unknown arm: " + a); - process.stdout.write(allowed.filter((a) => arms.includes(a)).join(" ")); - ')" || exit 1 - - mkdir -p probe-logs - : > probe-counts.tsv - : > probe-unmatched.txt - : > probe-iterations.tsv - - for arm in $ARM_LIST; do - echo "::group::Arm: $arm" - - # `npm pkg set` mangles keys containing a slash, so edit package.json directly. - # `npm install` (not `npm ci`) is required here because applying an override - # necessarily changes the lockfile. - if [ "$arm" = "override" ]; then - node -e ' - const fs = require("fs"); - const pkg = JSON.parse(fs.readFileSync("package.json", "utf8")); - pkg.overrides = { ...pkg.overrides, "@grpc/grpc-js": "^1.14.0" }; - fs.writeFileSync("package.json", JSON.stringify(pkg, null, 2) + "\n"); - ' - npm install --no-audit --no-fund - fi - - resolved="$(node -p "require('@grpc/grpc-js/package.json').version")" - echo "Arm $arm resolved @grpc/grpc-js: $resolved" - - pass=0 - flake=0 - infra=0 - hang=0 - grpc_err=0 - flake_with_grpc=0 - - 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. - # Unquoted on purpose: both are either empty or a fixed literal set above, - # never user input. - # - # ⚠️ `set +e` is LOAD-BEARING, do not remove it. This command failing is the - # entire point of the probe, but the step runs under `bash -e`, so without - # this the first flake kills the step before `rc` is even read: no - # 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 --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)) - saw_grpc=1 - fi - - # ⚠️ EVERY QUESTION BELOW IS SCOPED TO FIRESTORE'S OWN OUTPUT, and it has to - # be. In firestore-only mode anything in the log was necessarily about #776. - # In full-suite mode that is false: `expected 'loading' to deeply equal - # 'success'` is just what vitest prints when a data hook's status assertion - # fails, and it appears in 6 of the 9 test files, 40 times over. An unscoped - # search counts a slow storage upload or a functions failure as a #776 flake. - # - # In a vitest log the FAIL line names the file and the assertion or timeout - # sits on the NEXT line, verified against #781's real overnight failure, so - # -A1 is the correct window. Captured into a variable rather than piped into - # `grep -q`, because an early-exiting `grep -q` can SIGPIPE its producer and - # `pipefail` would turn that 141 into a silent "no match". - fs_fails="$(grep -A1 -E "FAIL.*test/firestore\.test\.tsx" "$log" || true)" - - if [ "$rc" -eq 0 ]; then - pass=$((pass + 1)) - 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 - # firestore result this iteration means anything, so the run is void. - # - # ⚠️ Scoped to firestore deliberately. An unscoped check let ANY emulator's - # health failure outrank a real firestore flake in the same run, filing it - # as infra and dropping it from the rate. A non-firestore health failure - # now falls through to the final `else`, where it is still excluded but is - # recorded in probe-unmatched.txt instead of being silently miscounted. - # - # 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 - # The #776 signature, in firestore's output specifically. - flake=$((flake + 1)) - # Whether the gRPC desync and the #776 assertion co-occur is the whole - # question, so count the overlap rather than two independent totals. - if [ "$saw_grpc" -eq 1 ]; then - flake_with_grpc=$((flake_with_grpc + 1)) - fi - 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)) - 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 - # a genuine failure in another test file. Record the first FAIL line from - # anywhere in the log, not just firestore's, so both are visible. - if line="$(grep -m1 -E "FAIL |AssertionError|expected .* to " "$log")"; then - printf '%s run %s: %s\n' "$arm" "$i" "$line" >> probe-unmatched.txt - 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' \ - "$NODE_MAJOR" "$arm" "$resolved" \ - "$pass" "$flake" "$infra" "$hang" "$grpc_err" "$flake_with_grpc" \ - >> probe-counts.tsv - - echo "arm=$arm node=$NODE_MAJOR pass=$pass flake=$flake infra=$infra hang=$hang grpc_err=$grpc_err overlap=$flake_with_grpc" - echo "::endgroup::" - done - - # Rendered separately, and on `always()`, so a job killed by `timeout-minutes` - # still reports every arm that finished before the wall. - - name: Summarize - if: ${{ always() }} - env: - NODE_MAJOR: ${{ matrix.node }} - WORKLOAD: ${{ inputs.workload }} - run: | - set -uo pipefail - - if [ ! -s probe-counts.tsv ]; then - echo "No arm completed; nothing to summarize." >> "$GITHUB_STEP_SUMMARY" - exit 0 - fi - - while IFS=$'\t' read -r node arm resolved pass flake infra hang grpc_err overlap; do - counted=$((pass + flake)) - if [ "$counted" -gt 0 ]; then - # `< /dev/null` so the subshell cannot consume the loop's stdin. - rate="$(node -e "process.stdout.write(((${flake}/${counted})*100).toFixed(1))" < /dev/null)" - else - rate="n/a" - fi - - { - echo "### Node ${node} / ${arm} / ${WORKLOAD} (@grpc/grpc-js ${resolved})" - echo "" - echo "| Outcome | Count |" - echo "| --- | --- |" - echo "| Pass | ${pass} |" - echo "| Flake (#776 signature) | ${flake} |" - echo "| ...of which also showed RESOURCE_EXHAUSTED | ${overlap} |" - echo "| Hang (test timeout, no assertion) | ${hang} |" - echo "| Infra failure (excluded) | ${infra} |" - echo "| Runs showing RESOURCE_EXHAUSTED | ${grpc_err} |" - echo "" - echo "**Flake rate: ${rate}% of ${counted} counted runs.**" - echo "" - if [ "$hang" -gt 0 ] || [ "$infra" -gt 0 ]; then - echo "> ${hang} hang(s) and ${infra} infra failure(s) are excluded from the rate." - echo "" - fi - } >> "$GITHUB_STEP_SUMMARY" - done < probe-counts.tsv - - { - echo "---" - echo "" - if [ "$WORKLOAD" = "firestore-only" ]; then - echo "⚠️ **A clean table here is not a verdict on CI.** This ran one emulator and" - echo "one test file; \`npm run test\` in CI starts five emulators and runs the whole" - echo "suite with parallel workers. The 2026-08-07 run of this mode came back 120/120" - echo "clean with zero \`RESOURCE_EXHAUSTED\`, so this configuration is not known to" - echo "reproduce either the local or the CI failure. Prefer \`full-suite\`." - else - echo "This ran the same workload as CI: every emulator in \`firebase.json\` and the" - echo "whole test suite, one fresh emulator start per iteration. A failure in any" - echo "test file counts, but only the #776 assertion signature counts toward the" - echo "flake rate; anything else is reported separately and listed below." - fi - 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" - echo "" - echo "These runs failed with an assertion the classifier does not know, so they" - echo "were counted as infra. If vitest reworded the #776 message, the flake counts" - echo "above are wrong and the pattern needs updating." - echo "" - echo '```' - cat probe-unmatched.txt - echo '```' - echo "" - } >> "$GITHUB_STEP_SUMMARY" - fi - - # The probe reports; it does not fail. A red job here would mean the probe - # broke, not that the flake reproduced. - total_counted="$(awk -F'\t' '{ s += $4 + $5 } END { print s + 0 }' probe-counts.tsv)" - if [ "$total_counted" -eq 0 ]; then - echo "Every run failed for infrastructure reasons; the probe measured nothing." - exit 1 - fi - - - name: Upload probe logs - if: ${{ always() }} - uses: actions/upload-artifact@ea165f8d65b6e75b540449e92b4886f43607fa02 # v4.6.2 - with: - name: probe-logs-node${{ matrix.node }} - path: | - probe-logs/ - probe-counts.tsv - probe-unmatched.txt - probe-iterations.tsv - retention-days: 7