docs(buglog): bug-1920 fixed
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
762c6f1883
commit
8e97b11929
GPG key ID:
80533536B0EB651C
2 changed files with 23 additions and 12 deletions
|
|
@ -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-<its LSN>), `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"
|
||||
}
|
||||
]
|
||||
|
|
|
|||
|
|
@ -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-<its LSN>), `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
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue