Skip to content

flaky test: TestCutoverAtomicityWithConcurrentWrites #746

New issue
New issue
Closed
Bug
Closed
flaky test: TestCutoverAtomicityWithConcurrentWrites#746
Bug
#853 (+3)
Assignees
morgo

Description

@morgo
morgo
opened on May 1, 2026
2026-05-01T00:03:16.0248830Z test-1   |     cutover_test.go:306: 
2026-05-01T00:03:16.0248984Z test-1   |         	Error Trace:	/app/pkg/migration/cutover_test.go:306
2026-05-01T00:03:16.0249100Z test-1   |         	Error:      	Condition never satisfied
2026-05-01T00:03:16.0249254Z test-1   |         	Test:       	TestCutoverAtomicityWithConcurrentWrites
2026-05-01T00:03:16.0249462Z test-1   |         	Messages:   	Checksums should eventually match between old and new tables
2026-05-01T00:03:16.0249689Z test-1   |     cutover_test.go:312: Old table checksum: 2795909001, New table checksum: 3807567528
2026-05-01T00:03:16.0249855Z test-1   |     cutover_test.go:321: Old table count: 159, New table count: 157
2026-05-01T00:03:16.0250603Z test-1   | 2026/05/01 00:03:14 INFO migration status: state=copyRows copy-progress=2000/3 66666.67% binlog-deltas=0 total-time=0s copier-time=2562047h47m16.854775807s copier-remaining-time=DUE copier-is-throttled=false conns-in-use=0
2026-05-01T00:03:16.0250691Z test-1   |     cutover_test.go:322: 
2026-05-01T00:03:16.0250834Z test-1   |         	Error Trace:	/app/pkg/migration/cutover_test.go:322
2026-05-01T00:03:16.0250922Z test-1   |         	Error:      	Not equal: 
2026-05-01T00:03:16.0251010Z test-1   |         	            	expected: 159
2026-05-01T00:03:16.0251096Z test-1   |         	            	actual  : 157
2026-05-01T00:03:16.0251248Z test-1   |         	Test:       	TestCutoverAtomicityWithConcurrentWrites
2026-05-01T00:03:16.0251355Z test-1   |         	Messages:   	Row counts should match

