CI: real-timer userEvent tests time out in SearchPicker/HouseholdItemPicker, blocking promotion

[steilerDev]

CORRECTION (posted after diagnosis). The "Likely cause" section as originally filed blamed the @testing-library/user-event 14.6.1 -> 14.6.7 bump. That is wrong and has been refuted twice. The corrected diagnosis is below. Do not re-run the dependency bisection — it has now been done twice with a negative result.

Problem

Quality Gates fails on the beta -> main promotion PR (#2075). 11 tests fail, all of them 60-second timeouts, confined to two files:

• client/src/components/SearchPicker/SearchPicker.test.tsx — 9 failures
• client/src/components/HouseholdItemPicker/HouseholdItemPicker.breadcrumb.test.tsx — 2 failures

All 16 E2E shards pass. No assertion failures anywhere — purely wall-clock exhaustion.

Evidence

Shard wall-clock times across consecutive runs:

Run	Shards 1-4	Shard 5	Shard 6
PR #2071 (merged 06:19)	7-10 min	8 min PASS	7 min PASS
PR #2070 (dev-deps bump, merged 11:19)	9-11 min	26 min PASS	needed a retry to pass
PR #2075 (promotion)	9-12 min	45 min FAIL	22 min FAIL

Shards 1-4 were healthy on the same run where 5 and 6 blew up, so the CI runner as a whole was fine.

Root cause (corrected)

Not a dependency regression. Not a production bug. Not a bad assertion. This is real-timer scheduling latency in the test harness.

Under real timers, every userEvent sub-event awaits wait(config) — a real setTimeout(..., 0) inside the jsdom vm context. A single user.click() dispatches the full pointer/focus/click sequence, each step yielding a macrotask, each running pointerEventsCheck: EachApiCall (an ancestor walk calling getComputedStyle per level). So:

cost = (number of macrotask yields) x (event-loop scheduling latency)

On a contended runner with 6 Jest workers the latency term dominates. That is precisely why the timeline above worsens monotonically (8 -> 26 -> 45 min) with no code change between runs — a dependency-caused regression would have stepped once and stayed flat.

The decisive evidence is a control group inside the failing file itself. SearchPicker.test.tsx lines 79 and 100 use the fake-timer idiom. Those two tests type into the same input, flip the same isOpen, and mount the same FloatingPortal for the first time — and they are fast and have never failed. The cost therefore is not the portal mount's CPU work; it is the real-timer scheduling around it. Fake timers collapse every yield into a synchronous advanceTimersByTime, which is why the control group is immune.

Why the dependency bump was ruled out

1. Bisection on PR chore(deps-dev): bump the dev-dependencies group across 1 directory with 20 updates #2070: a scratch install of @testing-library/react@16.3.2 @testing-library/user-event@14.6.1 jest@30.4.2 jest-environment-jsdom@30.4.1 reproduced identical failures — same test names, same shape — on the old versions. This result is already recorded in the jest.config.ts comment committed by chore(deps-dev): bump the dev-dependencies group across 1 directory with 20 updates #2070.
2. Binary diff of the two published user-event tarballs (normalizing transpiler churn): the only substantive changes in dist/esm are a key-repeat flag in keyboard/index.js and a property-descriptor form change in document/patchFocus.js. utils/misc/wait.js is byte-identical and delay: 0 is unchanged in setup/setup.js. No hot-path change capable of a 5x regression.

A separate earlier investigation on PR #2073 had already excluded i18next/react-i18next by controlled swap.

Why raising the timeout again is the wrong fix

PR #2070 responded to this by raising the global testTimeout to 60000. We are now past that ceiling too. Raising it a third time keeps a 45-minute shard in the critical path of every promotion.

Fix

Convert all 57 real-timer userEvent.setup() call sites in the two files (47 + 10) to the fake-timer idiom already proven by the in-file control group, via a local per-file helper:

function setupUser() {
  jest.useFakeTimers();
  return userEvent.setup({ advanceTimers: jest.advanceTimersByTime.bind(jest) });
}

Partial conversion will not work. The failing set is not determined by test content — line 307 fails while the near-identical line 323 passes; line 164 fails while line 141 with the same shape passes. There is no property separating them, so any "just the marginal ones" list is a snapshot of one run's luck. Converting 9 of 47 also leaves the file's wall clock dominated by the other 38, missing the shard-time criterion.

Scope note on testTimeout

testTimeout: 60000 stays in this fix. There are ~649 real-timer userEvent.setup() call sites across the client suite; this change converts 57. The remaining ~592 still depend on the raised ceiling. Lowering it now would turn a scoped 2-file hotfix into a repo-wide firefight during a blocked promotion. Lowering belongs to the suite-wide follow-up.

Acceptance criteria

• SearchPicker.test.tsx and HouseholdItemPicker.breadcrumb.test.tsx pass reliably in CI (run twice — the failure is probabilistic)
• Shard 5 and shard 6 wall-clock times return toward the ~10-minute range
• Per-test before/after timings captured, so the mechanism is evidenced rather than assumed
• testTimeout value stays exactly 60000 (comment amended, number untouched)
• No production code changes
• No assertion is weakened — any test that goes green by asserting less is a regression, not a fix

Blocking

This blocks the v2.15.0 promotion (PR #2075).

[steilerDev]

Measurement results — two hypotheses falsified, and what that actually means

I measured rather than assumed, and both proposed mechanisms turned out to be wrong in the local environment. Recording this so nobody re-runs these experiments.

Full-file A/B, SearchPicker.test.tsx, --maxWorkers=1, unloaded sandbox

Version	Result	Wall clock
Original (real timers, unconverted)	60/60 pass	1331.6 s
Converted (fake timers), run 1	60/60 pass	1290.7 s
Converted (fake timers), run 2	60/60 pass	1352.0 s

The fake-timer conversion makes no measurable difference locally, and the unconverted original passes locally too. The local sandbox does not reproduce the CI failure at all.

pointerEventsCheck probe (4-test subset, ~21 s/test — subset confirmed representative)

Config	Wall clock
Fake timers (as committed)	110.9 s
Fake timers + pointerEventsCheck: Never	101.3 s

Only ~9%. The getComputedStyle ancestor walk is not the dominant cost either. The ~21 s per-test base cost remains unexplained; it is CPU-bound and lies somewhere else (jsdom layout, floating-ui computePosition, React render, or i18n init).

Why this does not invalidate the fix

The local runs used --maxWorkers=1 with no competing load. That configuration cannot exercise the mechanism the fix targets. An unloaded setTimeout(..., 0) resolves in ~1 ms; under CI's --maxWorkers=2 plus runner noise it does not. So:

• There is a ~21 s CPU base cost per dropdown test, present with or without fake timers, which local runs measure accurately.
• In CI there is additionally scheduling inflation, paid only by real-timer tests, proportional to contention.
• Base alone stays under the 60 s ceiling; base + inflation exceeds it. Fake timers remove the inflation term and nothing else.

That is consistent with every observation, including the one the dependency theory could not explain: the monotonic 8 -> 26 -> 45 min worsening across runs with no code change between them, which tracks contention rather than anything in the tree.

Consequence: CI is the only oracle for this fix. Local green does not prove it works; local no-improvement does not prove it fails. The change is verified safe locally (below), and CI must adjudicate whether it is sufficient.

Safety verification (this part is settled)

• All 173 expect(...) lines byte-identical to the pre-change versions — no assertion weakened
• Test counts unchanged: 60 and 10. No .skip / .only introduced
• Zero userEvent.setup() remaining outside the helper and the two pre-existing control-group tests
• jest.config.ts testTimeout still exactly 60000 — comment-only edit
• Both files pass twice consecutively; lint/format clean
• No production file touched

pointerEventsCheck: Never was considered and rejected

Not merely because it measured poorly (9%), but because it disables userEvent's check that an element is not pointer-events: none. A test could then pass against a control a real user cannot click — assertion-weakening relocated into harness config. Not a trade worth making for wall clock, and it should not be reintroduced later on performance grounds.

If CI still fails

Do not raise testTimeout a third time. The remaining lever is the unexplained ~21 s base cost — profile where it actually goes (that measurement has never been done) before changing anything else. #2077 tracks the broader idiom rollout.

[steilerDev]

Resolved as a promotion blocker — but AC2 was NOT met

Fixed by #2079 (merged to `beta` as `e3ccf553`). `Quality Gates` is green: all 6 shards pass, including shard 5.

Being explicit, because a merge criterion was fixed in advance for exactly this situation: the agreed test was "judge on shard wall-clock, not merely green — if shard 5 comes back green but still 35-45 minutes, the fix did nothing and we got a quiet runner."

Shard	Pre-#2070 baseline	AC2 target	This run
5	8 min	~10 min	42 min 7 s
6	7 min	~10 min	11 min 56 s

So AC2 (return to ~10 min) is not met, and this issue is not being closed on the basis that the slowness was solved. It wasn't. It was given headroom.

What is resolved: the 60-second timeouts that blocked the v2.15.0 promotion. The tests pass, no assertion was weakened, and no production code changed.

What actually caused it

Not the dependency bump, not real timers, not worker contention — all three were falsified by measurement (see the earlier comments and #2079). The cause is a machine-speed gap: GitHub-hosted runners are ~1.8x slower single-threaded than the dev boxes the 60 s ceiling was calibrated on (SearchPicker 2326 s CI vs 1330 s local; WorkItemPicker 436 s vs 224 s). At ~39 s/test in CI the heaviest tests cross 60 s and the rest don't.

That also explains the two things that made this look mysterious: near-identical tests splitting across the pass/fail boundary (line 307 failed, line 323 passed), and the monotonic 8 -> 26 -> 45 min worsening with no code change — it tracks runner speed, not the tree.

The residual, and where it lives

The ~21 s per-test CPU cost on a dev box (~40 s in CI) is completely unexplained. Two hypotheses for it have now been falsified by measurement: pointerEventsCheck: Never removes only ~9%, and coverage instrumentation only 0.3%.

That residual is carried by #2078, whose next step is node --cpu-prof on a single dropdown test. Closing here rather than keeping two issues open for the same residual work — #2077 was already consolidated into #2078 for the same reason. The work is not finished, it has an owner.

Anyone reading a future green Quality Gates should not infer the slowness was fixed. The suite now sits under the ceiling with headroom instead of just over it — which is the same thin-margin state that #2070 created and that took about three weeks to breach.