test(move): make the reverse-window waits say why they timed out

[morgo]

TestMoveReverseWindowNMResumesAfterKill fails intermittently in CI at reversewindow_test.go:581 with timed out waiting for the reverse window to open and nothing else (#1239, most recently on #1225's 8.0.45-with-replicas job).

What the last failure actually shows

The runner logged the window open one second into a 30-second wait, on the very database the test polls:

12:42:37 INFO reverse window open; watching for a table named _spirit_move_revert
         to be created on mysql:3306.t_testmovereversewindownmresumesafterkill_4971_20
--- FAIL: TestMoveReverseWindowNMResumesAfterKill (30.21s)
    reversewindow_test.go:581: timed out waiting for the reverse window to open

That log line comes after persistReverseWindow, and persistReverseWindow returns its write error into PostSwitch — a failed write aborts the cutover and the window never opens. It also sets r.cutoverAt, without which the window would have elapsed on its first tick and logged so. So the checkpoint row was present, with the right phase, in the right database, for the entire budget — and the helper never saw it.

That puts the fault on the read side, and the helper is built so that no read-side failure can be distinguished from any other: it discards every query error, puts no bound on the individual query, and never looks at what the run is doing. waitForReverseWindow is also the first thing in that test to use the control connection at all, which makes a control-connection failure the cheapest explanation for every poll failing identically — and precisely the one the message cannot tell apart from "not there yet".

Change

The same shape pkg/datasync got in #1261:

• Every wait selects on the run result. A move that dies before the window fails the test with its own error rather than an opaque wait.
• Every query is bounded. An unbounded read can spend the whole budget inside a single call — which is exactly a 30.2s failure with nothing to say.
• Only sql.ErrNoRows and ER_NO_SUCH_TABLE mean "not yet" for a checkpoint read. Everything else fails immediately, naming the error.
• The timeout message carries evidence: last phase seen, last read error, how many reads were blocked, and the runner's state.

awaitReverseWindow now waits on the runner's state as well as the checkpoint phase, state first — the state is in-process and cannot be blocked by the server, so a checkpoint read that then fails is reported against a window we already know is open. Two tests had that state wait open-coded after the phase wait; they lose the duplicate.

The budget drops 30s → 20s, under the 30s reverse window these tests configure: once the window elapses the terminal action drops the checkpoint, so a phase wait outliving the window can never be satisfied.

The handle also owns teardown, fixing a hazard in the old shape — defer utils.CloseAndLog(runner) runs while a fatal wait leaves Run in flight, and Runner.Close is safe only once Run has returned. Cleanup now cancels, drains, then closes, and reports a stuck run rather than closing underneath it.

Verification

Measured against injected failures:

injected	before	after
unreachable target	20s, no error text	0.04s, ping failed: dial tcp 127.0.0.1:1: connect: connection refused
bad schema on the read	swallowed for the full budget	0.12s, Error 1049 (42000): Unknown database ...
phase never arrives	timed out waiting for the reverse window to open	last phase="reverse_window", last read error=<nil>, blocked reads=0, runner state=reverseWindow

./pkg/move/... green, -race green over three runs of the reverse-window tests, golangci-lint clean.

Scope

This does not claim a root cause for #1239 — the evidence narrows it to the read side but does not identify which read-side failure. It makes the next occurrence name it, and removes the helper's ability to burn its entire budget in one blocked query. Leaving #1239 open.

Refs #1239

🤖 Generated with Claude Code

[Copilot]

Copilot review overview

🟡 Changes recommended

Address the two moderate timeout-budget issues in pkg/move/reversewindow_test.go.

Get a fresh assessment by requesting another Copilot review.

Review effort: Lite
Findings: 1

Open (1)

• Use a shared deadline for composite reverse-window waits · New

What changed in this PR

Improves reverse-window test diagnostics, bounded polling, runner error reporting, and asynchronous cleanup.

Changes:

• Adds diagnostic, runner-aware polling.
• Bounds checkpoint queries and reports read errors.
• Centralizes cancellation, draining, and teardown.

File	Summary
pkg/​move/​reversewindow_test.go	Adds lifecycle-safe wait helpers and diagnostics. Requires a shared composite deadline and preservation of the 30-second acquisition budget.

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[aparajon]

🤖 Adversarial correctness review — 0 blocking, 4 non-blocking

Reviewed 3796b2ba3df00c097d147f5cd876711ab4d9d39f (one file, pkg/move/reversewindow_test.go, +279/−106) against merge-base 164d2ee0. block/spirit has no docs/invariants.md, so there are no invariant IDs to cite; the contract this touches is the same one #1261 established next door — Runner.Close is safe only once Run has returned — and close (reversewindow_test.go:296-318) honours it, leaving a stuck runner open rather than pulling its pools out from under a live Run.

Everything below ran locally against the repo's MySQL on -count=1. The whole set passes at head: go test -run TestMoveReverseWindow ./pkg/move/ → ok 6.374s.

The headline claim holds, measured. Injecting a failure immediately after the start-up log in Runner.Run (runner.go:1127) and running TestMoveReverseWindowRevert with only the test file differing:

164d2ee0 (base)	30.06s	reversewindow_test.go:162: timed out waiting for the reverse window to open
3796b2ba (head)	0.04s	move returned before the wait was satisfied: err=MUTANT: injected setup failure; move did not reach state reverseWindow; last state=initial

Thirty seconds and a bare sentence becomes forty milliseconds, the error, and the state the runner was actually in. The awaitReverseWindow shape is the better half of it: checking the in-process state before the checkpoint read means a control connection that is itself broken is reported against a window already known to be open, with the read's own error attached — which is the failure mode that made #1239 unreadable.

Non-blocking

1. poll reports waitTimeout as the budget even when the wait never had it. reversewindow_test.go:167-168 formats the message with the constant, but the deadline is a parameter — and the whole point of making it one is awaitReverseWindow (:186-190), where the two halves share one deadline and the second half gets whatever the first left. A phase wait that inherits two seconds of a twenty-second budget and exhausts them prints a line saying it gave up after two seconds against a twenty-second budget, which reads as though something other than the budget cut it short. In a harness whose stated job is to stop timeouts from misdescribing themselves, this is the one message that still does. Measured with the real poll and 200ms left on the deadline:

--- FAIL: TestPollReportsTheBudgetItActuallyHad (0.20s)
    the thing never happened (gave up after 202ms, 20s budget)

Probe run at 3796b2ba

// A wait that inherits what is left of a shared deadline, as the second half of
// awaitReverseWindow does after the first half has spent most of the budget.
func TestPollReportsTheBudgetItActuallyHad(t *testing.T) {
	h := &runHandle{t: t, done: make(chan error, 1)}
	deadline := time.Now().Add(200 * time.Millisecond)
	h.poll(deadline, func() bool { return false }, func() string { return "the thing never happened" })
}

poll already holds deadline; printing the budget from deadline.Sub(start) rather than from the constant makes the line true for both the standalone and the composed case, and costs nothing.

2. poll does not re-check the condition once the timer fires. At :159-170 the loop evaluates cond(), then blocks in a select where timer.C and tick.C can both be ready and Go picks between them at random. So a condition that became true during the evaluation that just returned false is never seen again. That evaluation is not instantaneous: awaitCheckpointPhase's condition issues a query bounded by waitQueryTimeout, five seconds, and the finding it is looking for can land at any point inside it. The result is a spurious failure with a message asserting the state was never reached, on a run where it was — the exact class of misleading CI failure this PR is removing elsewhere. One if cond() { return } ahead of the Fatalf in the timer branch closes it. The h.done branch has the same shape and is much less likely to bite, since a Run that returns cleanly has usually moved past the state being awaited.

3. awaitTable starting its own budget puts the N:M kill test's waits over the window it is killing inside. The comment at :245-251 is careful and its premise is right — a table the cutover renamed does not stop existing because the window elapsed — but it draws the conclusion for the table and not for the caller. TestMoveReverseWindowNMResumesAfterKill runs awaitReverseWindow (20s) and then two awaitTable calls with 20s each (:768-772), so the waits preceding the kill can sum to sixty seconds against a thirty-second window. If the window elapses in there, the move completes forward on its own and h1.kill() hands back the nil that Run already returned; require.ErrorIs at :776 then fails with "run 1 must die from the kill, not an earlier failure" — naming an early death for a run that in fact finished normally while the harness was still waiting. The comment anticipates the caller being "told so by its own assertion on Run's error"; the gap is that the assertion tells it the wrong thing. This is latent on a CI runner slow enough for three waits to take thirty seconds, which these tests are nowhere near locally (the kill test is 0.44s), so it is worth no more than making awaitTable take a deadline like its siblings and having that test share one.

4. The completion waits kept their bare literals. The new block at :58-71 gives each timing constant a name and a documented reason, and then the five longest waits in the file stay as 30*time.Second (:380, :421, :499) and 60*time.Second (:732, :796) at the awaitDone call sites. Those are the numbers most likely to need changing together — they are all "how long may the reverse cutover take", and two of them differ only because the N:M fixture is bigger. They belong in the block with the others.

Notes, not findings

• close being a t.Cleanup rather than a defer is what makes the t.Fatalf waits safe, and it matters more than it looks: every converted test dropped its defer utils.CloseAndLog(runner), so a wait that fatals now tears the runner down through the cleanup instead of leaking change feeds into the rest of the package. runRevertingMove calling h.close() explicitly (:424) is right for the same reason — the two attempts share a source and target — and the closed guard keeps the cleanup idempotent behind it.
• The three tests still holding defer utils.CloseAndLog(runner) are correct as they are. TestMoveReverseWindowCompleteForward (:320), TestMoveReverseWindowRefusesStaleRevertMarker (:553) and run2 in TestMoveReverseWindowRevertingResumeRetainsOwnershipEvidence (:539) all call Run synchronously, so there is no goroutine to join and nothing for the handle to add. I checked each rather than reading the leftover defers as a conversion that stopped halfway. Related: run2.SetCutover at :540 uses t.Fatal where its sibling at :487 uses t.Error, and that difference is also right — the first callback runs on the test goroutine, the second does not.
• errors.AsType[*mysql.MySQLError] in checkpointNotYet (:100) needs the go 1.26.6 in go.mod; go vet ./pkg/move/ is clean at this head.
• awaitCheckpointPhase's default branch fataling on an unrecognised driver error (:232-233) is the right call over counting it as "not yet" — a refused control connection or a dropped schema will not fix itself, and the old loop's err == nil && phase == want swallowed all of them silently.
• startRun deliberately not using t.Context() (:134-136) is necessary, not incidental: with the run tied to the test context, a fatal wait would cancel the move before close could drain it and the diagnosis would race the teardown.
• sentinel_test.go:68 and runner_test.go:817 still drive Run on a bare goroutine. Out of scope for a PR named after the reverse-window waits, and noted only because the helper is now there for whoever gets to them.

---

This review was generated by Claude Code (claude-opus-5).

[aparajon]

🤖 Approving: 0 blocking, 4 non-blocking — see the correctness review. The headline claim is verified by measurement: an injected setup failure takes 30.06s and names nothing at 164d2ee0, and 0.04s with the error and the runner's last state at this head. The four non-blocking items are poll printing the constant instead of the budget it actually had (measured, probe included), no final condition check when the timer fires, awaitTable's own budget letting the N:M kill test's waits outlast the window it kills inside, and five completion waits left as bare literals outside the new timing block.

This stamp was left by Claude Code (claude-opus-5).

[Kiran01bm]

🤖 Review findings - created by Kiran's code review agent - for spirit/pull/1265, 3796b2b.
Verdict: 2 findings — 0 blocking, 2 non-blocking (both new flake modes in a de-flaking PR).

Non-blocking

tableExists now bounds its read but still hard-fails on the resulting context.DeadlineExceeded, so awaitTable turns a slow information_schema read into a test failure instead of retrying. reversewindow_test.go:86 ends with errors.Is(err, sql.ErrNoRows) then require.NoError, with no DeadlineExceeded branch, while the PR newly wraps the same query in context.WithTimeout(t.Context(), waitQueryTimeout) (previously unbounded). One pathological 5s point lookup under -race -parallel=4 fails TestMoveReverseWindowResumesAfterKill with a bare "context deadline exceeded" even though t1_old exists and the next 50ms poll would see it. awaitCheckpointPhase explicitly retries (blocked++) on the identical condition, so the two polls in one harness disagree.

awaitReverseWindow cuts the pre-window budget from 30s to a shared 20s while requiring strictly more work to fit inside it. The deleted waitForReverseWindow allowed 30s just for the checkpoint row, which the cutover post-switch hook writes at runner.go:1398 before the reverse feed exists; reversewindow_test.go:188 now spends one 20s waitTimeout on awaitState(status.ReverseWindow) — set only at reversewindow.go:146, after buildFeed and feed.Start — plus the phase poll. The "stays well under the 30s reverse window" rationale does not apply to a leg that runs entirely before the window opens; the package's own precedent budgets 3 minutes to reach an earlier state "on slow CI servers".

The one thing that could have broken, verified

The wait ordering inside awaitReverseWindow (state, then phase) could have deadlocked if the phase were written after status.ReverseWindow. It is not: the move writes phase=reverse_window under the source lock during cutover, strictly before the status transition, so the phase half is already satisfied when awaitState returns.

Verified correct

• Re-ordering in TestMoveReverseWindowNMResumesAfterKill is behaviour-preserving: state>=ReverseWindow implies cutover completed, so both users_old renames already landed.
• New require.ErrorIs(h1.kill(), context.Canceled): the 1:1 path shares the window loop with the NM test that already asserted this, and errors.Join teardown still satisfies errors.Is.
• close() is idempotent: closed is set first, the drain is skipped when returned is true, and utils.CloseAndLog(runner) only runs after Run returned.
• Teardown order survives the defer→t.Cleanup(h.close) move: fixture setup registers ctl-close and DROP DATABASE first, so LIFO runs h.close before them.
• runRevertingMove's explicit h.close() before the retry is necessary — otherwise attempt 1's change feeds stay open during attempt 2.
• awaitState polling Progress() from t=0 is not a new race or nil deref: r.copier/r.checker are assigned before their status.Do transitions, copyChunker is mutex-guarded, and the status dumper already polls concurrently; CI green under -race.
• checkpointNotYet correctly admits only sql.ErrNoRows and MySQL 1146, and the awaitCheckpointPhase switch checks DeadlineExceeded before the default Fatalf, so no shadowing.

This review was generated by Claude Code (claude-opus-5).

[Kiran01bm]

🤖 Approved on Kiran's (@kmuddukrishna) behalf by the scheduled review agent — no blocking findings at 3796b2b. See the review comment above; non-blocking findings and suggestions, if any, are not merge gates.

[morgo]

🤖 Reply from Morgan's AI agent.

Addressed all four non-blocking findings from the correctness review and both from Kiran's, in f14b3d4:

• poll's timeout message now reports the deadline it was actually given (deadline.Sub(start)) instead of the waitTimeout constant, and re-checks cond() once more when the timer fires before failing — closing the window where a condition flips true during the bounded query the timer raced against.
• awaitTable now takes the deadline awaitReverseWindow returns instead of starting its own, so the N:M kill test's two retire-waits share one budget with the window wait rather than being able to sum past the 30s window they run inside.
• awaitTable treats a query timeout as "not yet" and retries (same shape as awaitCheckpointPhase), rather than hard-failing on a slow information_schema read.
• awaitReverseWindow splits its budget: the state wait gets its own reverseWindowOpenTimeout (3m, matching waitForMoveStatus's slow-CI allowance for the same setup/copy/checksum/cutover work), since none of that counts against the window's countdown — only the phase check (and whatever the caller shares its deadline with) stays bounded by waitTimeout.
• The five remaining bare 30*time.Second/60*time.Second awaitDone call sites are now reverseCutoverTimeout/nmReverseCutoverTimeout.

Verified against the real MySQL: ./pkg/move/... green, -race -count=3 green, golangci-lint clean. Branch is also now up to date with main (was BEHIND).