chore(buglog): bug-1891 fixed (4922f6c8)
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
4922f6c844
commit
a928f7a79b
GPG key ID:
80533536B0EB651C
2 changed files with 23 additions and 16 deletions
|
|
@ -16477,18 +16477,18 @@
|
|||
},
|
||||
{
|
||||
"id": "bug-1891",
|
||||
"status": "open",
|
||||
"status": "fixed",
|
||||
"status_updated": "2026-09-29",
|
||||
"status_note": "newly logged",
|
||||
"status_note": "",
|
||||
"component": "controller",
|
||||
"severity": "hang",
|
||||
"timestamp": "2026-09-29T14:33:30Z",
|
||||
"last_seen": "2026-09-29T14:33:30Z",
|
||||
"occurrences": 1,
|
||||
"error_message": "xce_controller primary sends a rejoining standby's snapshot to a different standby\n\n**Observed:** after a standby (ctrl-2) is killed, wiped and rejoins empty, the primary decides a snapshot is needed from ctrl-2's state but the transfer lands on the OTHER, already caught-up standby (ctrl-3). Primary (ctrl-1), xce-1890-nd5:\n```\n[2026-09-29 14:28:20,377] ... on_standby_connected] HA: repl registered late-joiner standby peer[1] (slot 2, localhost:9992)\n[2026-09-29 14:28:44,429] ... ha_process_standby_state] HA: standby[1] converged: config_tag=7302089038923290268 applied_lsn=114 (committed_tag=... committed_lsn=114)\n[2026-09-29 14:28:44,429] ... ha_dispatch_repl_action_for_standby] HA repl: standby[1] lsn=0 < oldest_wal_lsn=112 → requesting snapshot transfer\n[2026-09-29 14:28:44,437] ... ha_send_snapshot_to_standby: snapshot transfer start checkpoint_lsn=114 size=528825\n```\nEvery such transfer (14:28:41, :44, :47, :56) was received and installed by ctrl-3 (`HA: snapshot loaded lsn=114`, 7 installs); ctrl-2 received none. The same standby[1] alternates every heartbeat between `converged ... applied_lsn=114` (ctrl-2's pre-wipe position, or ctrl-3's) and `lsn=0 → requesting snapshot`, and each request is logged twice.\n\n**Expected:** the snapshot is sent on the rejoining standby's own connection, and its status reflects only that live connection.\n**Impact:** a wiped/rejoining standby never catches up while the misrouting persists; the other standby reinstalls the same snapshot every few seconds; ctrlstatus/soak convergence is reported from stale state (the soak printed `cluster reconverged (3-of-3)` and then failed `ctrl-2's log shows NO snapshot install`).\n**Found by:** soak -- xce-test-ha --force-snapshot while verifying bug-1890, 2026-09-29. Suspected: two repl slots for peer[1] after kill+rejoin (the late-joiner slot 2 plus the pre-kill slot, cf. bug-1819/bug-1474), with state read from one slot and the send going to an endpoint that belongs to another peer.",
|
||||
"file": "src/controller/ha.c (ha_dispatch_repl_action_for_standby), src/controller/config_repl.c (ha_send_snapshot_to_standby)",
|
||||
"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",
|
||||
"error_message": "xce_controller primary sends a rejoining standby's snapshot to a different standby\n\n**Observed:** after a standby (ctrl-2) is killed, wiped and rejoins empty, the primary decides a snapshot is needed from ctrl-2's state but the transfer lands on the OTHER, already caught-up standby (ctrl-3). Primary (ctrl-1), xce-1890-nd5:\n```\n[2026-09-29 14:28:20,377] ... on_standby_connected] HA: repl registered late-joiner standby peer[1] (slot 2, localhost:9992)\n[2026-09-29 14:28:44,429] ... ha_process_standby_state] HA: standby[1] converged: config_tag=7302089038923290268 applied_lsn=114 (committed_tag=... committed_lsn=114)\n[2026-09-29 14:28:44,429] ... ha_dispatch_repl_action_for_standby] HA repl: standby[1] lsn=0 < oldest_wal_lsn=112 → requesting snapshot transfer\n[2026-09-29 14:28:44,437] ... ha_send_snapshot_to_standby: snapshot transfer start checkpoint_lsn=114 size=528825\n```\nEvery such transfer (14:28:41, :44, :47, :56) was received and installed by ctrl-3 (`HA: snapshot loaded lsn=114`, 7 installs); ctrl-2 received none. The same standby[1] alternates every heartbeat between `converged ... applied_lsn=114` (ctrl-2's pre-wipe position, or ctrl-3's) and `lsn=0 → requesting snapshot`, and each request is logged twice.\n\n**Expected:** the snapshot is sent on the rejoining standby's own connection, and its status reflects only that live connection.\n**Impact:** a wiped/rejoining standby never catches up while the misrouting persists; the other standby reinstalls the same snapshot every few seconds; ctrlstatus/soak convergence is reported from stale state (the soak printed `cluster reconverged (3-of-3)` and then failed `ctrl-2's log shows NO snapshot install`).\n**Found by:** soak -- xce-test-ha --force-snapshot while verifying bug-1890, 2026-09-29. Suspected: two repl slots for peer[1] after kill+rejoin (the late-joiner slot 2 plus the pre-kill slot, cf. bug-1819/bug-1474), with state read from one slot and the send going to an endpoint that belongs to another peer.\n\nUPDATE (2026-09-29): root-caused -- not duplicate repl slots as suspected, but an index-space mix-up between vote and heartbeat endpoints (see Root cause).",
|
||||
"file": "src/controller/ha.c (repl_ack_decode_and_dispatch), src/controller/config_repl.c (ha_walack_on_ack), src/controller/ha.h (catchup_inflight)",
|
||||
"root_cause": "Two kinds of endpoint deliver heartbeat state reports to the primary. A promoted vote endpoint's vote_ep_ctx_t.peer_idx is RELATIVE to the votes array, which leaves out the primary itself; a late-joiner's heartbeat standby endpoint carries the ABSOLUTE peer index. repl_ack_decode_and_dispatch (ha.c) passed the raw vctx->peer_idx to ha_process_standby_state (which stores ha->standby_reported_tag/lsn[peer_idx]) and ha_dispatch_repl_action_for_standby (which reads those back and acts on the endpoint the report arrived on). The WAL-ack branch beside it already remapped with ha_repl_ack_abs_peer_idx; the state-report branch did not. With ctrl-1 primary (self 0), ctrl-3's vote endpoint (relative 1) and the rejoined ctrl-2's heartbeat endpoint (absolute 1) shared slot 1: their handlers interleaved, one read the other's position and acted on its own endpoint. ctrl-3's handler read ctrl-2's lsn=0 and sent the snapshot over ctrl-3's connection (hence the duplicated `requesting snapshot transfer` lines and the alternating `converged ... applied_lsn=114` for standby[1]). ha_walack_on_ack also received the raw index, so catchup_inflight[] single-flight flags could collide the same way.",
|
||||
"fix": "src/controller/ha.c: the state-report branch of repl_ack_decode_and_dispatch resolves the absolute index with ha_repl_ack_abs_peer_idx(ha, vctx->ctx != NULL, vctx->peer_idx) before recording, deciding and sending, and ha_walack_on_ack gets the already-resolved absolute index. src/controller/ha.h + config_repl.c: catchup_inflight[] is sized MAX_HA_CANDIDATES (was MAX_STANDBYS=3) and its four bounds checks updated, so every absolute index fits (a 4-candidate cluster's peer at absolute 3 would otherwise be rejected). Each standby's state now has its own slot, so the snapshot decision and the send are for the same standby. Test seam ha_repl_ack_dispatch_for_test (XCE_TESTING) drives the dispatcher.\n\nVerification:\n- Test: test_vote_ep_report_lands_on_its_absolute_index in src/controller/testsuite/test_standby_state_peer_idx.c sends a real encoded state report through repl_ack_decode_and_dispatch on a promoted vote endpoint with relative index 1 (primary at 0): RED before the fix (`Expected 5 Was 777. bug-1891: peer 2's state report was not recorded under peer 2`), GREEN after; the heartbeat-endpoint baseline passes both ways\n- Suites: controller 1258/1258, asan, no sanitizer errors\n- Live: xce-test-ha --force-snapshot, 16 runs (2026-09-29, xce-1891-fx1..16): 16/16 PASS and 0 snapshots installed on a non-target node after the target rejoined -- versus misrouted installs in 25 of 48 runs before the fix (xce-1871-fs/-fix, xce-1890-nd). xce-test-ha --sequential 6 rounds (xce-1891-seq2): PASS, all 3 nodes led, zero job loss, 6 worker-resync jobs reconciled, replay parity 7 files 0 mismatches",
|
||||
"tags": [
|
||||
"ha",
|
||||
"snapshot",
|
||||
|
|
@ -16501,7 +16501,9 @@
|
|||
"bug-1819",
|
||||
"bug-1474"
|
||||
],
|
||||
"fix_commits": [],
|
||||
"fix_commits": [
|
||||
"4922f6c8"
|
||||
],
|
||||
"record": ".wolf/bugs/bug-1891.md",
|
||||
"gitea_issue": 337,
|
||||
"gitea_synced_status": "open"
|
||||
|
|
|
|||
|
|
@ -1,16 +1,17 @@
|
|||
---
|
||||
id: "bug-1891"
|
||||
status: "open"
|
||||
status: "fixed"
|
||||
status_updated: "2026-09-29"
|
||||
status_note: "newly logged"
|
||||
status_note: ""
|
||||
component: "controller"
|
||||
severity: "hang"
|
||||
timestamp: "2026-09-29T14:33:30Z"
|
||||
last_seen: "2026-09-29T14:33:30Z"
|
||||
occurrences: 1
|
||||
files: ["src/controller/ha.c (ha_dispatch_repl_action_for_standby)", "src/controller/config_repl.c (ha_send_snapshot_to_standby)"]
|
||||
files: ["src/controller/ha.c (repl_ack_decode_and_dispatch)", "src/controller/config_repl.c (ha_walack_on_ack)", "src/controller/ha.h (catchup_inflight)"]
|
||||
tags: ["ha", "snapshot", "standby", "repl", "soak"]
|
||||
related: ["bug-1871", "bug-1819", "bug-1474"]
|
||||
fix_commits: ["4922f6c8"]
|
||||
gitea_issue: 337
|
||||
gitea_synced_status: "open"
|
||||
gitea_synced_hash: "4dfc80c73e64"
|
||||
|
|
@ -32,6 +33,8 @@ Every such transfer (14:28:41, :44, :47, :56) was received and installed by ctrl
|
|||
**Impact:** a wiped/rejoining standby never catches up while the misrouting persists; the other standby reinstalls the same snapshot every few seconds; ctrlstatus/soak convergence is reported from stale state (the soak printed `cluster reconverged (3-of-3)` and then failed `ctrl-2's log shows NO snapshot install`).
|
||||
**Found by:** soak -- xce-test-ha --force-snapshot while verifying bug-1890, 2026-09-29. Suspected: two repl slots for peer[1] after kill+rejoin (the late-joiner slot 2 plus the pre-kill slot, cf. bug-1819/bug-1474), with state read from one slot and the send going to an endpoint that belongs to another peer.
|
||||
|
||||
UPDATE (2026-09-29): root-caused -- not duplicate repl slots as suspected, but an index-space mix-up between vote and heartbeat endpoints (see Root cause).
|
||||
|
||||
## 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)
|
||||
|
|
@ -47,15 +50,17 @@ Every such transfer (14:28:41, :44, :47, :56) was received and installed by ctrl
|
|||
- Evidence: /home/claude/tmp/xce-1890-nd5 (failing run, logs/ctrl-*.log, ../xce-1890-nd5.out), /home/claude/tmp/xce-1871-fs16
|
||||
|
||||
## Root cause
|
||||
TODO: required for fixed/partial
|
||||
Two kinds of endpoint deliver heartbeat state reports to the primary. A promoted vote endpoint's vote_ep_ctx_t.peer_idx is RELATIVE to the votes array, which leaves out the primary itself; a late-joiner's heartbeat standby endpoint carries the ABSOLUTE peer index. repl_ack_decode_and_dispatch (ha.c) passed the raw vctx->peer_idx to ha_process_standby_state (which stores ha->standby_reported_tag/lsn[peer_idx]) and ha_dispatch_repl_action_for_standby (which reads those back and acts on the endpoint the report arrived on). The WAL-ack branch beside it already remapped with ha_repl_ack_abs_peer_idx; the state-report branch did not. With ctrl-1 primary (self 0), ctrl-3's vote endpoint (relative 1) and the rejoined ctrl-2's heartbeat endpoint (absolute 1) shared slot 1: their handlers interleaved, one read the other's position and acted on its own endpoint. ctrl-3's handler read ctrl-2's lsn=0 and sent the snapshot over ctrl-3's connection (hence the duplicated `requesting snapshot transfer` lines and the alternating `converged ... applied_lsn=114` for standby[1]). ha_walack_on_ack also received the raw index, so catchup_inflight[] single-flight flags could collide the same way.
|
||||
|
||||
## Fix
|
||||
TODO: required for fixed/partial
|
||||
src/controller/ha.c: the state-report branch of repl_ack_decode_and_dispatch resolves the absolute index with ha_repl_ack_abs_peer_idx(ha, vctx->ctx != NULL, vctx->peer_idx) before recording, deciding and sending, and ha_walack_on_ack gets the already-resolved absolute index. src/controller/ha.h + config_repl.c: catchup_inflight[] is sized MAX_HA_CANDIDATES (was MAX_STANDBYS=3) and its four bounds checks updated, so every absolute index fits (a 4-candidate cluster's peer at absolute 3 would otherwise be rejected). Each standby's state now has its own slot, so the snapshot decision and the send are for the same standby. Test seam ha_repl_ack_dispatch_for_test (XCE_TESTING) drives the dispatcher.
|
||||
|
||||
## 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_vote_ep_report_lands_on_its_absolute_index in src/controller/testsuite/test_standby_state_peer_idx.c sends a real encoded state report through repl_ack_decode_and_dispatch on a promoted vote endpoint with relative index 1 (primary at 0): RED before the fix (`Expected 5 Was 777. bug-1891: peer 2's state report was not recorded under peer 2`), GREEN after; the heartbeat-endpoint baseline passes both ways
|
||||
- Suites: controller 1258/1258, asan, no sanitizer errors
|
||||
- Live: xce-test-ha --force-snapshot, 16 runs (2026-09-29, xce-1891-fx1..16): 16/16 PASS and 0 snapshots installed on a non-target node after the target rejoined -- versus misrouted installs in 25 of 48 runs before the fix (xce-1871-fs/-fix, xce-1890-nd). xce-test-ha --sequential 6 rounds (xce-1891-seq2): PASS, all 3 nodes led, zero job loss, 6 worker-resync jobs reconciled, replay parity 7 files 0 mismatches
|
||||
|
||||
## References
|
||||
- Related: none
|
||||
- Fix commit: 4922f6c8
|
||||
- Related: bug-1871, bug-1890 (found while verifying it), bug-1819
|
||||
- Gitea: #337
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue