From a928f7a79b6eceebd4b82e9e0a4818ea776fcbef Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Tue, 29 Sep 2026 15:13:15 +0000 Subject: [PATCH] chore(buglog): bug-1891 fixed (4922f6c8) Co-Authored-By: Claude Opus 5.5 (1M context) --- .wolf/buglog.json | 16 +++++++++------- .wolf/bugs/bug-1891.md | 23 ++++++++++++++--------- 2 files changed, 23 insertions(+), 16 deletions(-) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index cce607e3..f244d6ea 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -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" diff --git a/.wolf/bugs/bug-1891.md b/.wolf/bugs/bug-1891.md index 527ac089..aeafc8b6 100644 --- a/.wolf/bugs/bug-1891.md +++ b/.wolf/bugs/bug-1891.md @@ -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