fix(ha): close permanent quorum-loss deadlock on log-conflicted standby (bug-1479)

Chaotic election churn (config-upgrade-snapshot task 8.6's force_elect_node
rotation) can leave a standby log-conflicted after a rejoin. Fixing this
needed three compounding layers, each unit-green but still failing the
identical live scenario until the next layer landed:

1. ha_raft_on_repl_nack (ha.c/ha.h): routes a WAL-ACK NACK into the raft
   library's nextIndex backoff and immediately repl_start_catchup's the
   standby at the corrected position, instead of the 16-strike silent
   eviction with no catch-up driver after it. Correct from the start, but
   live soak still failed identically: nothing ever produced the NACK this
   code was waiting for.

2. Standby-side NACK sending: ha_apply_term_entry_via_library's logOk-reject
   path now calls a new ha_send_wal_ack_reply_ex(..., success=0) instead of
   silently dropping the reject. ha_send_wal_ack_reply had hardcoded
   success=1 unconditionally -- the only WalAckReply sender in the
   controller -- making (1)'s NACK-routing correct but unreachable dead
   code. New ha_wal_ack_send_hook (XCE_TESTING) lets a unit test observe
   the NACK without a live endpoint. Live-confirmed the NACK now reaches
   the primary -- but the scenario still failed for a third reason.

3. ha_compute_repl_stream_ceiling_lsn (ha.c/ha.h): ha_stream_wal_to_standby's
   catch-up range was hard-bounded at committed_lsn, which can never advance
   in this exact scenario because advancing it requires an ACK from the very
   standby that's stuck catching up (2-of-3 alive, this standby is the only
   path to a new majority) -- a self-referential deadlock. Widens the
   STREAM_WAL ceiling (and the convergence check gating it) to the leader's
   own log tail, matching raft.tla's real AppendEntries semantics
   (leaderCommit is advisory, never a send-cap), while reusing bug-1478's
   exact guard so this doesn't reopen that trap (never widen onto a trailing
   local-only checkpoint's own unstreamable LSN).

Verification: controller_unit_test 1053/1053 PASS, clean twice, including
new regression tests for all three layers (test_config_repl.c,
test_term_safety_adapter.c, test_ha_role.c), each RED-confirmed against its
pre-fix behavior before the real fix was restored. Three successive live
run-ha-soak.sh --config-upgrade re-runs tracked each layer landing; the
final run passed end-to-end -- all 3 force_elect_node rounds succeeded
(ctrl-2: 3/3 jobs acked term=6; ctrl-3: 3/3 jobs acked term=7, never
previously reached), zero materialized-state divergence, zero job loss.
Unblocks config-upgrade-snapshot task 8.6.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-07-29 04:11:32 +00:00
parent aecd8766f4
commit 34ab78d72d
14 changed files with 1256 additions and 377 deletions

View file

