Skip to content

ci(flake-probe): add a full-suite workload mode - #785

Open
tyler-reitz wants to merge 1 commit into
FirebaseExtended:mainfrom
tyler-reitz:ci/probe-full-suite
Open

ci(flake-probe): add a full-suite workload mode#785
tyler-reitz wants to merge 1 commit into
FirebaseExtended:mainfrom
tyler-reitz:ci/probe-full-suite

Conversation

@tyler-reitz

Copy link
Copy Markdown
Contributor

Refs #776, #783. Adds a full-suite workload mode to the flake probe merged in #780.

Why

The probe ran for the first time today: run 31204989659, 30 iterations per arm, both Node versions. 120 of 120 runs passed, with zero RESOURCE_EXHAUSTED.

That is a negative result rather than good news. The probe runs one emulator and one test file; the #776 failures come from npm run test, which starts five emulators and runs the whole suite with parallel workers. Zero flakes in 60 baseline runs excludes the 13.6% local rate for this configuration (0.88^60 is about 0.05%), and by the rule of three the true rate here is under 5%.

Two consequences:

  1. The override arm is uninformative. It cannot improve on a baseline that never failed, so there is still no controlled evidence either way on the @grpc/grpc-js bump.
  2. The isolated suite cannot serve as a control at all, so merging the override would foreclose the comparison rather than merely complicate it.

The fix is to run the workload the failures actually come from.

What this changes

  • New workload input, a choice of full-suite (the new default) or firestore-only. Full-suite runs npx firebase emulators:exec --project=rxfire-525a3 "npx vitest run", which is what test.yaml runs. firestore-only is kept rather than deleted: it isolates the Firestore client and is roughly 3x cheaper per iteration, which is still useful for a targeted question.
  • Functions deps are installed in full-suite mode. test.yaml does npm install in ./functions before npm run test, and the functions emulator does not start without it. The probe was missing this, which would have failed every full-suite iteration.
  • timeout-minutes 60 -> 180. See the arithmetic below.
  • A failing double check - emulator is running is now classified as infra, ahead of the hang check.
  • The summary footer is workload-aware. A firestore-only table now carries a warning naming the 120/120 result and pointing at full-suite.

Correcting the timing figure I published

I previously told #783 and #776 that a full-suite iteration costs about 57s and that this collided with the 60 minute timeout. That was wrong, and both comments have been corrected. 57s was the duration of the whole Test Node.js 22 job including checkout, npm ci, Java setup and artifact download. The Run tests step itself is 23s.

Mode Per iteration 30/arm (60 runs) 50/arm (100 runs) 200/arm (400 runs)
firestore-only ~8s ~10 min ~16 min ~55 min
full-suite ~23s ~28 min ~43 min ~153 min

So the default fits comfortably inside the old 60 minute timeout and the raise is not needed for it. The raise is headroom for the 200 cap, which is the only setting that can hit the wall. The always() summary step added in #780 means a run that does hit it still reports the arms that finished.

The classification bug, and how it was found

Running one full-suite iteration locally and feeding the real log to the classifier is what surfaced this. It came back hang, which is wrong: the failure was the RTDB emulator being unreachable, and an emulator that never came up is infra.

It reached hang because the health check fails by timing out, so it matched Test timed out in 5000ms. test/auth.test.tsx, test/firestore.test.tsx and test/database.test.tsx each open with one of these health checks, so in full-suite mode this would have fired regularly and quietly inflated the hang count, which is the bucket meant for #776's 120s hang.

The check now precedes the hang branch and is anchored on FAIL.*, so a passing health check in the same log does not swallow a real #776 assertion.

Inspection would not have found this. It only showed up against a real log.

Verification

  • One full-suite iteration run locally, end to end. 8 of 9 test files pass; the failure is the unreachable local RTDB emulator, which is what produced the log above. This also confirms the command works and that the functions deps are required.
  • That real log fed through the classifier, before and after the fix: hang before, infra (emulator health) after.
  • Regression cases unchanged: flake, hang, unrecognized-infra, and a log where the health check passes alongside a genuine CI: test/firestore.test.tsx flakes intermittently on both Node 22 and Node 24 #776 assertion, which still classifies as flake.
  • The workload input rejects unknown values before reaching the loop, and the two known values produce the expected emulator and vitest arguments.
  • zizmor 1.25.2: no findings beyond the suppressed cache-poisoning rule.

⚠️ As with #780, the first real full-suite run is the first proof. workflow_dispatch only offers workflows on the default branch, so this cannot be exercised from the PR.

What this changes for anyone else

Nothing. One workflow file, manual dispatch only, no effect on normal CI.

The first run of the probe (2026-08-07, run 31204989659) came back 120/120
clean in firestore-only mode with zero RESOURCE_EXHAUSTED. That configuration
runs one emulator and one test file, while the FirebaseExtended#776 failures 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 for the
@grpc/grpc-js comparison.

Adds a `workload` input, defaulting to `full-suite`, which runs the same
command CI runs. `firestore-only` is kept because it isolates the Firestore
client and is roughly 3x faster per iteration.

Also:

- Install the functions deps in full-suite mode. `test.yaml` does this before
  `npm run test` and the functions emulator does not start without it.
- Raise timeout-minutes to 180. Measured per-iteration cost is ~23s full-suite
  and ~8s firestore-only, so the default 30 per arm is ~28 minutes; the raise
  is headroom for the 200 cap, which is ~153 minutes full-suite.
- Classify a failing `double check - emulator is running` as infra, ahead of
  the hang check. auth, firestore and database each open with that health
  check and it fails by timing out, so without this an emulator that never
  came up was counted as the FirebaseExtended#776 120s hang. Found by running the real suite
  on a machine where the RTDB emulator was unreachable, not by inspection.
- Make the summary footer workload-aware, so a firestore-only table carries a
  warning pointing at the 120/120 result.

Verified: one full-suite iteration run locally end to end (8 of 9 test files
passing, the failure being the unreachable local RTDB emulator), and that real
log fed through the classifier, which is what surfaced the health-check
misclassification; regression cases for flake, hang, infra and a log where the
health check passes alongside a real FirebaseExtended#776 assertion all classify unchanged;
workload input rejects unknown values; zizmor 1.25.2 clean.

Refs FirebaseExtended#776, FirebaseExtended#783.

@armando-navarro armando-navarro left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for turning this around so quickly. A clean sweep was not the result you were hoping for, and widening the probe to the workload that actually fails is the right call.

Two things I would fix before anyone runs this for real. The first is one line.

The probe cannot record a failing run

You did not introduce this, but this PR is where it starts to matter, because the new default mode is the one that is meant to fail sometimes.

The step does not say which shell to use, so GitHub uses its default, which is bash with exit-on-error turned on. The set -uo pipefail at the top of the script adds two other flags and does not turn that one off. The loop is:

npx firebase emulators:exec ... > "$log" 2>&1
rc=$?

With exit-on-error on, a command that fails ends the whole step right there. The next line, the one that reads the exit code, never runs. So the code that decides whether a run was a flake, a hang or an infrastructure problem never gets to see a failing run.

It gets worse after that. The line that writes the tally for an arm sits below the loop, so that arm records nothing. If it is the baseline arm, probe-counts.tsv is still empty and the summarize step prints "No arm completed; nothing to summarize." If baseline had already finished, you get baseline's table and silence where override should be.

The result is that the probe can only ever report a clean table. The first time it genuinely reproduces the flake, the job dies and tells you nothing, which your own comment says should mean the probe broke rather than that the flake reproduced. The 120 out of 120 run never hit this, because nothing in it failed.

I checked that emulators:exec does exit non-zero on a failed test: a forced #776 failure, an unreachable emulator and missing functions dependencies each gave 1, against 0 for a clean suite. Then I reproduced the abort with the same loop structure, under bash -e and under the fuller form GitHub uses for an explicit shell: bash. Both behave the same. Run 1 prints, run 2 kills the step, and nothing after the loop executes.

The version of #780 I reviewed had set +e and set -e wrapped around that command. They came out somewhere before it merged, and I approved that PR without noticing, so this one is at least half mine. Putting them back fixes it, and so would || true, or if ! npx firebase ...; then rc=$?; else rc=0; fi.

You wrote that inspection would not have found the health-check bug, that it only showed up against a real log. Same lesson here, pointed at both of us: this survived your authoring, my review of #780, and a second read today, and only fell over when I ran it. It is also why I would want both fixed before the first real run. Merge, run, learn has served you well, and this is the one bug that breaks that loop, because the first run to reproduce a flake is the one that reports nothing.

The counting still assumes only the firestore tests ran

This one does come from the widening. When the probe ran a single test file, anything it found in the log had to be about #776. That is no longer true, and the searches did not change.

The flake count picks up other files. The string it looks for, expected 'loading' to deeply equal 'success', is simply what vitest prints when expect(result.current.status).toEqual('success') fails. That is how every data-hook test in this repo is written. It appears in 6 of the 9 test files, 40 times over: firestore 19, database 8, auth 6, useObservable 4, functions 2, storage 1.