Activity

  1. morgo
    self-assigned this
    on May 1, 2026
  2. morgo
    added the
    Bug
    issue type on May 1, 2026

  3. morgo commented on May 1, 2026

    @morgo
    morgo
    on May 1, 2026
    CollaboratorAuthor

    Local repro update: Could not reproduce this locally despite 500+ iterations and varied stress configurations. Summary of attempts:

    • ~500 isolated runs of TestCutoverAtomicityWithConcurrentWrites (with explicit DROP TABLE IF EXISTS between iterations to avoid stale-state cascades): all PASS, no row-count mismatch.
    • 30 iterations with -race: all PASS.
    • 8 parallel go test runners × 10 iterations each, sharing one MySQL instance (mimicking CI's -parallel=4 + -race): plenty of failures, but all from sibling-test "metadata lock held by another connection" cascades caused by the partial-cutover leaving tables half-renamed — none were the row-count failure from this issue.
    • 16-thread variant with longer warmup (500ms) and 4-thread migration: failed in setup before reaching cutover.
    • Added per-event artificial latency to readStream (SPIRIT_DEBUG_BINLOG_DELAY_US) to simulate slow CI binlog delivery: 500us = no repro, 2ms = test aborts in setup, 5ms = hung. None reproduced the row-count mismatch either.

    Local environment: macOS, NVMe SSD, native MySQL 8.0.43. CI: Docker on Linux + -race + -parallel=4 + MySQL 8.0.45.

    Code-walk summary (see PR #750 for the diagnostic logging that should help next time this fires):

    The cutover protocol appears correct on paper. LOCK TABLES waits for in-flight transactions to fully commit (binlog write happens before row locks release). FlushUnderTableLock is called twice with BlockWait between, which forces the binlog reader to drain via FLUSH BINARY LOGS + SHOW MASTER STATUS. AllChangesFlushed() then checks each subscription's pending length. So I can't construct a deterministic bug from the code alone.

    That said, two things stand out as soft guarantees:

    1. AllChangesFlushed() only warns on bufferedPos > flushedPos, doesn't return false. Consistency hinges entirely on subscription length being authoritative.
    2. KeyAboveHighWatermark() returns TRUE (silently drops the change) when chunkPtr.IsNil() — the safe-by-accident default. The window between SetWatermarkOptimization(true) and the first chunker.Next() call drops binlog events, with the implicit assumption that "the chunker will SELECT them later." Probably fine for AUTO_INCREMENT but I haven't proven it can't bite under the right interleaving.

    Possible link to #743: Both flakes share the CI environment (binlog syncer can stall under load). But #743's fix in f4ce965 only changes when BlockWait issues FLUSH BINARY LOGS — it doesn't change BlockWait's correctness criterion (bufferedPos >= targetPos). I don't think f4ce965 will fix #746.

    The PR adds enough logging on failure to tell whether the missing rows are the latest ones (cutover-window race) or scattered through the id range (copy-phase race), and whether they're consecutive (single transaction) or independent. That should let us bisect on the next CI hit.

  4. morgo
    added a commit that references this issue on May 1, 2026

    test: log missing/diverged rows on cutover atomicity assertion failure

    cd81071

  5. morgo commented on May 1, 2026

    @morgo
    morgo
    on May 1, 2026
    CollaboratorAuthor
    2026-05-01T12:48:50.3234728Z test-1           | --- FAIL: TestCutoverAtomicityWithConcurrentWrites (7.60s)
2026-05-01T12:48:50.3234927Z test-1           |     cutover_test.go:280: Completed 156 writes with 53 errors during migration
2026-05-01T12:48:50.3235050Z test-1           |     cutover_test.go:306: 
2026-05-01T12:48:50.3235204Z test-1           |         	Error Trace:	/app/pkg/migration/cutover_test.go:306
2026-05-01T12:48:50.3235324Z test-1           |         	Error:      	Condition never satisfied
2026-05-01T12:48:50.3235480Z test-1           |         	Test:       	TestCutoverAtomicityWithConcurrentWrites
2026-05-01T12:48:50.3235695Z test-1           |         	Messages:   	Checksums should eventually match between old and new tables
2026-05-01T12:48:50.3235942Z test-1           |     cutover_test.go:312: Old table checksum: 3690051681, New table checksum: 334112154
2026-05-01T12:48:50.3236107Z test-1           |     cutover_test.go:321: Old table count: 157, New table count: 156
2026-05-01T12:48:50.3236227Z test-1           |     cutover_test.go:329: max(id) in _old=157
2026-05-01T12:48:50.3236647Z test-1           |     cutover_test.go:340: MISSING in _new: id=118 x_token=x-1777639633657271192 version=2 created_at=2026-05-01 12:47:13 updated_at=2026-05-01 12:47:13
2026-05-01T12:48:50.3236739Z test-1           |     cutover_test.go:360: 
2026-05-01T12:48:50.3236880Z test-1           |         	Error Trace:	/app/pkg/migration/cutover_test.go:360
2026-05-01T12:48:50.3236991Z test-1           |         	Error:      	Not equal: 
2026-05-01T12:48:50.3237112Z test-1           |         	            	expected: 157
2026-05-01T12:48:50.3237208Z test-1           |         	            	actual  : 156
2026-05-01T12:48:50.3237370Z test-1           |         	Test:       	TestCutoverAtomicityWithConcurrentWrites
2026-05-01T12:48:50.3237483Z test-1           |         	Messages:   	Row counts should match
  6. morgo
    added 10 commits that reference this issue on May 1, 2026

    test: log applier path and copier chunk completions at Debug for bloc…

    5826db4

    Merge pull request #759 from morgo/diagnostic-logging-746

    8b978c7

    test: disable FixDifferences when useTestCutover for #746 repro

    51894f0

    Merge pull request #764 from morgo/repro-746-no-fixdifferences

    501e30c

    fix: apply same KeyAboveHighWatermark fix to composite chunker; rever…

    c2e825a

    fix(block#746): KeyAboveHighWatermark must not silently drop in IsNil…

    fb2659d

    fix: apply same KeyAboveHighWatermark fix to composite chunker; rever…

    a8d916f

    fix(block#746): KeyAboveHighWatermark must not silently drop in IsNil…

    045117c

    fix: apply same KeyAboveHighWatermark fix to composite chunker; rever…

    1d6c609

    test: run cutover-atomicity probe across optimistic+composite × unbuf…

    5932c32

  7. 16 remaining items

  8. morgo
    added a commit that references this issue on May 5, 2026

    docs(repl): add history note explaining the unified subscription type

    5357df9
  9. morgo
    closed this as completedin #823on May 5, 2026
  10. morgo
    added a commit that references this issue on May 6, 2026

    test(migration): re-enable FixDifferences in TestCutoverAtomicityWith…

    4daae9f

  11. morgo commented on May 14, 2026

    @morgo
    morgo
    on May 14, 2026
    CollaboratorAuthor

    MySQL Bug: https://bugs.mysql.com/bug.php?id=120471

  12. morgo
    added 2 commits that reference this issue on May 16, 2026

    fix(block#746): make semi-sync lane actually inject the 100ms latency

    5683bb1

    docs(block#746): note semi-sync is supported and tested

    b64d6dc

  13. morgo commented on May 16, 2026

    @morgo
    morgo
    on May 16, 2026
    CollaboratorAuthor

    JFG, a replication expert, reached out with advice on the bug report.

    When you consider semi-sync, rows are sent to the replica ahead of when they are committed (and visible) on the source. So this race was likely present and a serious issue for semi-sync. We did not make any claims w.r.t. semi sync support, but I think that's a mistake and we should be testing it, so I am going to go ahead and add it to the test suite.

    JFG also said that even though semi-sync was not in use here, the same code-path is exercised in non-semi sync so there is a brief race by design. In other-words, expecting to see 'committed' rows in the binary log to be visible in InnoDB was an incorrect assumption (and likely a common one).

    I will leave the MySQL bug open for now to get a possible second opinion on this, but what JFG is saying makes sense. The only action item here is to ensure we have semi-sync testing in scope and document it as supported.

    (Also many thanks to JFG!)

  14. morgo
    added 5 commits that reference this issue on May 16, 2026

    docs(block#746): address Copilot review — describe the connected dela…

    55d1d01

    fix(block#746): keep netem sidecar alive so test container actually runs

    efadead

    test(#746): semi-sync cutover regression test (build-tagged)

    811b90b

    Merge pull request #852 from morgo/semi-sync-tests

    cae0bbd

    fix(#847): switch applier to REPLACE INTO; remove rewind machinery

    5256bb3
  15. morgo
    unpinned this issue on Jun 8, 2026
  16. morgo
    added a commit that references this issue on Aug 13, 2026

    docs+test: KeyAboveHighWatermark discard vs binlog delivery-before-vi…

    fdaf733
  17. morgo
    added a commit that references this issue on Aug 27, 2026

    change: stop deferring not-yet-dispatched keys at flush time (#1167)

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

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

Bug

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions