81 lines
8.2 KiB
Markdown
81 lines
8.2 KiB
Markdown
---
|
|
id: "bug-1920"
|
|
status: "fixed"
|
|
status_updated: "2026-10-04"
|
|
status_note: ""
|
|
component: "controller"
|
|
severity: "hang"
|
|
timestamp: "2026-10-04T07:25:24Z"
|
|
last_seen: "2026-10-04T07:25:24Z"
|
|
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"]
|
|
gitea_issue: 340
|
|
gitea_synced_status: "fixed"
|
|
gitea_synced_hash: "92bfd940b0d5"
|
|
---
|
|
|
|
# bug-1920: new primary's WAL catch-up stalls after log-mismatch NACK; standby never advances, commits stuck
|
|
|
|
## Description
|
|
**Observed:**
|
|
```
|
|
# new primary ctrl-2 (term 21), its only reachable standby ctrl-1 (ctrl-3 killed):
|
|
07:06:45,520 ctrl-2 HA repl: standby[0] lsn=323 < stream_ceiling_lsn=342 (committed_lsn=341) → stream WAL batches
|
|
07:06:45,522 ctrl-2 ha_stream_wal_to_standby: streamed WAL [323+1..342] to standby
|
|
07: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)
|
|
07:06:45,523 ctrl-2 repl_ack_decode_and_dispatch: WAL NACK from standby lsn=342 success=0 — marking catch-up
|
|
07:06:48,603 ctrl-2 HA repl: standby[0] lsn=340 < stream_ceiling_lsn=342 (committed_lsn=341) → stream WAL batches
|
|
07:06:48,603 ctrl-2 ha_stream_wal_to_standby: streamed WAL [340+1..342] to standby
|
|
07:06:48,602 ctrl-1 ha_consume_append_entries: leader_idx=-1 term=21 prevIdx=323 n=0 -> success=1 match=323 (nop heartbeat)
|
|
... same pair every 3 s for >60 s; ctrl-1 never logs another walCatchupEntry ...
|
|
07:07:47,044 ctrl-2 commit: WAIT deadline expired without commit (lsn=343 committed_lsn=341 writable_lsn=342 timeout_ms=500)
|
|
worker: xcecli failover: cluster not ready after 21 attempts (last status=-10013)
|
|
[xce-test-ha] FAIL: round 19: worker-resync job ...: worker never logged a fresh rejoin after the failover (pre=18 post=18)
|
|
```
|
|
After 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.
|
|
|
|
**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.
|
|
**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.
|
|
**Found by:** soak (`/xce-test-ha` sequential 20 rounds, validating bug-1919, 2026-10-04)
|
|
|
|
## Environment
|
|
- OS: no /etc/os-release; Docker container; NixOS kernel; kernel Linux 6.18.33 x86_64
|
|
- libc: glibc 2.42-47 (interpreter /nix/store/wb6rhpznjfczwlwx23zmdrrw74bayxw4-glibc-2.42-47/lib/ld-linux-x86-64.so.2)
|
|
- Toolchain: gcc (GCC) 15.2.0, meson 1.9.1
|
|
- Build: asan (xce.build)
|
|
- Code: scheduler-framework @ acf78f9a-dirty
|
|
- Deployment: local 3-node HA (`/xce-test-ha` sequential), one xcecd_virtual soak worker + scheduler; working tree also carries the uncommitted bug-1915 and bug-1919 changes
|
|
|
|
## Reproduction
|
|
1. `XCE_HA_ROUNDS=20 nix develop ./src --command bash .claude/skills/xce-test-ha/run-ha-soak.sh 20 <scratch dir>`.
|
|
2. Needs a failover where the surviving standby's log is far behind the new primary's (here match 323 vs leader tip 342) when the new primary registers it.
|
|
3. Round fails "worker never logged a fresh rejoin"; ctrl-2.log repeats `standby[0] lsn=340 < stream_ceiling_lsn=342` every 3 s with no walCatchupEntry arriving at ctrl-1.
|
|
- Frequency: 1/4 soak runs, 2026-10-04 (round 19 of run 3)
|
|
- Evidence: session scratchpad stall-ctrl-1.log, stall-ctrl-2.log; soak log soak-seq3.log (deploy dir ha-seq3)
|
|
|
|
## Root cause
|
|
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
|
|
- `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: `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.
|
|
|
|
UPDATE (2026-10-08): Permanent gate (2026-10-08, 5cf92335): the sequential, chaotic and truncated-fence soak modes now run wal-layout-check.py before PASS; it flags the pre-fix runs' misfiled seg-...0001 and passed a sequential 20-round soak (25 segments, 0 problems).
|
|
|
|
## References
|
|
- Related: none
|