@ -12,6 +12,8 @@
- Keep test logs for analysis, don't skip intermediate output even if a test hangs
## Key Learnings
- (2026-07-28, bug-1479 ROOT-CAUSED not fixed) A permanent quorum-loss family member unrelated to admission control: when repl.c's `repl_broadcast` (live single-entry WAL tail-follow) gets an `ae_reject_logmismatch` NACK back from a standby (a genuinely NORMAL Raft outcome after rapid leader-election churn leaves a conflicting uncommitted tail entry at the same LSN with a different term — confirmed byte-precise via `xce_test waldump`: ctrl-2's own lsn=13 was its own deposed term=3 noop, while the canonical/surviving log has a DIFFERENT term=4 noop at the same lsn), NOTHING in ha.c's `repl_ack_decode_and_dispatch` NACK branch (`!success`) does anything but check for a higher observed term and then literally `WARN("...success=0 — ignoring")` — no `repl_on_ack` call (the ONLY site that decrements `pending_ack_count`), no nextIndex backoff-and-retry, no catch-up trigger. Consequence: `pending_ack_count` climbs 1-per-broadcast-attempt with zero decrements until `repl_broadcast`'s own `MAX_PENDING_ACKS=16` defensive eviction fires and marks the standby `in_catch_up=1` — which correctly excludes it from `repl_active_standby_count`/quorum, but NOTHING then drives an actual catch-up stream/snapshot-install for it (the only other `repl_complete_catchup` call site, config_repl.c's ACK-driven `catchup_lane_fn`, can never engage a standby that never sends a genuine ACK in the first place). Net effect: a standby with ONE conflicting log entry from election churn (routine, expected) becomes PERMANENTLY excluded from quorum with no self-healing path — in a 3-node cluster this is one unlucky election sequence away from total write-quorum loss. **General lesson**: when a symptom looks like "resource exhaustion" (admission cap, connection pool, whatever), always verify the actual counter's INCREMENT and DECREMENT sites are symmetric across EVERY reply outcome (success AND failure/reject), not just the happy path — a counter that only decrements on success but increments unconditionally will silently drift to its ceiling under ANY sustained failure condition, which looks identical to a genuine leak from the outside (repeated timeouts / repeated rejects) but has a completely different fix (handle the reject/failure path, not "find the missing release call"). Confirmed the ORIGINAL admission-slot-leak hypothesis for this bug was WRONG by checking `commit_resolve()`/`wait_release_locked()` — those DO release correctly on every timeout, 1:1 (17 timeouts, 17 releases) — before chasing the real mechanism.
- (2026-07-28, waldump REPL usage) `xce_test` (built at `src/xce.build/controller/xce_test` or `src/build.dbg/controller/xce_test`) has no `waldump` CLI flag — `--help` only shows generic argp options. It's a REPL: pipe commands via stdin, e.g. `printf 'waldump <data_dir_or_wal_seg>\nquit\n' | ASAN_OPTIONS=detect_leaks=0 timeout 60 <path-to-xce_test>` (mirrors the `xtest()` shell helper in both `clean_failover_preservation.sh` and `run-ha-soak.sh`). Output columns are `LSN | TERM | TYPE | PLEN | PCRC | INFO` — the PLEN column is payload length, NOT a second type code (a WAL_CONFIG_MARKER shows as `UNKNOWN | 40 |` because waldump's type-name table has no case for type 50 yet — 40 there is the marker's 40-byte payload length, not its wire type number). This is a fast, byte-precise way to independently confirm/refute term or index divergence between two members' WALs without instrumenting production code.
- (2026-07-27/28, bug-1475 FIXED) A term/version index that grows its backing array geometrically and zero-fills the newly-grown region to mean "absent" has a subtle, TIME-DEPENDENT bug: zero-filling with the same sentinel value used for a legitimate "recorded as literal 0" entry makes a deliberately-never-recorded slot (here: persist.c's per-LSN term_index, where a WAL_CHECKPOINT's own LSN is BY DESIGN never passed to record_entry_term) silently and RETROACTIVELY flip from "absent" to "present, value 0" the instant ANY later index is recorded and the array-growth watermark (`term_index_count`) crosses it — even though nothing ever explicitly wrote to that slot. Two readers that check the SAME never-recorded slot at DIFFERENT times (e.g. a sender that reads it AFTER appending later entries, vs. a receiver that reads it BEFORE appending anything past it) get DIFFERENT answers for what should be a stable, position-only fact — this produced a permanent AppendEntries logOk rejection (bug-1475: sender computed prev_log_term=1 (WAL_LEGACY_TERM), receiver computed prev_log_term=0 (absent), for the identical checkpoint LSN). **General fix pattern**: reserve a DIFFERENT sentinel (here `TERM_INDEX_UNSET = UINT64_MAX`, filled via `memset(...,0xFF,...)` on array growth) distinct from every legitimate stored value, so a never-explicitly-written slot reads "absent" PERMANENTLY, independent of later growth — never let "grown but unwritten" collide with a real, meaningful value (here, literal term 0 / WAL_LEGACY_TERM) in the same sentinel. **Do-not-repeat**: when hand-tracing (not instrumenting) a bug involving an in-memory index that has a documented "grows on demand, gaps read as absent" contract, don't trust that the gap actually STAYS absent across the FULL lifetime of the process/test — verify with real instrumentation whether "absent" is a stable property of the position or merely a snapshot of "not yet grown past." This was found only after two prior, plausible-looking production fixes (config_repl.c's tracker-advance + ha.c's JIT log_len resync, both already landed) still left the regression test RED — real fprintf instrumentation at the streamer, the JIT resync, and raft.c's logOk check (all added and fully removed afterward) pinned the exact moment prev_log_term flipped from 0 to 1. See `.wolf/buglog.json` bug-1475 for the full three-part fix and `test_bug1475_catchup_survives_midstream_checkpoint` (test_config_repl.c) for the regression proof.
- (2026-07-11, controller_unit_test isolated-group + leak-detection runs) `controller_unit_test` supports `--run STR` (repeatable, arg key `-t`) to select one or more TEST()-registered groups by exact function name (matches `argp`-parsed `-t`/`--run`, dispatch via `check_test()`/`TEST()` macro in `controller_test.c`) — use it to isolate a single suite instead of parsing the full-suite log. Full-suite direct runs interleave two PASS-print conventions: older suites only print via Unity's own per-assertion output (no `<file>:<line>:<name>:PASS` banner), while newer TDD suites (apply/HA-prevote family) add a custom `printf("%s: PASS\n", ...)` + banner — so grepping for `../controller/testsuite/<file>.c` banners under-counts groups that don't use the newer convention; don't infer suite pass/fail or crash-truncation from banner presence alone, always check the process exit code. Confirmed via meson (`Ok:1/Fail:0`, one lumped "controller test") AND a clean direct exit(0) with zero grep hits for AddressSanitizer/heap-buffer-overflow/UAF/double-free/FAIL across a 15.7k-line full-suite log — the log's abrupt-looking tail (last group's own internal UNITY_BEGIN/END subtotal printed twice) is normal, not truncation; verify with `echo $?` instead. The historical "test_ha_prevote 18/18" figure from an earlier session was the COMBINED total of `test_ha_prevote` (12 tests, confirmed via `grep -c RUN_TEST` in the .c file) + `test_ha_failover_prevote` (6 tests) — the two are separate TEST() groups in `controller_test.c`, not one suite of 18; report them separately (12/12 + 6/6) to avoid a false "regression" reading.
@ -574,3 +576,10 @@ Resumed `/kiro-impl config-upgrade-snapshot` with buglog.json's bug-1476 entry c
## Do-Not-Repeat (2026-07-28, bug-1477 live verification) — confirming ONE bug's fix live can surface a DIFFERENT bug at a LATER step the soak never previously reached
Re-running `run-ha-soak.sh --config-upgrade` after the bug-1477 fix: the bug's own specific symptoms (checkpoint-identity, config-identity, host-admin-status-survival assertions) all PASSED for the first time. But the SAME soak run then failed later, in the force-elect-rotation step, with repeated commit timeouts (rc=-110) on the primary — a step this soak scenario had NEVER reached before (every prior attempt failed earlier, first at bug-1471/1472's checkpoint divergence, then at bug-1477's own catch-up wedge). **Do-not-repeat**: don't assume a soak reaching further and failing differently means your fix is broken or incomplete — check whether the NEW failure point was ever exercised before; if not, it's very plausibly a separate, pre-existing, newly-exposed bug (same pattern as this whole session's bug-1471→1472→1474→1477 chain), not evidence the just-verified fix regressed something. Investigate the new failure on its own terms (what's different about THIS code path) rather than assuming causality from the just-changed code.
## Key Learning (2026-07-29, bug-1479 FIXED — 3-layer fix, each layer only verifiable live) — a correct adapter-side fix can be unit-green and still be dead code in production; only a live re-run proves the wire is actually connected
bug-1479 (permanent quorum loss when a standby log-conflicts during chaotic election churn) needed THREE compounding fixes, and each of the first two looked complete after a clean unit-test run yet still failed the EXACT SAME live scenario (`run-ha-soak.sh --config-upgrade`'s `force_elect_node` loop) for a NEW reason each time:
1. **`ha_raft_on_repl_nack`** (primary-side): routes a WAL-ACK-reply NACK into the raft library's nextIndex backoff + immediate `repl_start_catchup`. Unit-correct, 1048/1048 green — but live soak v1 still failed identically (0/3 acked), because nothing ever produced the `success=0` reply this code was waiting for.
2. **Standby-side NACK sending** (`ha_apply_term_entry_via_library`'s logOk-reject path now calls `ha_send_wal_ack_reply_ex(..., success=0)` instead of silently dropping the reject — `ha_send_wal_ack_reply` had hardcoded `success=1` unconditionally, the ONLY WalAckReply sender in the whole controller). Unit-correct, verified via a new capture-hook test — but live soak v2 confirmed the NACK NOW reaches the primary (log-grepped: `WAL NACK from standby ... success=0`) and STILL failed identically, because `ha_stream_wal_to_standby`'s catch-up range was hard-capped at `committed_lsn`, which can never advance without this exact standby's own ack — a self-referential deadlock invisible from EITHER side's code in isolation.
3. **`ha_compute_repl_stream_ceiling_lsn`**: widens the STREAM_WAL ceiling (and the convergence check gating it) to the leader's own log tail, matching raft.tla's real AppendEntries semantics (leaderCommit is advisory, never a send-cap) — while re-using bug-1478's exact guard (never widen onto a trailing local-only checkpoint's unstreamable LSN) so fixing gap 3 didn't reopen gap-1478. Live soak v3: PASS, all 3 force-elect rounds, 1053/1053 unit tests.
**Do-not-repeat**: when an adapter/wire-protocol fix passes its own unit tests, that only proves the function is INTERNALLY correct — it does NOT prove anything upstream/downstream actually calls it with real data. For any fix whose job is "handle X when X arrives," always ALSO verify (via a live/integration run, log-grepped, not inferred) that X actually arrives in production BEFORE declaring victory — a unit-green "correct but unreachable" fix is functionally identical to no fix at all, and the only way to catch that is to re-run the EXACT scenario that surfaced the original bug, all the way to its real end state, every time a layer is added.