From 8e97b11929be6e12990e5d93127f63fb9ddcc369 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Sun, 4 Oct 2026 12:02:37 +0000 Subject: [PATCH] docs(buglog): bug-1920 fixed Co-Authored-By: Claude Opus 5.5 (1M context) --- .wolf/buglog.json | 12 +++++++----- .wolf/bugs/bug-1920.md | 23 ++++++++++++++++------- 2 files changed, 23 insertions(+), 12 deletions(-) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 701acf37..ca58a28a 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -17317,9 +17317,9 @@ }, { "id": "bug-1920", - "status": "investigating", + "status": "fixed", "status_updated": "2026-10-04", - "status_note": "Next: why ha_stream_wal_to_standby sends no walCatchupEntry for [341..342] after the NACK, and why the NACK backoff lands at 340 rather than the standby's match 323", + "status_note": "", "component": "controller", "severity": "hang", "timestamp": "2026-10-04T07:25:24Z", @@ -17327,8 +17327,8 @@ "occurrences": 1, "error_message": "new primary's WAL catch-up stalls after log-mismatch NACK; standby never advances, commits stuck\n\n**Observed:**\n```\n# new primary ctrl-2 (term 21), its only reachable standby ctrl-1 (ctrl-3 killed):\n07:06:45,520 ctrl-2 HA repl: standby[0] lsn=323 < stream_ceiling_lsn=342 (committed_lsn=341) → stream WAL batches\n07:06:45,522 ctrl-2 ha_stream_wal_to_standby: streamed WAL [323+1..342] to standby\n07:06:45,520 ctrl-1 ha_consume_append_entries: leader_idx=-1 term=21 prevIdx=341 n=1 -> success=0 match=0 (ae_reject_logmismatch)\n07:06:45,523 ctrl-2 repl_ack_decode_and_dispatch: WAL NACK from standby lsn=342 success=0 — marking catch-up\n07:06:48,603 ctrl-2 HA repl: standby[0] lsn=340 < stream_ceiling_lsn=342 (committed_lsn=341) → stream WAL batches\n07:06:48,603 ctrl-2 ha_stream_wal_to_standby: streamed WAL [340+1..342] to standby\n07:06:48,602 ctrl-1 ha_consume_append_entries: leader_idx=-1 term=21 prevIdx=323 n=0 -> success=1 match=323 (nop heartbeat)\n... same pair every 3 s for >60 s; ctrl-1 never logs another walCatchupEntry ...\n07:07:47,044 ctrl-2 commit: WAIT deadline expired without commit (lsn=343 committed_lsn=341 writable_lsn=342 timeout_ms=500)\nworker: xcecli failover: cluster not ready after 21 attempts (last status=-10013)\n[xce-test-ha] FAIL: round 19: worker-resync job ...: worker never logged a fresh rejoin after the failover (pre=18 post=18)\n```\nAfter the term-21 election the standby's Raft log matched only to 323. The first catch-up stream reached ctrl-1 only as a single entry (prevIdx=341, n=1), which was rejected. The bug-1479 NACK backoff then set the standby's catch-up join position to 340 (one below the rejected index) instead of 323. From then on the primary \"streams [341..342]\" every heartbeat, yet ctrl-1 receives only nop heartbeats (no walCatchupEntry), so no further NACK arrives to walk the position back. ctrl-1 stays at 323, the 2-of-3 cluster cannot commit (committed_lsn stuck at 341), and every client request gets -10013 not ready.\n\n**Expected:** the primary walks its catch-up position back to the standby's real match index (323) and streams [324..], so the standby catches up and commits resume, as bug-1479 intended.\n**Impact:** after a failover, the new primary is unavailable (no commits, clients get not-ready) for as long as the only other live member stays stalled. Observed for >60 s, unresolved until the soak tore the cluster down.\n**Found by:** soak (`/xce-test-ha` sequential 20 rounds, validating bug-1919, 2026-10-04)", "file": "src/controller/ha.c, src/controller/config_repl.c, src/controller/repl.c", - "root_cause": "TODO: required for fixed/partial", - "fix": "TODO: required for fixed/partial\n\nVerification:\n- Test: TODO: name + file; RED before the fix, GREEN after\n- Suites: TODO: suite results and build profile\n- Live: TODO: soak/deploy run, or n/a and why", + "root_cause": "Three layers; the first is the defect, the other two let it turn into a stall:\n1. **Pre-recovery WAL writes corrupt the segment layout.** A restarted standby accepts the primary's connection during its startup delay, before `cluster_init_phase2`/`persist_recover` runs (bug-849's \"phase2 before cluster_run accepts replication\" does not hold: ctrl-2 got the primary hello at 07:05:47.806, phase2 ran at 07:05:48.18). In that window the primary streams catch-up from the advertised `applied_lsn=0`, and `persist_wal_write_replicated` wrote into the un-recovered `persist_t` (`current_lsn=1`, no open segment): `open_new_segment` O_TRUNC'd the existing `seg-0000000000000001.wal` and rewrote LSNs 1..234 into it. `persist_recover` then set `current_lsn=306` but left that fd open as the append segment, so LSNs 306..348 were filed under `seg-...0001`. Found on disk: ctrl-2's seg-1 = 1..234 then 306..348; no `seg-...0132`. The bug-1416 `recovery_complete` gate already closed this window for apply, but not for WAL writes.\n2. **The catch-up streamer silently sends nothing.** `ha_stream_wal_to_standby` orders segments by filename start LSN and skips any segment whose successor starts at or below the standby's position, so it skipped seg-1 and found no entry above 305. It still logged \"streamed WAL [..] to standby\" with zero entries sent.\n3. **The catch-up start position runs above the standby's log.** After a log-mismatch NACK (prevIdx=341), `ha_raft_on_repl_nack` set the join position to next_index-1 = 340, and `ha_dispatch_repl_action_for_standby` let it override the standby's own report (323). From 340, even a correct stream needs one rejected round per heartbeat to walk back 17 entries.\n\nScan of the four 2026-10-04 soaks: 3 nodes in 2 runs had a misfiled seg-1. It stalls only when that node later becomes primary and a standby needs catch-up from the misfiled range.", + "fix": "- `persist_wal_write_replicated` returns `-EBUSY` while `!persist_recovery_complete(p)` (the bug-1416 gate that myapp closes before any network traffic and that `persist_recover` reopens). This is the backstop for every replicated-write path.\n- `ha_apply_wal_catchup_entry` and `ha_handle_snapshot_chunk` drop replication traffic silently before recovery: no persist, no ACK, no NACK (a NACK would walk the primary's next_index back past entries this node really holds). One INFO line per process.\n- `ha_dispatch_repl_action_for_standby` streams from min(join position, standby report): a lower join position (a bug-1479 conflicted suffix) still wins.\n- `ha_stream_wal_to_standby` WARNs \"found NO entries\" when a non-empty range yields nothing, and logs the entry count on success.\n\nVerification:\n- Test: `test_replicated_write_refused_before_recovery` (src/controller/testsuite/test_commit_durability.c: a pre-recovery replicated write leaves seg-1 intact and the first post-recovery append opens seg-), `test_intake_dropped_before_recovery` (test_term_safety_adapter.c: neither ACK nor NACK, nothing persisted), `test_dispatch_streams_from_min_of_join_and_report` (test_convergence_verification.c: streams from 323 rather than 340; a lower join position still wins). All three RED before the fix (write returned 0 / ACK sent / streamed from 340), GREEN after.\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04).\n- Live: 4x `/xce-test-ha` sequential 20 rounds, 2026-10-04: 4/4 PASS. The pre-recovery drop fired 14 times (3-5 per run), no \"found NO entries\" warning, and a scan of every node's WAL found every segment's first LSN equal to its filename with no LSN jumps. Before the fix, the same scan found misfiled seg-1 on 3 nodes in 2 of 4 runs. Longer runs, 2026-10-04: sequential 50 rounds PASS, chaotic 50 rounds PASS (zero committed divergence), sequential 30 rounds under 40 CPU spinners on 32 cores PASS. The drop fired 7/10/5 times, there was no \"found NO entries\" warning, the WAL layout was clean on every node, and there were no ASAN reports.", "tags": [ "ha", "repl", @@ -17338,7 +17338,9 @@ "related_bugs": [ "bug-1479" ], - "fix_commits": [], + "fix_commits": [ + "762c6f18" + ], "record": ".wolf/bugs/bug-1920.md" } ] diff --git a/.wolf/bugs/bug-1920.md b/.wolf/bugs/bug-1920.md index ba33603d..3b8ef7e0 100644 --- a/.wolf/bugs/bug-1920.md +++ b/.wolf/bugs/bug-1920.md @@ -1,8 +1,8 @@ --- id: "bug-1920" -status: "investigating" +status: "fixed" status_updated: "2026-10-04" -status_note: "Next: why ha_stream_wal_to_standby sends no walCatchupEntry for [341..342] after the NACK, and why the NACK backoff lands at 340 rather than the standby's match 323" +status_note: "" component: "controller" severity: "hang" timestamp: "2026-10-04T07:25:24Z" @@ -11,6 +11,7 @@ occurrences: 1 files: ["src/controller/ha.c", "src/controller/config_repl.c", "src/controller/repl.c"] tags: ["ha", "repl", "catch-up", "soak"] related: ["bug-1479"] +fix_commits: ["762c6f18"] --- # bug-1920: new primary's WAL catch-up stalls after log-mismatch NACK; standby never advances, commits stuck @@ -53,15 +54,23 @@ After the term-21 election the standby's Raft log matched only to 323. The first - Evidence: session scratchpad stall-ctrl-1.log, stall-ctrl-2.log; soak log soak-seq3.log (deploy dir ha-seq3) ## Root cause -TODO: required for fixed/partial +Three layers; the first is the defect, the other two let it turn into a stall: +1. **Pre-recovery WAL writes corrupt the segment layout.** A restarted standby accepts the primary's connection during its startup delay, before `cluster_init_phase2`/`persist_recover` runs (bug-849's "phase2 before cluster_run accepts replication" does not hold: ctrl-2 got the primary hello at 07:05:47.806, phase2 ran at 07:05:48.18). In that window the primary streams catch-up from the advertised `applied_lsn=0`, and `persist_wal_write_replicated` wrote into the un-recovered `persist_t` (`current_lsn=1`, no open segment): `open_new_segment` O_TRUNC'd the existing `seg-0000000000000001.wal` and rewrote LSNs 1..234 into it. `persist_recover` then set `current_lsn=306` but left that fd open as the append segment, so LSNs 306..348 were filed under `seg-...0001`. Found on disk: ctrl-2's seg-1 = 1..234 then 306..348; no `seg-...0132`. The bug-1416 `recovery_complete` gate already closed this window for apply, but not for WAL writes. +2. **The catch-up streamer silently sends nothing.** `ha_stream_wal_to_standby` orders segments by filename start LSN and skips any segment whose successor starts at or below the standby's position, so it skipped seg-1 and found no entry above 305. It still logged "streamed WAL [..] to standby" with zero entries sent. +3. **The catch-up start position runs above the standby's log.** After a log-mismatch NACK (prevIdx=341), `ha_raft_on_repl_nack` set the join position to next_index-1 = 340, and `ha_dispatch_repl_action_for_standby` let it override the standby's own report (323). From 340, even a correct stream needs one rejected round per heartbeat to walk back 17 entries. + +Scan of the four 2026-10-04 soaks: 3 nodes in 2 runs had a misfiled seg-1. It stalls only when that node later becomes primary and a standby needs catch-up from the misfiled range. ## Fix -TODO: required for fixed/partial +- `persist_wal_write_replicated` returns `-EBUSY` while `!persist_recovery_complete(p)` (the bug-1416 gate that myapp closes before any network traffic and that `persist_recover` reopens). This is the backstop for every replicated-write path. +- `ha_apply_wal_catchup_entry` and `ha_handle_snapshot_chunk` drop replication traffic silently before recovery: no persist, no ACK, no NACK (a NACK would walk the primary's next_index back past entries this node really holds). One INFO line per process. +- `ha_dispatch_repl_action_for_standby` streams from min(join position, standby report): a lower join position (a bug-1479 conflicted suffix) still wins. +- `ha_stream_wal_to_standby` WARNs "found NO entries" when a non-empty range yields nothing, and logs the entry count on success. ## Verification -- Test: TODO: name + file; RED before the fix, GREEN after -- Suites: TODO: suite results and build profile -- Live: TODO: soak/deploy run, or n/a and why +- Test: `test_replicated_write_refused_before_recovery` (src/controller/testsuite/test_commit_durability.c: a pre-recovery replicated write leaves seg-1 intact and the first post-recovery append opens seg-), `test_intake_dropped_before_recovery` (test_term_safety_adapter.c: neither ACK nor NACK, nothing persisted), `test_dispatch_streams_from_min_of_join_and_report` (test_convergence_verification.c: streams from 323 rather than 340; a lower join position still wins). All three RED before the fix (write returned 0 / ACK sent / streamed from 340), GREEN after. +- Suites: `xce-build.sh all` asan, 127/127 meson suites OK, Go tests ok (2026-10-04). +- Live: 4x `/xce-test-ha` sequential 20 rounds, 2026-10-04: 4/4 PASS. The pre-recovery drop fired 14 times (3-5 per run), no "found NO entries" warning, and a scan of every node's WAL found every segment's first LSN equal to its filename with no LSN jumps. Before the fix, the same scan found misfiled seg-1 on 3 nodes in 2 of 4 runs. Longer runs, 2026-10-04: sequential 50 rounds PASS, chaotic 50 rounds PASS (zero committed divergence), sequential 30 rounds under 40 CPU spinners on 32 cores PASS. The drop fired 7/10/5 times, there was no "found NO entries" warning, the WAL layout was clean on every node, and there were no ASAN reports. ## References - Related: none