Skip to content
Firestore flake probe

Firestore flake probe #4

Sign in to view logs

Firestore flake probe

Firestore flake probe #4

Workflow file for this run

.github/workflows/flake-probe.yaml at 23da94e
# 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