test: log applier path and copier chunk completions at Debug for #746#759
Merged
Conversation
…k#746 The first round of diagnostics (block#750) confirmed that TestCutoverAtomicityWithConcurrentWrites is losing rows mid-keyspace (e.g. id=118 with id=157 still present), ruling out the cutover-window race and pointing at the copy-phase delta-map / watermark interaction. The next round needs per-key traces to discriminate between (a) HasChanged silently dropping the binlog event, (b) the key being parked in the delta map and skipped repeatedly, or (c) the REPLACE statement running with affected_rows=0. Adds Debug-level logs at the relevant decision points and bumps the test log level to Debug in the affected packages so they appear in CI: pkg/repl/subscription_map.go: - HasChanged: log adds and above-high-watermark drops with key. - deltaMap.Flush: log not-below-low-watermark skips, per-statement affected_rows on the parallel path, and the keys_flushed count on the under-lock path. pkg/copier/{unbuffered,buffered}.go: - Log each chunk completion with table, range, affected_rows, and duration so a missing PK can be matched back to the chunk that should have copied it. pkg/{migration,repl,copier}/*_test.go (TestMain): - slog.SetLogLoggerLevel(slog.LevelDebug) so these new logs (and the existing Debug logs that were already there) reach CI output. Production behavior unchanged — Debug stays filtered there. Verified locally: TestCutoverAtomicityWithConcurrentWrites passes (2.4s) and emits the expected debug lines for HasChanged adds, Flush stmt with affected_rows, and CopyChunk completion with chunk range. Investigative scaffolding only — once block#746 is root-caused the new log sites will still be useful but the test-level Debug bump can be reverted. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
morgo
force-pushed
the
diagnostic-logging-746
branch
from
f31e486 to
5826db4
Compare
morgo
changed the title
aparajon
approved these changes
May 1, 2026
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
pkg/{migration,repl,copier}test log level to Debug inTestMainso the new logs reach CI output. Production behavior unchanged — Debug stays filtered there.Why
Round one (#750) confirmed
TestCutoverAtomicityWithConcurrentWritesloses rows mid-keyspace (e.g. id=118 missing while id=157 is present), ruling out the cutover-window race and pointing at the copy-phase delta-map / watermark interaction. The next CI failure needs to answer:(a) Did
HasChanged(K)ever fire? Was it dropped byKeyAboveHighWatermark?(b) Was K ever in the delta map? Skipped repeatedly by
KeyBelowLowWatermark?(c) When the
REPLACE INTO ... SELECT ...for K ran, what was itsaffected_rows?(d) Which copy chunk's range covered K? What was that chunk's
affected_rows?This patch makes (a)-(d) printable in CI logs. Debug is the right level — it's what these decisions would warrant in any case, and there's no reason to filter them in tests.
What's logged (at Debug)
pkg/repl/subscription_map.goHasChanged— every add to the delta map, and every drop byKeyAboveHighWatermark.deltaMap.Flush— every key skipped byKeyBelowLowWatermark; per-statementaffected_rowson the parallel path;stmt_count/keys_flushedon the under-lock path.pkg/copier/{unbuffered,buffered}.goaffected_rows, duration.Test plan
go build ./...— clean.go vet ./pkg/repl/ ./pkg/copier/ ./pkg/migration/— clean.go test ./pkg/repl/ ./pkg/copier/— pass.go test -run TestCutoverAtomicityWithConcurrentWrites ./pkg/migration/— pass (2.4s) and emits the expected debug lines (HasChanged added to delta map,Flush stmt executed table=... affected_rows=... stmt=...,CopyChunk completed chunk=... affected_rows=...).🤖 Generated with Claude Code