I checked this rather than assuming it. I moved functions/node_modules out of the way and ran the full suite. Two tests in functions.test.tsx failed with that exact message, and your classifier called the run a flake. Your new install step means that particular cause will not come up in the probe, but the general problem stays. The storage upload-timing test, or any non-firestore emulator being slow, would produce the same line.

The hang count has the same problem. It searches the whole log for Test timed out or Hook timed out, and the summary presents that number as the 120 second hang from #776. Any test in any file that times out lands there. Worth noting that probe-unmatched.txt is no help here, since it is only written in the final else. Anything that lands in flake or hang for the wrong reason does so silently.

And a real flake can be thrown away. The health check runs in three files backed by three separate emulators, and your new branch sits above the flake branch. So if one emulator fails its health check while firestore genuinely flakes in the same run, the log contains both messages, the health check wins, and the flake is filed as infrastructure. It does not even reach probe-unmatched.txt, since that only happens in the final else. Your own local run was that shape: the failure you used to find this bug was the RTDB emulator being unreachable while firestore was fine.

All three go away if the searches are scoped to firestore's output.

My first attempt at that hardcoded the two test names #776 lists, and it was wrong. It would drop a genuine firestore flake that happened to land in a different test in the same file, which is a worse failure than the one it fixes. Scoping to the file avoids both. In a real log the FAIL line naming the file and the assertion line sit next to each other, so:

grep -A1 -E "FAIL.*test/firestore\.test\.tsx" "$log" | grep -q "expected 'loading' to deeply equal 'success'"

I ran that against six logs. It matches the real #776 failure from #781's overnight run, the one I forced by hand, and a firestore failure in a different test. It does not match the functions failure, an unreachable emulator, or a clean run.

One caveat if you use that shape as written. It is a pipeline inside a step that sets pipefail, so a SIGPIPE on the first grep would return 141 and read as no match. I could only trigger it with tens of thousands of matching lines, and that file has 15 tests, so it does not arise. Take whatever shape you prefer, the ask is the file scope.

The same idea works for the hang search, and for the health check, where the question should be whether the firestore health check failed rather than any of them.

Smaller: the 180 minute headroom is thinner than a flat 23 seconds suggests

You sized the raise on 23 seconds an iteration, and 400 times 23 is the 153 minutes in your table. Across the last four CI runs, though, the Run tests step lands anywhere from 20 to 31 seconds. At 31 it would want about 207 minutes, past the 180.

My local runs do show a warm-up effect, 19 seconds for the first iteration against 15 or 16 after, but I would not lean on it: every iteration still boots five fresh JVMs, and what a timeout cares about is the slowest iterations rather than the median. So I am not claiming the real figure is lower, only that a flat 23 is optimistic. The default is fine under any reading. It is the 200 cap, the setting the raise was sized for, that sits close enough to the wall to be worth another look. And if #776's 120 second hang ever reproduces, those iterations cost far more than 23 seconds each, which is the case where the cap and the wall meet.

One related thing, mostly reassurance. Your comment says the separate summarize step means a job killed by timeout-minutes still reports the arms that finished. GitHub's workflow cancellation reference does describe a path where that works: on cancellation the server re-evaluates if conditions, always() comes out true and the step runs, and there is a five minute window before anything still running is forcibly terminated. What the docs do not say is whether a timeout-minutes kill goes down that cancellation path. If it does, you are fine with room to spare, since summarizing takes seconds. Worth knowing only because the tallies are written one per arm, so it is the difference between losing an arm and losing the run.

What I checked that came out fine

  • The full suite runs clean under your new command: 9 files, 69 tests passing, five times out of five, 15 or 16 seconds each on my machine.
  • Your timing diagnosis is right. Taking the Node 22 job of #781's overnight run as an example, the Run tests step was 23 seconds while the job record was 59. Different run from whichever you measured, so do not read anything into 59 against your 57, but the shape is exactly what you describe.
  • Your health check fix works on a log you have never seen. I still had one from Tuesday with the firestore emulator genuinely unreachable: main files it as a hang, yours as infrastructure. The FAIL anchor earns its place too, since that log has 8 lines carrying the phrase and only 1 with FAIL.
  • And it does not misfile the real thing. On the #776 failure in #781's overnight run the health check passed and nothing matches the new pattern, so that run still counts as a flake. One of those passes took 2245ms though, which is worth a look on its own given the failing tests work to a 1000ms budget.

Approving rather than blocking, because merging this does not run anything, and the shell bug is sitting on main whether or not this lands. I would just not trust a table produced before both of those are in.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants