Flaky test: TestMoveForceRecoversCheckpointMissingSource hangs on an unbounded lock wait, timing out pkg/move

[morgo]

pkg/move hit the 10-minute package timeout on the "MySQL 9.7 /w docker-compose" job, with a single test wedged for 8m42s inside one UPDATE.

• Failing run: https://github.com/block/spirit/actions/runs/34136296013/job/101787953865 (PR feat(move): add host-aware autoscaling for sharded moves #1216, head b4a150fd)
• Package: github.com/block/spirit/pkg/move — FAIL ... 600.031s
• Test: TestMoveForceRecoversCheckpointMissingSource

Symptom

panic: test timed out after 10m0s
	running tests:
		TestMoveForceRecoversCheckpointMissingSource (8m42s)

The test goroutine is blocked in a socket read, not spinning:

goroutine 16244 [IO wait, 8 minutes]:
internal/poll.runtime_pollWait(...)
github.com/block/mysql.(*mysqlConn).readWithTimeout(...)
github.com/block/mysql.(*okHandler).readResultSetHeaderPacket(...)
github.com/block/mysql.(*mysqlConn).exec(0xc000386000, {0xc000166280, 0x4d})
...
database/sql.(*DB).ExecContext(...)
github.com/block/spirit/pkg/testutils.RunSQL(0xc00022a6c8, {0xc000166280, 0x4d})
	/app/pkg/testutils/testing.go:191 +0x12a
github.com/block/spirit/pkg/move.TestMoveForceRecoversCheckpointMissingSource.func1({0xc00016c8d0, 0x13})
	/app/pkg/move/runner_test.go:1808 +0x97
github.com/block/spirit/pkg/move.testForceRecoversUnresumableCheckpoint(...)
	/app/pkg/move/runner_test.go:1755 +0x5cd

The statement is 0x4d = 77 bytes, which is exactly the corrupt closure at runner_test.go:1808:

UPDATE dest_force_nosrckey._spirit_move_checkpoint SET binlog_position = '{}'

So the test got past checkpointAndStop, and then its very next statement — a plain single-row UPDATE on the checkpoint table it just wrote — never got a response from the server.

What the log shows immediately before the hang

15:07:53 INFO created table on target table=t1 target=0 database=dest_force_nosrckey deferred_indexes=false
15:07:53 INFO begin to sync binlog from GTID set ...
15:07:53 INFO scaled read workers up from=0 to=1
15:07:53 INFO approaching the end of the table, synchronously updating statistics
15:07:53 INFO syncer is closing...
15:07:53 INFO kill last connection id=6784
15:07:53 INFO syncer is closed
[mysql] 2026/09/07 15:07:53 packets.go:68 [warn] unexpected sequence nr: expected 1, got 2
panic: test timed out after 10m0s

That is checkpointAndStop's runner completing its copy, dumping the checkpoint, and being closed by closeTestRunner — and then a driver-level protocol desync on a database/sql connection, immediately before the UPDATE wedges.

It is a lock wait, and specifically not a row-lock wait

Two things narrow this down:

• The server was idle. No other test was running: the three parallel tests in the dump are all parked in testing.(*T).Parallel for 9 minutes waiting for the serial test to finish. So this is not the container being slow.
• It cannot be an InnoDB row lock. compose/ sets no lock timeouts, so innodb_lock_wait_timeout is the 50s default — an UPDATE queued behind an uncommitted REPLACE on the same checkpoint row would have failed with 1205 after 50 seconds, not hung for 8m42s. lock_wait_timeout (metadata locks) defaults to 31536000s, which does match a wait of arbitrary length.

That points at a metadata lock on dest_force_nosrckey._spirit_move_checkpoint held by a session that outlived Runner.Close(). The unexpected sequence nr warning on the line before is the corroborating signal: it means a pooled connection was left out of protocol sync, i.e. abandoned mid-statement rather than cleanly returned. database/sql's DB.Close() does not close connections that are still checked out, so a target-pool connection abandoned that way keeps its server-side session — and any locks it holds — alive well past the runner's teardown.

I could not reproduce locally (-count 3 on the three TestMoveForceRecovers* tests, real MySQL, passes in ~1.5s), which is consistent with a teardown race rather than a deterministic bug.

Why an 8-minute wait instead of a fast failure

testutils.RunSQL executes with context.Background():

func RunSQL(t *testing.T, stmt string) {
	t.Helper()
	db, err := sql.Open(driverName, DSN())
	require.NoError(t, err)
	defer func() { _ = db.Close() }()
	// Might be run in cleanup, use Background context
	_, err = db.ExecContext(context.Background(), stmt)
	require.NoError(t, err)
}

There is no deadline, so a metadata-lock wait is unbounded and consumes the entire package's 10-minute budget. The failure then surfaces as "pkg/move timed out" with no indication of which lock or which session, which is what makes this expensive to diagnose from CI alone.

Suggested follow-ups

1. Bound the wait. Give RunSQL (or a RunSQLContext variant) a deadline — anything well under the package timeout. A blocked statement should fail its own test with a clear error rather than killing the package.
2. Say who holds the lock. On that timeout, dump performance_schema.metadata_locks joined to performance_schema.threads, plus information_schema.processlist. The queries already exist in pkg/dbconn/kill.go (TableLockQuery, LongRunningEventQuery) and would name the holder directly.
3. Investigate the teardown. Determine whether move.Runner.Close() can return while a target-pool connection is still checked out — and whether the unexpected sequence nr desync is the mechanism that strands it. If so the leak is in production code, not just test scaffolding.

Not caused by PR #1216

testForceRecoversUnresumableCheckpoint and its three callers were added in #1038 and are unchanged on main; PR #1216 touches neither pkg/move/runner_test.go nor the checkpoint path (its pkg/move changes are autoscale.go, move.go, pool.go, reversewindow.go and runner.go, with autoscaling off by default). This is a pre-existing flake that happened to land on that PR's run.