diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 47254627..7b6b5aeb 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -16088,9 +16088,9 @@ }, { "id": "bug-1878", - "status": "open", + "status": "fixed", "status_updated": "2026-09-28", - "status_note": "logged 2026-09-28; reproduced locally; fix not started", + "status_note": "", "component": "controller", "severity": "wrong-result", "timestamp": "2026-09-28T07:11:38Z", @@ -16099,7 +16099,7 @@ "error_message": "ctrlstatus reports appliedLsn 0 on the primary (standby-only counter)\n\n**Observed:**\n```\nxce/client>ctrlstatus\nPrimary: ctrl-1\n...\nanswered by ctrl-1 (primary)\nterm: 2\ncommittedLsn: 4900\nappliedLsn: 0\n```\n(pc13v, 2026-09-28 14:56; locally: committedLsn 2, appliedLsn 0)\n**Expected:** the primary's real apply position, next to its committed position.\n**Impact:** every primary's ctrlstatus says it has applied nothing, which reads like a stalled apply pump; operators and scripts comparing applied vs committed get a false alarm. The data path itself is fine.\n**Found by:** user running xce_test ctrlstatus on pc13v after the bug-1872..1877 retest", "file": "src/controller/ctrlstatus.c", "root_cause": "ctrlstatus_fill() (src/controller/ctrlstatus.c:178) sets appliedLsn from ha->applied_lsn for every role. That counter (ha.h:161, \"Standby: last applied WAL LSN\") is only advanced when a standby applies replicated entries; ha_init() zeroes it and nothing advances it on a primary. The primary's apply cursor is persist->last_applied_lsn, which ctrlstatus never reads. The two use different conventions: ha->applied_lsn is the NEXT lsn to apply (entry->lsn+1, ha.h:969), persist->last_applied_lsn the last applied entry -- a fix has to report one convention for both roles.", - "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", + "fix": "ctrlstatus_fill() (src/controller/ctrlstatus.c) reports a primary's appliedLsn from persist->last_applied_lsn (the last entry applied, never above committedLsn); a standby still reports ha->applied_lsn, as the spec defines. The existing primary fixture set ha.applied_lsn=42 on a primary, a state that never occurs live -- it now uses persist.last_applied_lsn. The controller-status design doc's \"already correct in every role\" note is corrected.\n\nVerification:\n- Test: test_ctrlstatus_primary_reports_its_apply_cursor in src/controller/testsuite/test_ctrlstatus.c (pc13v's values): RED before the fix (Expected 4900 Was 0), GREEN after\n- Suites: controller suite 1256/0 (asan); test_ha_failover_prevote 11/0, test_ha_liveness 38/0, test_ha_failover 8/0, test_ctrlstatus 23/0\n- Live: HA soaks on aa7fc65a's tree: sequential 6 rounds PASS (21 jobs, zero job loss, all 3 nodes led); chaotic 6 rounds PASS (zero committed divergence, zero committed job loss); pc13v retest pending; ctrlstatus on the soak clusters not captured separately", "tags": [ "controller", "ctrlstatus", @@ -16109,14 +16109,16 @@ "related_bugs": [ "bug-1819" ], - "fix_commits": [], + "fix_commits": [ + "aa7fc65a" + ], "record": ".wolf/bugs/bug-1878.md" }, { "id": "bug-1879", - "status": "open", + "status": "fixed", "status_updated": "2026-09-28", - "status_note": "logged 2026-09-28; reproduced locally; fix not started", + "status_note": "", "component": "controller", "severity": "hang", "timestamp": "2026-09-28T07:11:39Z", @@ -16124,8 +16126,8 @@ "occurrences": 1, "error_message": "fresh HA cluster has no primary for ~10 s: first election lost, not retried until liveness timeout\n\n**Observed:**\n```\n[14:47:32,960] ctrl-1 HA FSM: -> CTRL_ELECTING (async, n_peers=3)\n[14:47:32,962] ctrl-1 HA FSM (raft): -> CTRL_STANDBY (term=1, first_boot=1)\n[14:47:32,962] ctrl-1 myapp_run: CTRL_STANDBY — waiting for primary to connect and push config\n[14:47:44,368] ctrl-1 WARN liveness_poll_fn: HA: liveness poll: no primary activity for 11s (timeout=10s) -> failover\n[14:47:44,661] ctrl-1 HA FSM (raft): -> CTRL_PRIMARY (term=2, first_boot=0)\n```\n(pc13v; locally ctrl-2/ctrl-3 log `ha_start_election_async: no local config (tag=0, n_peers=3) — participating as voter only`)\n**Expected:** a fresh cluster elects its primary as soon as a quorum of nodes is up (about a second with start-all.sh's 0.5-1 s stagger).\n**Impact:** every cold start of an HA cluster has no primary for about 10 s (the standby liveness timeout): no job submission, config push or scheduling in that window, a spurious failover WARN, and the cluster always starts at term 2. Also the cause of the 10 s of standby 'waiting for config' seen in bug-1876.\n**Found by:** user reading ctrl-1's boot log and ctrlstatus (electedTerm 2) on pc13v after the bug-1872..1877 retest", "file": "src/controller/ha.c, src/controller/myapp.c", - "root_cause": "Established from both runs: ctrl-1, the only node with a local config, starts its term-1 election before its peers are running, cannot reach a quorum, and drops to CTRL_STANDBY (\"waiting for primary\") within ~50 ms. ctrl-2 and ctrl-3 have no local config, so ha_start_election_async() makes them voters only -- they never stand. That is by design (confirmed by the user, 2026-09-28): on a cold boot only the node holding the initial configuration (ctrl-1) may become primary, so the retry has to come from ctrl-1. Nothing starts another election until ctrl-1's standby liveness poll (10 s) treats the missing primary as a failure and runs PreVote, which it then wins at once.\n\nUnconfirmed: why the lost first-boot election leaves ctrl-1 in CTRL_STANDBY with only the 10 s liveness poll as a retry, instead of retrying after a short (randomized) election timeout as Raft does for a candidate that fails to win -- to be read in ha.c's raft_cb_become_follower()/first_boot path and myapp_run().", - "fix": "Proposed: when the config-holding node loses its first-boot election for lack of quorum, keep it a candidate and retry its own election after a short randomized election timeout (well under the 10 s standby liveness timeout) until it wins or another primary appears -- instead of settling into CTRL_STANDBY with only the liveness poll as a retry. Nodes without a config stay voters only.\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": "Established from both runs: ctrl-1, the only node with a local config, starts its term-1 election before its peers are running, cannot reach a quorum, and drops to CTRL_STANDBY (\"waiting for primary\") within ~50 ms. ctrl-2 and ctrl-3 have no local config, so ha_start_election_async() makes them voters only -- they never stand. That is by design (confirmed by the user, 2026-09-28): on a cold boot only the node holding the initial configuration (ctrl-1) may become primary, so the retry has to come from ctrl-1. Nothing starts another election until ctrl-1's standby liveness poll (10 s) treats the missing primary as a failure and runs PreVote, which it then wins at once.\n\nConfirmed: why the lost first-boot election leaves ctrl-1 in CTRL_STANDBY with only the 10 s liveness poll as a retry, instead of retrying after a short (randomized) election timeout as Raft does for a candidate that fails to win -- to be read in ha.c's raft_cb_become_follower()/first_boot path and myapp_run().\n\nConfirmed in the code: vote_reply_dispatch() counts a connect failure as a \"no\" vote (bug-1423), so with both peers down the raft library's all-replied-no-quorum step (raft.c Step 6) makes ctrl-1 a follower within ~50 ms; raft_cb_become_follower() only arms the standby liveness watchdog (heartbeat_timeout_ms, 10 s). A second defect blocked a faster retry: ha_heartbeat_is_fresh() treats last_activity -- which ha_arm_heartbeat_timeout_vtask() sets to the arm time -- as primary contact, so the failover gates believed a primary was alive.", + "fix": "ha_note_leaderless() (ha.c) marks a config-holding node that becomes a follower with no leader known. While marked, the liveness poll retries the election through the existing PreVote failover after HA_LEADERLESS_RETRY_MS (1 s), doubling up to heartbeat_timeout_ms, and polls no slower than the pending retry; ha_heartbeat_is_fresh() reports \"not fresh\" (no primary heard from yet). ha_on_heartbeat_received() and raft_cb_become_leader() clear it. Config-less nodes stay voters only, as designed.\n\nVerification:\n- Test: test_leaderless_follower_retries_election_after_short_delay, test_leaderless_retry_waits_for_its_delay, test_leaderless_retry_backoff_is_capped, test_primary_contact_clears_leaderless and test_only_a_config_holder_without_leader_is_leaderless in src/controller/testsuite/test_ha_failover_prevote.c (new behaviour; the first one also caught the freshness-gate defect)\n- Suites: controller suite 1256/0 (asan); test_ha_failover_prevote 11/0, test_ha_liveness 38/0, test_ha_failover 8/0, test_ctrlstatus 23/0\n- Live: local cold start 2026-09-28 07:23:58: ctrl-1 lost its first election at .476, retried after 1381 ms, CTRL_PRIMARY at 07:24:00.152 (1.7 s after start; ~10 s before). HA soaks on aa7fc65a's tree: sequential 6 rounds PASS (21 jobs, zero job loss, all 3 nodes led); chaotic 6 rounds PASS (zero committed divergence, zero committed job loss); pc13v retest pending; both soaks' cold starts reached a primary in 1.7 s", "tags": [ "controller", "ha", @@ -16136,7 +16138,9 @@ "bug-1876", "bug-606" ], - "fix_commits": [], + "fix_commits": [ + "aa7fc65a" + ], "record": ".wolf/bugs/bug-1879.md" }, { diff --git a/.wolf/bugs/bug-1878.md b/.wolf/bugs/bug-1878.md index 856537d6..8ccfb5b4 100644 --- a/.wolf/bugs/bug-1878.md +++ b/.wolf/bugs/bug-1878.md @@ -1,8 +1,8 @@ --- id: "bug-1878" -status: "open" +status: "fixed" status_updated: "2026-09-28" -status_note: "logged 2026-09-28; reproduced locally; fix not started" +status_note: "" component: "controller" severity: "wrong-result" timestamp: "2026-09-28T07:11:38Z" @@ -11,6 +11,7 @@ occurrences: 1 files: ["src/controller/ctrlstatus.c"] tags: ["controller", "ctrlstatus", "ha", "display"] related: ["bug-1819"] +fix_commits: ["aa7fc65a"] --- # bug-1878: ctrlstatus reports appliedLsn 0 on the primary (standby-only counter) @@ -49,12 +50,12 @@ appliedLsn: 0 ctrlstatus_fill() (src/controller/ctrlstatus.c:178) sets appliedLsn from ha->applied_lsn for every role. That counter (ha.h:161, "Standby: last applied WAL LSN") is only advanced when a standby applies replicated entries; ha_init() zeroes it and nothing advances it on a primary. The primary's apply cursor is persist->last_applied_lsn, which ctrlstatus never reads. The two use different conventions: ha->applied_lsn is the NEXT lsn to apply (entry->lsn+1, ha.h:969), persist->last_applied_lsn the last applied entry -- a fix has to report one convention for both roles. ## Fix -TODO: required for fixed/partial +ctrlstatus_fill() (src/controller/ctrlstatus.c) reports a primary's appliedLsn from persist->last_applied_lsn (the last entry applied, never above committedLsn); a standby still reports ha->applied_lsn, as the spec defines. The existing primary fixture set ha.applied_lsn=42 on a primary, a state that never occurs live -- it now uses persist.last_applied_lsn. The controller-status design doc's "already correct in every role" note is corrected. ## 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_ctrlstatus_primary_reports_its_apply_cursor in src/controller/testsuite/test_ctrlstatus.c (pc13v's values): RED before the fix (Expected 4900 Was 0), GREEN after +- Suites: controller suite 1256/0 (asan); test_ha_failover_prevote 11/0, test_ha_liveness 38/0, test_ha_failover 8/0, test_ctrlstatus 23/0 +- Live: HA soaks on aa7fc65a's tree: sequential 6 rounds PASS (21 jobs, zero job loss, all 3 nodes led); chaotic 6 rounds PASS (zero committed divergence, zero committed job loss); pc13v retest pending; ctrlstatus on the soak clusters not captured separately ## References - Related: bug-1819 (ctrlstatus_fill stale-slot bug, same function) diff --git a/.wolf/bugs/bug-1879.md b/.wolf/bugs/bug-1879.md index b9f5fd3b..b8a03829 100644 --- a/.wolf/bugs/bug-1879.md +++ b/.wolf/bugs/bug-1879.md @@ -1,8 +1,8 @@ --- id: "bug-1879" -status: "open" +status: "fixed" status_updated: "2026-09-28" -status_note: "logged 2026-09-28; reproduced locally; fix not started" +status_note: "" component: "controller" severity: "hang" timestamp: "2026-09-28T07:11:39Z" @@ -11,6 +11,7 @@ occurrences: 1 files: ["src/controller/ha.c", "src/controller/myapp.c"] tags: ["controller", "ha", "election", "cold-boot"] related: ["bug-1876", "bug-606"] +fix_commits: ["aa7fc65a"] --- # bug-1879: fresh HA cluster has no primary for ~10 s: first election lost, not retried until liveness timeout @@ -47,15 +48,17 @@ related: ["bug-1876", "bug-606"] ## Root cause Established from both runs: ctrl-1, the only node with a local config, starts its term-1 election before its peers are running, cannot reach a quorum, and drops to CTRL_STANDBY ("waiting for primary") within ~50 ms. ctrl-2 and ctrl-3 have no local config, so ha_start_election_async() makes them voters only -- they never stand. That is by design (confirmed by the user, 2026-09-28): on a cold boot only the node holding the initial configuration (ctrl-1) may become primary, so the retry has to come from ctrl-1. Nothing starts another election until ctrl-1's standby liveness poll (10 s) treats the missing primary as a failure and runs PreVote, which it then wins at once. -Unconfirmed: why the lost first-boot election leaves ctrl-1 in CTRL_STANDBY with only the 10 s liveness poll as a retry, instead of retrying after a short (randomized) election timeout as Raft does for a candidate that fails to win -- to be read in ha.c's raft_cb_become_follower()/first_boot path and myapp_run(). +Confirmed: why the lost first-boot election leaves ctrl-1 in CTRL_STANDBY with only the 10 s liveness poll as a retry, instead of retrying after a short (randomized) election timeout as Raft does for a candidate that fails to win -- to be read in ha.c's raft_cb_become_follower()/first_boot path and myapp_run(). + +Confirmed in the code: vote_reply_dispatch() counts a connect failure as a "no" vote (bug-1423), so with both peers down the raft library's all-replied-no-quorum step (raft.c Step 6) makes ctrl-1 a follower within ~50 ms; raft_cb_become_follower() only arms the standby liveness watchdog (heartbeat_timeout_ms, 10 s). A second defect blocked a faster retry: ha_heartbeat_is_fresh() treats last_activity -- which ha_arm_heartbeat_timeout_vtask() sets to the arm time -- as primary contact, so the failover gates believed a primary was alive. ## Fix -Proposed: when the config-holding node loses its first-boot election for lack of quorum, keep it a candidate and retry its own election after a short randomized election timeout (well under the 10 s standby liveness timeout) until it wins or another primary appears -- instead of settling into CTRL_STANDBY with only the liveness poll as a retry. Nodes without a config stay voters only. +ha_note_leaderless() (ha.c) marks a config-holding node that becomes a follower with no leader known. While marked, the liveness poll retries the election through the existing PreVote failover after HA_LEADERLESS_RETRY_MS (1 s), doubling up to heartbeat_timeout_ms, and polls no slower than the pending retry; ha_heartbeat_is_fresh() reports "not fresh" (no primary heard from yet). ha_on_heartbeat_received() and raft_cb_become_leader() clear it. Config-less nodes stay voters only, as designed. ## 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_leaderless_follower_retries_election_after_short_delay, test_leaderless_retry_waits_for_its_delay, test_leaderless_retry_backoff_is_capped, test_primary_contact_clears_leaderless and test_only_a_config_holder_without_leader_is_leaderless in src/controller/testsuite/test_ha_failover_prevote.c (new behaviour; the first one also caught the freshness-gate defect) +- Suites: controller suite 1256/0 (asan); test_ha_failover_prevote 11/0, test_ha_liveness 38/0, test_ha_failover 8/0, test_ctrlstatus 23/0 +- Live: local cold start 2026-09-28 07:23:58: ctrl-1 lost its first election at .476, retried after 1381 ms, CTRL_PRIMARY at 07:24:00.152 (1.7 s after start; ~10 s before). HA soaks on aa7fc65a's tree: sequential 6 rounds PASS (21 jobs, zero job loss, all 3 nodes led); chaotic 6 rounds PASS (zero committed divergence, zero committed job loss); pc13v retest pending; both soaks' cold starts reached a primary in 1.7 s ## References - Related: bug-1876 (the standby 'waiting for config' warnings this caused), bug-606 (PreVote staggering)