From 119ff42cb11c39bc2594bca68f06384f4223fd35 Mon Sep 17 00:00:00 2001 From: James Thompson Date: Fri, 13 Nov 2026 19:41:10 -0500 Subject: [PATCH 1/2] test: wait for the rename page before typing so the locations example stops flaking The example clicked "Rename Blue binder" and at once filled in "Name". The Locations page it is leaving has a field labelled "Name" too (the add form), so when the visit to the rename page hadn't rendered yet, the text went into the add form; the rename page then arrived holding "Blue binder" and Save renamed the location to its own name. Cause, confirmed from an event timeline (Turbo's visit/render/load events and the fetch, logged in the window, with the rename page's fetch held back 400 ms): fill_in ran at 75-107 ms while location.pathname was /locations and the h1 was "Locations"; the rename page rendered at 433 ms. With no delay the page renders 31 ms after the click and fill_in starts 30 ms later, so the margin on a quick machine is one Selenium round trip and a slow response loses it. A person can't click and type within that time, and no app code is involved (the field is the same on both pages by design). Proof, a temporary spec of the example's rename steps with the fetch of the rename page held back (not committed; its code is in the issue): delay 40 ms: before 8 of 30 runs failed; after 0 of 30 delay 400 ms: before 10 of 10 failed; after 0 of 10 The example alone, no delay, on this machine: 0 of 60 before the change and 0 of 200 after it. That doesn't show the natural rate is gone: 0 of 60 already says it is under about 5%, and 0 of 200 says under about 1.5%, both at 95% confidence, no more. The other system specs were scanned for a click followed at once (or after one statement that isn't an expectation) by a fill or a click of a label the page being left also has; none shares the race: the second control only exists on the new page (bulk_move, select_touch_floor "Select all"; collection_import_preview "Export file"; deck_proxies "Card name", "Finish"; scanner_sitting "End sitting"; admin_jobs "Discard MTG::Art::BuildJob"; collection_location_filter "Remove 3 items"; deck_proxy_replacements' scripted example, whose field label has the lot's place and count), the page 1 of the bulk pager has no "Previous" (bulk_mode), the click opens an in-page menu or dialog (narrow_bulk_pages, collection_export, scanner_page, scanner_art), or the example runs on rack_test, where a click is synchronous (deck_proxy_replacements' second example, deck_additions). Reviewed by Opus 5.5, read-only: SPEC-ALIGNED. Closes #417 Co-Authored-By: Claude Sonnet 5.5 --- spec/system/locations_spec.rb | 3 +++ 1 file changed, 3 insertions(+) diff --git a/spec/system/locations_spec.rb b/spec/system/locations_spec.rb index e7874eba..7c2471d6 100644 --- a/spec/system/locations_spec.rb +++ b/spec/system/locations_spec.rb @@ -12,6 +12,9 @@ expect(page).to have_css(".c-locations__name", text: "Blue binder") click_on "Rename Blue binder" + # Wait for the rename page: this page has a field labelled "Name" too, so until the visit renders, the text goes into + # the add form and the rename page arrives still holding "Blue binder" (#417). + expect(page).to have_css("h1", text: "Rename location") fill_in "Name", with: "Trade binder" click_on "Save" expect(page).to have_css("#status", text: "Renamed “Blue binder” to “Trade binder”.") From 22d411da05220e12ad9b066133f0855a790acff8 Mon Sep 17 00:00:00 2001 From: James Thompson Date: Fri, 13 Nov 2026 20:51:58 -0500 Subject: [PATCH 2/2] chore(memory): capture session learnings (#417) Co-Authored-By: Claude Sonnet 5.5 --- .claude/memory/MEMORY.md | 2 +- .../memory/turbo-back-navigation-quirks.md | 3 ++- ...-provoke-a-rare-race-to-measure-the-fix.md | 25 +++++++++++++++++++ 3 files changed, 28 insertions(+), 2 deletions(-) create mode 100644 docs/lessons/2026-11-13-provoke-a-rare-race-to-measure-the-fix.md diff --git a/.claude/memory/MEMORY.md b/.claude/memory/MEMORY.md index 63d548bd..66aab3b5 100644 --- a/.claude/memory/MEMORY.md +++ b/.claude/memory/MEMORY.md @@ -19,7 +19,7 @@ - [Reproduce CI with its seed](reproduce-ci-with-seed.md) — on CI failure, run the full suite with the CI seed as an early reproduction step; a non-Image flake is re-run once only with the coordinator's go-ahead - [Third-party fault reproducers stay out of the suite](third-party-fault-reproducers-stay-out-of-the-suite.md) — a reproducer asserting a library's fault is the failing-first proof only; code goes in the issue and commit body - [Pre-push CI evidence](pre-push-ci-evidence.md) — a passing pre-push hook prints nothing; cite the pushed SHA, count examples with bin/rspec --dry-run -- [Turbo Back navigation quirks](turbo-back-navigation-quirks.md) — frame-advance has two races (the late visit cancels Back or a click, issue #62); filters now plain Drive GET visits + no-cache; stuck full-width progress bar = cancelled visit; Back within one frame of a render loses the saved scroll (#404); wait_for_turbo_idle, wait_for_scroll_events +- [Turbo Back navigation quirks](turbo-back-navigation-quirks.md) — frame-advance has two races (the late visit cancels Back or a click, issue #62); filters now plain Drive GET visits + no-cache; stuck full-width progress bar = cancelled visit; Back within one frame of a render loses the saved scroll (#404); a click then a fill_in of a label the old page has too types into the old page (#417); wait_for_turbo_idle, wait_for_scroll_events - [Turbo Stream strings are html_safe](turbo-stream-string-is-html-safe.md) — turbo_stream.update(target, "text") inserts the string as HTML; escape card and place names with ERB::Util.html_escape or use a partial (spec 082) - [PR #5 follow-ups](pr5-open-followups.md) — back-button flake fixed by PR #9 (merged 2026-10-02), watch CI; uncaptured failure - [Card scanner direction](card-scanner-direction.md) — spec 011 executed 2026-10-08 (34/35 right card first, margin 300 kept by ruling); next = sdd-review Mode B, then finishing diff --git a/.claude/memory/turbo-back-navigation-quirks.md b/.claude/memory/turbo-back-navigation-quirks.md index f86cc74c..e75d3088 100644 --- a/.claude/memory/turbo-back-navigation-quirks.md +++ b/.claude/memory/turbo-back-navigation-quirks.md @@ -1,6 +1,6 @@ --- name: turbo-back-navigation-quirks -description: Turbo 8.0.23 frame "advance" is racy (snapshot race; late page visit cancels Back or a click); filter pages now use plain Drive GET visits with no-cache; a stuck full-width progress bar means a cancelled visit; Back within one frame of a visit's render loses the saved scroll (#404, wait_for_scroll_events) +description: Turbo 8.0.23 frame "advance" is racy (snapshot race; late page visit cancels Back or a click); filter pages now use plain Drive GET visits with no-cache; a stuck full-width progress bar means a cancelled visit; Back within one frame of a visit's render loses the saved scroll (#404, wait_for_scroll_events); a click then a fill_in of a label the old page has too types into the old page (#417) metadata: type: reference --- @@ -14,6 +14,7 @@ How Turbo 8.0.23 (turbo-rails 2.0.23) behaved with a filter form targeting `turb - **Slowing repaints in a spec:** a `requestAnimationFrame` wrapper must also wrap `cancelAnimationFrame`, or `Visit#cancelRender` can't cancel a render and the cancelled visit still renders. `spec/system/catalog_search_spec.rb` has the full wrapper; the one in `back_navigation_spec.rb` doesn't cancel. - **A queued scroll event overwrites the saved scroll when Back follows a visit within one frame (root-caused 2026-11-13, issue #404).** A Turbo visit scrolls the new page to the top at render, which queues a scroll event for the next frame. `popstate` from a Back in that frame switches `history.restorationIdentifier` to the previous entry first, so `ScrollObserver` records the new page's `{y: 0}` on the *previous* entry, replacing the saved position; the restore visit then reads 0 (`spec/system/menu_tab_bar_clearance_spec.rb`, AC-1.13, `expected 0 to be within 1 of 442.75`, 3 in 60 runs). It isn't the restore reading early, and `wait_for_turbo_idle`'s `aria-busy` check can't see it (cleared at `turbo:load`). Not reachable by a person (the window is one frame, ~16 ms) and no app code is involved. A deterministic reproducer calls `history.back()` from a `turbo:load` handler (7 of 8 runs failed); its code is in the issue. The fix is `wait_for_scroll_events` (`spec/support/turbo_idle.rb`, two animation frames, no sleep), which `wait_for_turbo_idle` now calls. To find it: log `turbo:visit`, `turbo:before-render`, `turbo:render`, `turbo:load`, `scroll` and `popstate` in the frame with `scrollY`, `busy` and `history.restorationData` of the current identifier. - **Snapshots keep live form values, and cloned busy state goes stale.** Both only matter when a page is restored from a snapshot. The filter pages are `no-cache`, so Back/Forward refetch them, and the `url-sync` controller was removed. +- **A click then an at-once `fill_in` or click of a label the page being left also has races the visit (root-caused 2026-11-13, issue #417).** `spec/system/locations_spec.rb` filled "Name" (the add form has one too) before the rename page rendered: the text went into the old page, and Save renamed the location to its own name. Wait for something only the new page has (its h1) between the click and the act; no sleep. To provoke such a race, wrap `window.fetch` to hold one URL back and log `turbo:visit`, `turbo:render` and `turbo:load` with `location.pathname` (the issue has the spec). - **Tests.** Call `wait_for_turbo_idle` (`spec/support/turbo_idle.rb`; it also waits for queued scroll events, #404) before `go_back`/`go_forward`; for a page in the narrow frame, `wait_for_scroll_events(frame: "narrow")` before `history.back()`. **How to apply:** don't reintroduce frame-advance filters; a GET form doing a Drive visit keeps state in the URL with a working Back. If a frame advance is ever needed, test Back with the slow-repaint helper. To see which path ran, instrument `turbo:visit`, `turbo:before-fetch-request`, `turbo:frame-load` and `turbo:load`, and log `html[aria-busy]`/`turbo-frame[busy]` every few ms. Related: [[headless-firefox-narrow-frame]], [[pr5-open-followups]]. diff --git a/docs/lessons/2026-11-13-provoke-a-rare-race-to-measure-the-fix.md b/docs/lessons/2026-11-13-provoke-a-rare-race-to-measure-the-fix.md new file mode 100644 index 00000000..4a614bf0 --- /dev/null +++ b/docs/lessons/2026-11-13-provoke-a-rare-race-to-measure-the-fix.md @@ -0,0 +1,25 @@ +--- +date: 2026-11-13 +spec: none (#417) +tags: [testing, flaky-specs, system-specs, turbo] +--- + +# Lesson: a flake that fails once in thousands is measured by provoking its race, not by looping it + +## Context + +#417: `spec/system/locations_spec.rb:7` failed once in a 4950-example run. The example clicks "Rename Blue binder" and at once fills in "Name"; the page it leaves has a "Name" field too. + +## What happened + +- The example alone passed 60 of 60 before the fix and 200 of 200 after it. Those counts only bound the natural rate (under about 5% and 1.5%, at 95% confidence) and cannot tell a fixed example from an unfixed one. +- Holding back the one response the race depends on (a `window.fetch` wrapper that delays the rename page's request) made it measurable: with 40 ms, 8 of 30 runs failed before the fix and 0 of 30 after; with 400 ms, 10 of 10 and 0 of 10. An event log (`turbo:visit`, `turbo:render`, `turbo:load`, `location.pathname`) showed the typing at 75 ms on the old page and the new page rendering at 433 ms. + +## What to do next time + +For a race between a test and a page change, find the one response or event it depends on, delay it in a temporary spec, and compare before and after at a delay where the failure rate is high. Say in the PR what the clean loop of the real example does not show. Keep the temporary spec out of the suite and put its code in the issue. + +## Signals to watch for + +- A `click_on` followed at once by `fill_in` or `click_on` of a label the page being left also has. +- A "0 failures in N runs" offered as the proof of a flake's fix, with no provoked comparison.