docs(buglog): bug-1915 and bug-1919 fixed; log bug-1920
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
0ab12074f5
commit
f01bb7de34
GPG key ID:
80533536B0EB651C
4 changed files with 205 additions and 14 deletions
|
|
@ -17181,9 +17181,9 @@
|
|||
},
|
||||
{
|
||||
"id": "bug-1915",
|
||||
"status": "investigating",
|
||||
"status_updated": "2026-10-03",
|
||||
"status_note": "single log sample; reproduce under load and check election/term handling around elect_ctx replacement",
|
||||
"status": "fixed",
|
||||
"status_updated": "2026-10-04",
|
||||
"status_note": "",
|
||||
"component": "controller",
|
||||
"severity": "wrong-result",
|
||||
"timestamp": "2026-10-03T16:10:25Z",
|
||||
|
|
@ -17191,8 +17191,8 @@
|
|||
"occurrences": 1,
|
||||
"error_message": "two PreVote wins in one election replace elect_ctx; term-2 leader then finds no vote eps to promote\n\n**Observed:**\nIn one primary log captured during the bug-1913 investigation (late-joiner election under 40-spinner CPU load), \"PreVote round WON\" appears twice (prospective terms 2 and 3). The second real election replaced `ha->elect_ctx`, and the term-2 `raft_cb_become_leader` then found no vote endpoints to promote into standby channels, so both standbys had to register later as late joiners (bug-1913). A term-2 leader was also logged after the term-3 election had started.\n\n**Expected:** one election round per prospective term; a node that becomes leader promotes the vote connections from the election that elected it (or the stale election cannot complete leadership).\n**Impact:** unconfirmed (single sample). It is the trigger for late-joiner elections (bug-1913, now mitigated by an immediate catch-up probe), and a leader logged for an older term after a newer election started needs a Raft-safety check (term monotonicity, which election's votes made it leader).\n**Found by:** test (bug-1913 investigation, 2026-10-03)",
|
||||
"file": "src/controller/ha.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": "A PreVote round could be decided more than once, and stale election traffic was not tied to the election it belonged to:\n- `raft_on_pre_vote_reply` kept tallying after a round was already decided, so a late grant after WON re-ran the WON path and started a second real election (prospective term 3) that replaced `ha->elect_ctx` while the term-2 election was still completing.\n- `raft_cb_become_leader` promoted vote endpoints from whatever `elect_ctx` was current, not the one that elected it, so the term-2 leader found the term-3 record (no granted eps) and promoted nobody (the bug-1913 late-joiner trigger).\n- Related gaps found in review: a PreVote round could start while a real election was running or on a leader; replies, timeouts and endpoint errors from an older round (or a PreVote reply arriving on a real-vote endpoint, and vice versa) were counted against the current one; `raft_on_leader_lost` cleared `voted_for` within the same term, so a delayed same-term RequestVote from another candidate could be granted (two votes in one term); the failover stagger started PreVote inline on the delaymgr thread.",
|
||||
"fix": "- raft (src/lib/raft): a reply with no round in progress is a no-op, so a round is decided at most once. `raft_on_leader_lost` keeps `voted_for` and records `leader_lost_term`; `raft_check_and_start_election` starts the delayed election only while still a FOLLOWER in that term.\n- controller (src/controller/ha.c/.h): every PreVote round has an id, and every PreVote endpoint carries its round and kind. Replies, round timeouts and endpoint errors from another round or of the other kind are dropped. Stale real-election replies (other elect_term) are not counted; a higher term still steps down. A PreVote round starts only on a follower with no election in progress, and each open round always has its timeout timer (arm failure closes the round). `raft_cb_become_leader` promotes only with THIS election's vote record (stamped carrier, own term, majority); otherwise it refuses, steps down to FOLLOWER in the same term and re-arms. A cancelled round timer returns without taking raft_lock. The failover stagger hands the PreVote start to a vtask (delaymgr stays trigger-only), re-checking that the primary is still gone, with an inline fallback when there is no pool.\n\nVerification:\n- Test: src/controller/testsuite/test_ha_prevote.c: `test_bug1915_late_grant_after_won_is_ignored`, `test_bug1915_late_deny_after_won_is_ignored`, plus the gapA/gapB/gapD/gapE, become_leader_*, r2_f* and final_f* cases; src/lib/testsuite/test_raft.c: `test_leader_lost_keeps_voted_for`, `test_leader_lost_same_term_vote_from_other_denied`, `test_check_and_start_after_leader_lost_same_term_starts`, `test_check_and_start_skips_when_not_follower`. Written ahead of each change in the 2026-10-03 fix sessions (RED/GREEN per the session log; RED not re-run on 2026-10-04).\n- Suites: `xce-build.sh all` asan, 127/127 meson suites OK + Go tests ok (2026-10-04, together with bug-1919).\n- Live: 2026-10-03: `/xce-test-ha` chaotic 6 and loaded 8 rounds PASS; the sequential 20-round run failed on bug-1919 (fence), with a clean single-decision election timeline. 2026-10-04: 4x sequential 20 rounds, 3 PASS, 1 FAIL on bug-1920 (catch-up stream stall after a log-mismatch NACK; under investigation, relation to this change not established). Across the four 2026-10-04 runs, 94 PreVote rounds were decided WON and none twice (one \"PreVote round N WON\" per pid+round+term).",
|
||||
"tags": [
|
||||
"ha",
|
||||
"raft",
|
||||
|
|
@ -17202,7 +17202,9 @@
|
|||
"related_bugs": [
|
||||
"bug-1913"
|
||||
],
|
||||
"fix_commits": [],
|
||||
"fix_commits": [
|
||||
"88a8bf8a"
|
||||
],
|
||||
"record": ".wolf/bugs/bug-1915.md"
|
||||
},
|
||||
{
|
||||
|
|
@ -17285,6 +17287,59 @@
|
|||
],
|
||||
"fix_commits": [],
|
||||
"record": ".wolf/bugs/bug-1918.md"
|
||||
},
|
||||
{
|
||||
"id": "bug-1919",
|
||||
"status": "fixed",
|
||||
"status_updated": "2026-10-04",
|
||||
"status_note": "",
|
||||
"component": "controller",
|
||||
"severity": "wrong-result",
|
||||
"timestamp": "2026-10-04T06:10:10Z",
|
||||
"last_seen": "2026-10-04T06:10:10Z",
|
||||
"occurrences": 1,
|
||||
"error_message": "promotion fence never releases on a node that booted RECOVER_TRUNCATED, even after full catch-up\n\n**Observed:**\n```\n05:57:15,308 HA: promotion REFUSED (decision=1 ...) — recovery_truncated=1 durable_floor=360 cluster_hwm=360 peer_reachable=1; fencing + arming catch-up re-alert window, staying ALIVE\n05:57:15,308 HA: promotion FENCED + catch-up re-alert window armed (30000 ms) — recovery_truncated=1 durable_floor=360 < cluster HWM=360\n05:57:45,483 HA: promotion fence catch-up window elapsed but progress is possible (peer_reachable=0 durable_floor=375 baseline=360 HWM=360) — remaining fenced, catching up\n[xce-test-ha] FAIL: leadership-coverage: cluster did not reconverge before maneuver\n```\n`promotion_fence_timeout_fn` (src/controller/ha.c ~1546-1640) releases the fence only if `!truncated && !below_hwm && ...`, where `truncated = persist_recovery_truncated()` = `recovery_verdict == RECOVER_TRUNCATED` (persist.c:7005) — the BOOT-time recovery verdict, which never changes at runtime. So for a node that booted truncated the release branch is unreachable however far it catches up (here durable_floor 375 >= HWM 360). In the \"progress is possible\" branch the timer frees itself and returns WITHOUT re-arming, so the fence is never re-evaluated. `in_catch_up` stays 1, `ctrlstatus` reports `fenced: true` (ctrlstatus.c:193) forever, and `/xce-test-ha`'s `cluster_committed_converged` (a fenced member is not converged) never succeeds.\n\n**Expected:** once the fenced member has caught up to a committed-consistent state (durable floor >= the cluster HWM the fence was armed with, as a standby of the live primary), the fence is released (ha-commit-durability Req 2.6) and the node is promotable and reported converged; the re-check keeps running until that happens.\n**Impact:** a controller that was killed as primary, rebooted with a truncated WAL tail, and later attempted promotion stays fenced (non-promotable, `fenced: true`) until restarted, even though it is fully caught up: the cluster loses one promotion candidate (in a 3-node cluster, the next failover may then have only one eligible node), and soak convergence gates fail. No data loss (fail-safe direction).\n**Found by:** soak (`/xce-test-ha` sequential 20 rounds, validating bug-1915, 2026-10-04)",
|
||||
"file": "src/controller/ha.c, src/controller/persist.c, src/controller/ctrlstatus.c",
|
||||
"root_cause": "Two defects in `promotion_fence_timeout_fn` (src/controller/ha.c):\n1. The release branch requires `!persist_recovery_truncated()`, which read the boot-time `recovery_verdict` only. Nothing at runtime ever cleared it, so a member that booted RECOVER_TRUNCATED could never pass the release check, however far it caught up. The existing unit test `test_promotion_fence_released_on_catchup` hid this by writing `recovery_verdict = RECOVER_CLEAN` directly, which production never does.\n2. The \"progress is possible\" branch (peer reachable or durable floor advanced) freed the timer ctx without re-arming, citing \"existing catch-up machinery\" that would release the fence. No such path exists (the only other releases are the election gate, which itself refuses a truncated node, and `ha_evaluate_promotion_fence`, which has no production caller on this path). So once that branch ran, the fence was never re-evaluated.",
|
||||
"fix": "- `persist_t.recovery_truncation_healed` (src/include/persist.h): a runtime latch, reset by `persist_init`/`persist_recover`, set by the new `persist_mark_recovery_truncation_healed()`. `persist_recovery_truncated()` now returns `verdict == RECOVER_TRUNCATED && !healed`. `persist_recovery_verdict()` still returns the raw boot verdict for diagnostics.\n- `promotion_fence_timeout_fn`: if the member is truncated AND `durable_floor >= target_hwm` AND `durable_floor > baseline` (contiguous entries replicated from the live primary on top of the truncated log; a fenced member is never primary), mark the truncation healed and fall through to the release check. Without progress nothing proves the log matches the primary's, so the fence stays (conservative).\n- The \"progress is possible\" branch re-arms the timer with the SAME baseline and HWM, so re-evaluation continues until the release.\n\nVerification:\n- Test: `test_promotion_fence_truncated_boot_released_after_catchup` and `test_promotion_fence_rechecks_while_catching_up` (src/controller/testsuite/test_commit_durability.c) were RED before the fix (fence never released) and GREEN after; `test_promotion_fence_truncated_no_progress_stays_fenced` pins the conservative no-progress rule (GREEN before and 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. Run 2 hit the exact path: ctrl boot RECOVER_TRUNCATED → promotion REFUSED (durable_floor=323, HWM=323) → 30 s later \"recovery-truncated log healed by catch-up — durable_floor=338 (baseline=323)\" + \"promotion fence RELEASED\", and the soak PASSed (all 3 nodes led). Runs 1 and 4 PASS (path not hit). Run 3 FAILed on an unrelated replication catch-up stall (logged separately, no fence/truncation in that run).",
|
||||
"tags": [
|
||||
"ha",
|
||||
"fence",
|
||||
"recovery",
|
||||
"catch-up",
|
||||
"soak"
|
||||
],
|
||||
"related_bugs": [],
|
||||
"fix_commits": [
|
||||
"0ab12074"
|
||||
],
|
||||
"record": ".wolf/bugs/bug-1919.md"
|
||||
},
|
||||
{
|
||||
"id": "bug-1920",
|
||||
"status": "investigating",
|
||||
"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",
|
||||
"component": "controller",
|
||||
"severity": "hang",
|
||||
"timestamp": "2026-10-04T07:25:24Z",
|
||||
"last_seen": "2026-10-04T07:25:24Z",
|
||||
"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",
|
||||
"tags": [
|
||||
"ha",
|
||||
"repl",
|
||||
"catch-up",
|
||||
"soak"
|
||||
],
|
||||
"related_bugs": [
|
||||
"bug-1479"
|
||||
],
|
||||
"fix_commits": [],
|
||||
"record": ".wolf/bugs/bug-1920.md"
|
||||
}
|
||||
]
|
||||
}
|
||||
|
|
|
|||
|
|
@ -1,8 +1,8 @@
|
|||
---
|
||||
id: "bug-1915"
|
||||
status: "investigating"
|
||||
status_updated: "2026-10-03"
|
||||
status_note: "single log sample; reproduce under load and check election/term handling around elect_ctx replacement"
|
||||
status: "fixed"
|
||||
status_updated: "2026-10-04"
|
||||
status_note: ""
|
||||
component: "controller"
|
||||
severity: "wrong-result"
|
||||
timestamp: "2026-10-03T16:10:25Z"
|
||||
|
|
@ -11,6 +11,7 @@ occurrences: 1
|
|||
files: ["src/controller/ha.c"]
|
||||
tags: ["ha", "raft", "election", "prevote"]
|
||||
related: ["bug-1913"]
|
||||
fix_commits: ["88a8bf8a"]
|
||||
---
|
||||
|
||||
# bug-1915: two PreVote wins in one election replace elect_ctx; term-2 leader then finds no vote eps to promote
|
||||
|
|
@ -38,15 +39,19 @@ In one primary log captured during the bug-1913 investigation (late-joiner elect
|
|||
- Evidence: not kept (scratchpad loop logs from the bug-1913 investigation)
|
||||
|
||||
## Root cause
|
||||
TODO: required for fixed/partial
|
||||
A PreVote round could be decided more than once, and stale election traffic was not tied to the election it belonged to:
|
||||
- `raft_on_pre_vote_reply` kept tallying after a round was already decided, so a late grant after WON re-ran the WON path and started a second real election (prospective term 3) that replaced `ha->elect_ctx` while the term-2 election was still completing.
|
||||
- `raft_cb_become_leader` promoted vote endpoints from whatever `elect_ctx` was current, not the one that elected it, so the term-2 leader found the term-3 record (no granted eps) and promoted nobody (the bug-1913 late-joiner trigger).
|
||||
- Related gaps found in review: a PreVote round could start while a real election was running or on a leader; replies, timeouts and endpoint errors from an older round (or a PreVote reply arriving on a real-vote endpoint, and vice versa) were counted against the current one; `raft_on_leader_lost` cleared `voted_for` within the same term, so a delayed same-term RequestVote from another candidate could be granted (two votes in one term); the failover stagger started PreVote inline on the delaymgr thread.
|
||||
|
||||
## Fix
|
||||
TODO: required for fixed/partial
|
||||
- raft (src/lib/raft): a reply with no round in progress is a no-op, so a round is decided at most once. `raft_on_leader_lost` keeps `voted_for` and records `leader_lost_term`; `raft_check_and_start_election` starts the delayed election only while still a FOLLOWER in that term.
|
||||
- controller (src/controller/ha.c/.h): every PreVote round has an id, and every PreVote endpoint carries its round and kind. Replies, round timeouts and endpoint errors from another round or of the other kind are dropped. Stale real-election replies (other elect_term) are not counted; a higher term still steps down. A PreVote round starts only on a follower with no election in progress, and each open round always has its timeout timer (arm failure closes the round). `raft_cb_become_leader` promotes only with THIS election's vote record (stamped carrier, own term, majority); otherwise it refuses, steps down to FOLLOWER in the same term and re-arms. A cancelled round timer returns without taking raft_lock. The failover stagger hands the PreVote start to a vtask (delaymgr stays trigger-only), re-checking that the primary is still gone, with an inline fallback when there is no pool.
|
||||
|
||||
## 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: src/controller/testsuite/test_ha_prevote.c: `test_bug1915_late_grant_after_won_is_ignored`, `test_bug1915_late_deny_after_won_is_ignored`, plus the gapA/gapB/gapD/gapE, become_leader_*, r2_f* and final_f* cases; src/lib/testsuite/test_raft.c: `test_leader_lost_keeps_voted_for`, `test_leader_lost_same_term_vote_from_other_denied`, `test_check_and_start_after_leader_lost_same_term_starts`, `test_check_and_start_skips_when_not_follower`. Written ahead of each change in the 2026-10-03 fix sessions (RED/GREEN per the session log; RED not re-run on 2026-10-04).
|
||||
- Suites: `xce-build.sh all` asan, 127/127 meson suites OK + Go tests ok (2026-10-04, together with bug-1919).
|
||||
- Live: 2026-10-03: `/xce-test-ha` chaotic 6 and loaded 8 rounds PASS; the sequential 20-round run failed on bug-1919 (fence), with a clean single-decision election timeline. 2026-10-04: 4x sequential 20 rounds, 3 PASS, 1 FAIL on bug-1920 (catch-up stream stall after a log-mismatch NACK; under investigation, relation to this change not established). Across the four 2026-10-04 runs, 94 PreVote rounds were decided WON and none twice (one "PreVote round N WON" per pid+round+term).
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
|
|
|
|||
64
.wolf/bugs/bug-1919.md
Normal file
64
.wolf/bugs/bug-1919.md
Normal file
|
|
@ -0,0 +1,64 @@
|
|||
---
|
||||
id: "bug-1919"
|
||||
status: "fixed"
|
||||
status_updated: "2026-10-04"
|
||||
status_note: ""
|
||||
component: "controller"
|
||||
severity: "wrong-result"
|
||||
timestamp: "2026-10-04T06:10:10Z"
|
||||
last_seen: "2026-10-04T06:10:10Z"
|
||||
occurrences: 1
|
||||
files: ["src/controller/ha.c", "src/controller/persist.c", "src/controller/ctrlstatus.c"]
|
||||
tags: ["ha", "fence", "recovery", "catch-up", "soak"]
|
||||
related: []
|
||||
fix_commits: ["0ab12074"]
|
||||
---
|
||||
|
||||
# bug-1919: promotion fence never releases on a node that booted RECOVER_TRUNCATED, even after full catch-up
|
||||
|
||||
## Description
|
||||
**Observed:**
|
||||
```
|
||||
05:57:15,308 HA: promotion REFUSED (decision=1 ...) — recovery_truncated=1 durable_floor=360 cluster_hwm=360 peer_reachable=1; fencing + arming catch-up re-alert window, staying ALIVE
|
||||
05:57:15,308 HA: promotion FENCED + catch-up re-alert window armed (30000 ms) — recovery_truncated=1 durable_floor=360 < cluster HWM=360
|
||||
05:57:45,483 HA: promotion fence catch-up window elapsed but progress is possible (peer_reachable=0 durable_floor=375 baseline=360 HWM=360) — remaining fenced, catching up
|
||||
[xce-test-ha] FAIL: leadership-coverage: cluster did not reconverge before maneuver
|
||||
```
|
||||
`promotion_fence_timeout_fn` (src/controller/ha.c ~1546-1640) releases the fence only if `!truncated && !below_hwm && ...`, where `truncated = persist_recovery_truncated()` = `recovery_verdict == RECOVER_TRUNCATED` (persist.c:7005) — the BOOT-time recovery verdict, which never changes at runtime. So for a node that booted truncated the release branch is unreachable however far it catches up (here durable_floor 375 >= HWM 360). In the "progress is possible" branch the timer frees itself and returns WITHOUT re-arming, so the fence is never re-evaluated. `in_catch_up` stays 1, `ctrlstatus` reports `fenced: true` (ctrlstatus.c:193) forever, and `/xce-test-ha`'s `cluster_committed_converged` (a fenced member is not converged) never succeeds.
|
||||
|
||||
**Expected:** once the fenced member has caught up to a committed-consistent state (durable floor >= the cluster HWM the fence was armed with, as a standby of the live primary), the fence is released (ha-commit-durability Req 2.6) and the node is promotable and reported converged; the re-check keeps running until that happens.
|
||||
**Impact:** a controller that was killed as primary, rebooted with a truncated WAL tail, and later attempted promotion stays fenced (non-promotable, `fenced: true`) until restarted, even though it is fully caught up: the cluster loses one promotion candidate (in a 3-node cluster, the next failover may then have only one eligible node), and soak convergence gates fail. No data loss (fail-safe direction).
|
||||
**Found by:** soak (`/xce-test-ha` sequential 20 rounds, validating bug-1915, 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), worker + scheduler joined
|
||||
|
||||
## 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 node killed as primary that reboots with `recovery_truncated=1` and later wins a PreVote; its promotion is refused (expected) and it is fenced.
|
||||
3. After it catches up as a standby, `promotion_fence_timeout_fn` logs "progress is possible ... remaining fenced" and never runs again; `ctrlstatus` keeps `fenced: true`; the soak fails "cluster did not reconverge".
|
||||
- Frequency: 1/4 soak runs, 2026-10-04 (timing-dependent: needs a truncated-boot node to attempt promotion)
|
||||
- Evidence: ctrl-2 log kept in the session scratchpad as fence-ctrl-2.log; soak log s1915-seq.log
|
||||
|
||||
## Root cause
|
||||
Two defects in `promotion_fence_timeout_fn` (src/controller/ha.c):
|
||||
1. The release branch requires `!persist_recovery_truncated()`, which read the boot-time `recovery_verdict` only. Nothing at runtime ever cleared it, so a member that booted RECOVER_TRUNCATED could never pass the release check, however far it caught up. The existing unit test `test_promotion_fence_released_on_catchup` hid this by writing `recovery_verdict = RECOVER_CLEAN` directly, which production never does.
|
||||
2. The "progress is possible" branch (peer reachable or durable floor advanced) freed the timer ctx without re-arming, citing "existing catch-up machinery" that would release the fence. No such path exists (the only other releases are the election gate, which itself refuses a truncated node, and `ha_evaluate_promotion_fence`, which has no production caller on this path). So once that branch ran, the fence was never re-evaluated.
|
||||
|
||||
## Fix
|
||||
- `persist_t.recovery_truncation_healed` (src/include/persist.h): a runtime latch, reset by `persist_init`/`persist_recover`, set by the new `persist_mark_recovery_truncation_healed()`. `persist_recovery_truncated()` now returns `verdict == RECOVER_TRUNCATED && !healed`. `persist_recovery_verdict()` still returns the raw boot verdict for diagnostics.
|
||||
- `promotion_fence_timeout_fn`: if the member is truncated AND `durable_floor >= target_hwm` AND `durable_floor > baseline` (contiguous entries replicated from the live primary on top of the truncated log; a fenced member is never primary), mark the truncation healed and fall through to the release check. Without progress nothing proves the log matches the primary's, so the fence stays (conservative).
|
||||
- The "progress is possible" branch re-arms the timer with the SAME baseline and HWM, so re-evaluation continues until the release.
|
||||
|
||||
## Verification
|
||||
- Test: `test_promotion_fence_truncated_boot_released_after_catchup` and `test_promotion_fence_rechecks_while_catching_up` (src/controller/testsuite/test_commit_durability.c) were RED before the fix (fence never released) and GREEN after; `test_promotion_fence_truncated_no_progress_stays_fenced` pins the conservative no-progress rule (GREEN before and 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. Run 2 hit the exact path: ctrl boot RECOVER_TRUNCATED → promotion REFUSED (durable_floor=323, HWM=323) → 30 s later "recovery-truncated log healed by catch-up — durable_floor=338 (baseline=323)" + "promotion fence RELEASED", and the soak PASSed (all 3 nodes led). Runs 1 and 4 PASS (path not hit). Run 3 FAILed on an unrelated replication catch-up stall (logged separately, no fence/truncation in that run).
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
67
.wolf/bugs/bug-1920.md
Normal file
67
.wolf/bugs/bug-1920.md
Normal file
|
|
@ -0,0 +1,67 @@
|
|||
---
|
||||
id: "bug-1920"
|
||||
status: "investigating"
|
||||
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"
|
||||
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"]
|
||||
---
|
||||
|
||||
# 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
|
||||
TODO: required for fixed/partial
|
||||
|
||||
## Fix
|
||||
TODO: required for fixed/partial
|
||||
|
||||
## 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
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
Loading…
Add table
Add a link
Reference in a new issue