From aa7fc65a3611209e6894fd9caaeef6a8af44c208 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Mon, 28 Sep 2026 07:35:45 +0000 Subject: [PATCH] fix(controller): cold start elects in ~1.7 s, not ~10 s; ctrlstatus appliedLsn on the primary (bug-1879, bug-1878) bug-1879: on a fresh HA cluster the config-holding ctrl-1 started its term-1 election before its peers ran; connect failures count as "no" votes (bug-1423), so it lost at once and became a follower with no leader. ctrl-2/ctrl-3 hold no config and are voters only (by design), so nothing retried until ctrl-1's 10 s standby liveness timeout: every cold start had no primary for ~10 s. - ha_note_leaderless() marks a config-holding node that becomes a follower with no leader known; the liveness poll then retries the election (PreVote) after HA_LEADERLESS_RETRY_MS = 1 s, doubling up to heartbeat_timeout_ms. Primary contact or becoming leader clears it. - ha_heartbeat_is_fresh() answers "no" while leaderless: last_activity then only holds the watchdog's arm time, and the failover gates took it for a live primary. Live cold start: primary 1.7 s after the first node started (was ~10 s). bug-1878: ctrlstatus_fill() reported ha->applied_lsn for every role, a standby-only counter a primary never advances, so every primary showed "appliedLsn: 0". A primary now reports persist->last_applied_lsn. The controller-status design doc's "already correct in every role" note is corrected. Tests: 5 new in test_ha_failover_prevote.c, 1 new in test_ctrlstatus.c (RED: expected 4900, was 0); controller suite 1256/0. HA soaks: sequential 6 rounds PASS, chaotic 6 rounds PASS (zero divergence, zero job loss). Co-Authored-By: Claude Opus 5.5 (1M context) --- .kiro/specs/controller-status/design.md | 2 +- src/controller/ctrlstatus.c | 13 +- src/controller/ha.c | 65 ++++++++- src/controller/ha.h | 15 ++ src/controller/testsuite/test_ctrlstatus.c | 34 ++++- .../testsuite/test_ha_failover_prevote.c | 137 ++++++++++++++++++ 6 files changed, 260 insertions(+), 6 deletions(-) diff --git a/.kiro/specs/controller-status/design.md b/.kiro/specs/controller-status/design.md index 01f25c32..9bfcaf2d 100644 --- a/.kiro/specs/controller-status/design.md +++ b/.kiro/specs/controller-status/design.md @@ -273,7 +273,7 @@ No change to `committedLsn @8` / `committedConfigVersion @7` wire shape — Req - **Req 10 (committed sourcing):** replace the unconditional reads at `ctrlstatus.c:108–110,130` with the role-branch above: - `responderRole == CTRL_PRIMARY` → `committedLsn = persist.committed_lsn`, `committedConfigVersion = ha->committed_config_tag` (atomic acquire loads, unchanged). - else → `committedLsn = ha->last_known_committed_lsn` (atomic acquire), `committedConfigVersion = ha->last_known_committed_config_tag` (plain aligned load). - - `appliedLsn` (`ha->applied_lsn`) is unchanged — it is already correct in every role. + - `appliedLsn` (`ha->applied_lsn`) is unchanged here. **Correction (bug-1878, 2026-09-28):** it is *not* correct in every role — `ha->applied_lsn` is a standby-only counter (replicated WAL received/persisted) that a primary never advances, so every primary reported `appliedLsn: 0`. `ctrlstatus_fill` now reports a primary's apply cursor, `persist->last_applied_lsn` (the last entry applied, never above `committedLsn`); a standby still reports `ha->applied_lsn`. - **Req 11 (timestamp):** stamp `st->responder_time_ms` from `clock_gettime(CLOCK_REALTIME)` (`tv_sec*1000 + tv_nsec/1e6`) at the top of the snapshot, before/with the other field loads, so it marks the responder's sample moment. - **Read-only invariant (10.4, 1.2) preserved:** all additions are atomic/aligned loads + a clock read; no HA/persist/config mutation. diff --git a/src/controller/ctrlstatus.c b/src/controller/ctrlstatus.c index 5b093210..4b86abf0 100644 --- a/src/controller/ctrlstatus.c +++ b/src/controller/ctrlstatus.c @@ -175,8 +175,17 @@ void ctrlstatus_fill(cluster_t* c, xce_ctrlstatus_t* st) atomic_load_explicit(&ha->last_known_committed_config_tag, memory_order_acquire); } - st->appliedLsn = atomic_load_explicit(&ha->applied_lsn, - memory_order_acquire); + /* bug-1878: ha->applied_lsn is a standby-only counter (how far + * replicated WAL has been received and persisted); a primary never + * advances it, so every primary reported 0. A primary reports its apply + * cursor instead -- the last entry applied, never above committedLsn. */ + if (st->responderRole == (uint8_t)CTRL_PRIMARY) { + st->appliedLsn = atomic_load_explicit(&c->persist.last_applied_lsn, + memory_order_acquire); + } else { + st->appliedLsn = atomic_load_explicit(&ha->applied_lsn, + memory_order_acquire); + } /* fenced: catch-up OR recovery-unrecoverable (Req 6.3) */ int in_catch_up = atomic_load_explicit(&ha->in_catch_up, diff --git a/src/controller/ha.c b/src/controller/ha.c index 7d63447f..f2136856 100644 --- a/src/controller/ha.c +++ b/src/controller/ha.c @@ -1621,6 +1621,9 @@ loud_fence_no_timer: static void raft_cb_become_leader(void *ctx, uint64_t term) { ha_state_t *ha = (ha_state_t *)ctx; + + /* bug-1879: a leader exists (us) -- no leaderless retry pending */ + atomic_store_explicit(&ha->leaderless, 0, memory_order_release); cluster_t *c = ha->raft_c; /* Cancel any pending election timeout */ @@ -2144,12 +2147,34 @@ static void raft_cb_become_leader(void *ctx, uint64_t term) * calls cluster_init_phase2 on first boot (standbys also need it to * receive config replication push from the new primary). */ +static uint64_t ha_monotonic_ms(void) +{ + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + return (uint64_t)ts.tv_sec * 1000u + (uint64_t)ts.tv_nsec / 1000000u; +} + +/* bug-1879: see ha.h's `leaderless`. Only a node that can lead (holds a + * config) and knows no leader is marked; a config-less node is a voter only + * (ha_start_election_async) and keeps the plain liveness timeout. */ +void ha_note_leaderless(ha_state_t *ha, cluster_t *c, int leader_idx) +{ + if (!ha || leader_idx >= 0 || !c || !c->myconf + || c->myconf->config_version_tag == 0) + return; + if (!atomic_exchange_explicit(&ha->leaderless, 1, memory_order_acq_rel)) + ha->leaderless_retry_ms = HA_LEADERLESS_RETRY_MS; +} + static void raft_cb_become_follower(void *ctx, uint64_t term, int leader_idx) { - (void)leader_idx; ha_state_t *ha = (ha_state_t *)ctx; cluster_t *c = ha->raft_c; + /* bug-1879: a lost election with no leader known is retried soon, not + * after heartbeat_timeout_ms (armed below) */ + ha_note_leaderless(ha, c, leader_idx); + /* Cancel any pending election timeout */ raft_cb_cancel_timeout(ctx); @@ -5423,6 +5448,10 @@ int ha_heartbeat_is_fresh(ha_state_t *ha) time_t last = ha->last_activity; /* time_t load is atomic on LP64 */ if (last == 0) return 0; /* no primary message seen yet */ + /* bug-1879: while leaderless no primary has been heard from at all -- + * last_activity then only holds the watchdog's arm time */ + if (atomic_load_explicit(&ha->leaderless, memory_order_acquire)) + return 0; struct timespec now; clock_gettime(CLOCK_MONOTONIC, &now); long ms = (long)(now.tv_sec - last) * 1000L; @@ -8993,6 +9022,22 @@ static int liveness_poll_fn(void *arg) time_t elapsed = (last > 0) ? (now - last) : 0; uint32_t timeout_s = ha->config.heartbeat_timeout_ms / 1000; + /* bug-1879: a leaderless config-holding node retries the election after + * its (doubling) retry delay instead of the full heartbeat timeout */ + if (atomic_load_explicit(&ha->leaderless, memory_order_acquire)) { + uint64_t waited = ha_monotonic_ms() - ha->leaderless_since_ms; + + if (waited >= ha->leaderless_retry_ms) { + INFO("HA: no primary known after %lums — retrying the election", + (unsigned long)waited); + ha->leaderless_retry_ms *= 2; + if (ha->leaderless_retry_ms > ha->config.heartbeat_timeout_ms) + ha->leaderless_retry_ms = ha->config.heartbeat_timeout_ms; + ha_dispatch_rdhup_failover(ha, c); + return 0; /* failover (PreVote lost -> re-arm) handles the rest */ + } + } + if (last > 0 && (uint32_t)elapsed >= timeout_s) { /* Silence exceeded timeout — trigger failover */ WARN("HA: liveness poll: no primary activity for %lus (timeout=%us) → failover", @@ -9006,6 +9051,10 @@ static int liveness_poll_fn(void *arg) if (c && c->delaymgr.running) { uint32_t poll_ms = ha->config.heartbeat_interval_ms / 2; if (poll_ms < 100) poll_ms = 100; + /* bug-1879: poll no slower than a pending leaderless retry */ + if (atomic_load_explicit(&ha->leaderless, memory_order_acquire) + && ha->leaderless_retry_ms < poll_ms) + poll_ms = ha->leaderless_retry_ms; delay_task_ms(&c->delaymgr, (int)poll_ms, 1, (delay_task_entry_fn_t)liveness_poll_fn, ctx); } @@ -9079,6 +9128,15 @@ void ha_arm_heartbeat_timeout_vtask(ha_state_t *ha, cluster_t *c) uint32_t poll_ms = ha->config.heartbeat_interval_ms / 2; if (poll_ms < 100) poll_ms = 100; + if (atomic_load_explicit(&ha->leaderless, memory_order_acquire)) { + /* bug-1879: no leader known -- poll at the retry delay */ + ha->leaderless_since_ms = ha_monotonic_ms(); + if (ha->leaderless_retry_ms < poll_ms) + poll_ms = ha->leaderless_retry_ms; + INFO("HA: no primary known yet — election retry in %ums", + ha->leaderless_retry_ms); + } + INFO("HA: standby liveness poll armed (timeout=%ums, poll=%ums)", ha->config.heartbeat_timeout_ms, poll_ms); @@ -9138,6 +9196,11 @@ void ha_on_heartbeat_received(ha_state_t *ha) ha->last_activity = ts.tv_sec; tlog(TLOG_DEBUG3, "HA: heartbeat received — last_activity updated to %ld", (long)ts.tv_sec); + /* bug-1879: a primary exists -- back to the plain liveness timeout */ + if (atomic_exchange_explicit(&ha->leaderless, 0, memory_order_acq_rel)) + INFO("HA: primary contact — leaderless election retry stopped"); + ha->leaderless_retry_ms = HA_LEADERLESS_RETRY_MS; + /* ha-prevote task 4.2 (Req 4.2): a fresh primary heartbeat means the leader * is alive — a PreVote round started by a transient blip must be ABANDONED. * Cancel the in-progress round (clear the raft round state + the controller diff --git a/src/controller/ha.h b/src/controller/ha.h index 6178ef50..4709fe0a 100644 --- a/src/controller/ha.h +++ b/src/controller/ha.h @@ -134,6 +134,9 @@ typedef struct { #define HA_DEFAULT_HEARTBEAT_INTERVAL_MS 3000 #define HA_DEFAULT_HEARTBEAT_TIMEOUT_MS 10000 #define HA_DEFAULT_ELECTION_TIMEOUT_MS 5000 +/* bug-1879: first election retry of a leaderless config-holding node; + * doubles per attempt up to heartbeat_timeout_ms */ +#define HA_LEADERLESS_RETRY_MS 1000 #define HA_DEFAULT_PROBE_CONNECT_TIMEOUT_MS 500 /* Log the first connect failure per peer, then every Nth attempt. */ #define HA_CONNECT_LOG_THROTTLE 10 @@ -247,6 +250,16 @@ typedef struct { void *raft_election_timeout_ctx; /* election_timeout_ctx_t* for cancel (task 6.2) */ /* ── New fields added by ha-heartbeat-liveness spec (Task 1.1) ── */ time_t last_activity; /* CLOCK_MONOTONIC seconds of last primary message; 0 = none yet */ + /* bug-1879: set (ha_note_leaderless) when this node, able to lead (it + * holds a config), became a follower without knowing any leader -- e.g. + * its first-boot election lost because its peers were not up yet. The + * liveness poll then retries the election after leaderless_retry_ms + * (measured from leaderless_since_ms, CLOCK_MONOTONIC ms; doubling up to + * heartbeat_timeout_ms) instead of the full heartbeat_timeout_ms. The + * first primary contact (ha_on_heartbeat_received) clears it. */ + _Atomic int leaderless; + uint32_t leaderless_retry_ms; + uint64_t leaderless_since_ms; /* ── New fields added by ha-repl-hardening spec (Task 1.4) ──────── */ uint64_t standby_reported_tag[MAX_HA_CANDIDATES]; /* Last config_tag reported by each standby */ uint64_t standby_reported_lsn[MAX_HA_CANDIDATES]; /* Last applied_lsn reported by each standby */ @@ -956,6 +969,8 @@ int ha_schedule_phase2_retry(cluster_t *c); /* bug-1876: cluster_init_phase2()'s "cluster_config not pushed yet" result * (-EAGAIN) -- the normal cold-boot wait of a standby, retried, not a * failure; callers log it at INFO, everything else at WARN. */ +void ha_note_leaderless(ha_state_t *ha, cluster_t *c, int leader_idx); + static inline int ha_phase2_rc_is_waiting(int rc) { return rc == -EAGAIN; diff --git a/src/controller/testsuite/test_ctrlstatus.c b/src/controller/testsuite/test_ctrlstatus.c index bb8125d9..0834f34f 100644 --- a/src/controller/testsuite/test_ctrlstatus.c +++ b/src/controller/testsuite/test_ctrlstatus.c @@ -90,6 +90,33 @@ static void cs_teardown_cluster(cluster_t* c) /* ── tests ──────────────────────────────────────────────────── */ +/* bug-1878: a primary never advances ha->applied_lsn (a standby-only + * counter: how far replicated WAL has been received), so ctrlstatus showed + * "committedLsn: 4900 / appliedLsn: 0" on every primary. A primary reports + * its apply cursor, persist->last_applied_lsn (the last entry applied). */ +static void test_ctrlstatus_primary_reports_its_apply_cursor(void) +{ + cluster_t c; + myconf_t mc; + cs_setup_cluster(&c, &mc); + + atomic_store_explicit(&c.ha.role, (int32_t)CTRL_PRIMARY, + memory_order_release); + atomic_store_explicit(&c.ha.applied_lsn, 0, memory_order_release); + atomic_store_explicit(&c.persist.committed_lsn, 4900, memory_order_release); + atomic_store_explicit(&c.persist.last_applied_lsn, 4900, + memory_order_release); + + xce_ctrlstatus_t st; + ctrlstatus_fill(&c, &st); + + TEST_ASSERT_EQUAL_UINT64(4900, st.committedLsn); + TEST_ASSERT_EQUAL_UINT64(4900, st.appliedLsn); + TEST_ASSERT_TRUE_MESSAGE(st.appliedLsn <= st.committedLsn, + "a primary applies only committed entries"); + ctrlstatus_free_fields(&st); +} + /* (a) PRIMARY: responderRole==PRIMARY, primaryName==self, peers/version * populated; committed/applied/term reflect the atomics. (Req 2.1, 3.1, 3.2, * 4.1, 4.2, 5.1, 6.1, 6.2, 6.4) */ @@ -102,7 +129,9 @@ static void test_ctrlstatus_primary(void) atomic_store_explicit(&c.ha.role, (int32_t)CTRL_PRIMARY, memory_order_release); atomic_store_explicit(&c.ha.term, 7, memory_order_release); - atomic_store_explicit(&c.ha.applied_lsn, 42, memory_order_release); + /* bug-1878: a primary's applied position is persist.last_applied_lsn; + * ha.applied_lsn (standby-only) is left at the 0 a live primary has */ + atomic_store_explicit(&c.persist.last_applied_lsn, 41, memory_order_release); atomic_store_explicit(&c.ha.committed_config_tag, 0xAABBCCDDEE001122ULL, memory_order_release); atomic_store_explicit(&c.persist.committed_lsn, 41, memory_order_release); @@ -120,7 +149,7 @@ static void test_ctrlstatus_primary(void) TEST_ASSERT_NOT_NULL(st.primaryName); TEST_ASSERT_EQUAL_STRING("ctrlA", st.primaryName); TEST_ASSERT_EQUAL_UINT64(7, st.term); - TEST_ASSERT_EQUAL_UINT64(42, st.appliedLsn); + TEST_ASSERT_EQUAL_UINT64(41, st.appliedLsn); TEST_ASSERT_EQUAL_UINT64(41, st.committedLsn); TEST_ASSERT_EQUAL_UINT64(0xAABBCCDDEE001122ULL, st.configVersion); TEST_ASSERT_EQUAL_UINT64(0xAABBCCDDEE001122ULL, st.committedConfigVersion); @@ -1098,6 +1127,7 @@ void test_ctrlstatus(void) UnitySetTestFile(__FILE__); RUN_TEST(test_ctrlstatus_format_time_ms); RUN_TEST(test_ctrlstatus_primary); + RUN_TEST(test_ctrlstatus_primary_reports_its_apply_cursor); RUN_TEST(test_ctrlstatus_standby_known_primary); RUN_TEST(test_ctrlstatus_unknown_primary); RUN_TEST(test_ctrlstatus_standby_self_vote_is_unknown); diff --git a/src/controller/testsuite/test_ha_failover_prevote.c b/src/controller/testsuite/test_ha_failover_prevote.c index 0ca61197..30b6331c 100644 --- a/src/controller/testsuite/test_ha_failover_prevote.c +++ b/src/controller/testsuite/test_ha_failover_prevote.c @@ -352,6 +352,138 @@ static void test_config_less_node_does_not_start_prevote(void) printf("test_config_less_node_does_not_start_prevote: PASS\n"); } +/* ── bug-1879: cold boot / lost election with no leader known ──────────── */ + +/* + * A config-holding node that loses its first election because its peers are + * not up yet (connect failures count as "no" votes, bug-1423) became a + * follower with nobody to follow, and only the 10 s liveness timeout ever + * retried: every cold start had no primary for ~10 s. Now such a node is + * marked leaderless and the liveness poll retries the election (via PreVote) + * after leaderless_retry_ms, doubling up to heartbeat_timeout_ms. + */ +static uint64_t now_ms(void) +{ + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + return (uint64_t)ts.tv_sec * 1000u + (uint64_t)ts.tv_nsec / 1000000u; +} + +static void test_leaderless_follower_retries_election_after_short_delay(void) +{ + ha_state_t ha; + TEST_ASSERT_EQUAL_INT(0, ha_init(&ha, &g_cfg, 0)); + ha_do_demote(&ha); + make_three_node(&ha); + + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + ha.last_activity = ts.tv_sec; /* the 6 s timeout is far away */ + atomic_store(&ha.leaderless, 1); + ha.leaderless_retry_ms = HA_LEADERLESS_RETRY_MS; + ha.leaderless_since_ms = now_ms() - HA_LEADERLESS_RETRY_MS - 50; + + liveness_poll_ctx_t ctx; + memset(&ctx, 0, sizeof(ctx)); + ctx.ha = &ha; + atomic_init(&ctx.cancelled, 0); + liveness_poll_fn_test_entry(&ctx); + + TEST_ASSERT_EQUAL_INT_MESSAGE(1, ha.raft.pre_vote_in_progress, + "a leaderless config-holding node retries after leaderless_retry_ms"); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(2 * HA_LEADERLESS_RETRY_MS, + ha.leaderless_retry_ms, "the next retry waits twice as long"); + ha_fini(&ha); +} + +static void test_leaderless_retry_waits_for_its_delay(void) +{ + ha_state_t ha; + TEST_ASSERT_EQUAL_INT(0, ha_init(&ha, &g_cfg, 0)); + ha_do_demote(&ha); + make_three_node(&ha); + + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + ha.last_activity = ts.tv_sec; + atomic_store(&ha.leaderless, 1); + ha.leaderless_retry_ms = HA_LEADERLESS_RETRY_MS; + ha.leaderless_since_ms = now_ms() - 100; + + liveness_poll_ctx_t ctx; + memset(&ctx, 0, sizeof(ctx)); + ctx.ha = &ha; + atomic_init(&ctx.cancelled, 0); + liveness_poll_fn_test_entry(&ctx); + + TEST_ASSERT_EQUAL_INT(0, ha.raft.pre_vote_in_progress); + ha_fini(&ha); +} + +static void test_leaderless_retry_backoff_is_capped(void) +{ + ha_state_t ha; + TEST_ASSERT_EQUAL_INT(0, ha_init(&ha, &g_cfg, 0)); + ha_do_demote(&ha); + make_three_node(&ha); + + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + ha.last_activity = ts.tv_sec; + atomic_store(&ha.leaderless, 1); + ha.leaderless_retry_ms = g_cfg.heartbeat_timeout_ms; + ha.leaderless_since_ms = now_ms() - g_cfg.heartbeat_timeout_ms - 50; + + liveness_poll_ctx_t ctx; + memset(&ctx, 0, sizeof(ctx)); + ctx.ha = &ha; + atomic_init(&ctx.cancelled, 0); + liveness_poll_fn_test_entry(&ctx); + + TEST_ASSERT_EQUAL_UINT32(g_cfg.heartbeat_timeout_ms, ha.leaderless_retry_ms); + ha_fini(&ha); +} + +static void test_primary_contact_clears_leaderless(void) +{ + ha_state_t ha; + TEST_ASSERT_EQUAL_INT(0, ha_init(&ha, &g_cfg, 0)); + ha_do_demote(&ha); + atomic_store(&ha.leaderless, 1); + ha.leaderless_retry_ms = 4 * HA_LEADERLESS_RETRY_MS; + + ha_on_heartbeat_received(&ha); + + TEST_ASSERT_EQUAL_INT(0, atomic_load(&ha.leaderless)); + TEST_ASSERT_EQUAL_UINT32(HA_LEADERLESS_RETRY_MS, ha.leaderless_retry_ms); + ha_fini(&ha); +} + +static void test_only_a_config_holder_without_leader_is_leaderless(void) +{ + ha_state_t ha; + cluster_t c; + myconf_t conf; + + TEST_ASSERT_EQUAL_INT(0, ha_init(&ha, &g_cfg, 0)); + memset(&c, 0, sizeof(c)); + memset(&conf, 0, sizeof(conf)); + c.myconf = &conf; + + conf.config_version_tag = 0; /* voter only */ + ha_note_leaderless(&ha, &c, -1); + TEST_ASSERT_EQUAL_INT(0, atomic_load(&ha.leaderless)); + + conf.config_version_tag = 0x1234; /* can lead, leader known */ + ha_note_leaderless(&ha, &c, 1); + TEST_ASSERT_EQUAL_INT(0, atomic_load(&ha.leaderless)); + + ha_note_leaderless(&ha, &c, -1); /* can lead, no leader */ + TEST_ASSERT_EQUAL_INT(1, atomic_load(&ha.leaderless)); + TEST_ASSERT_EQUAL_UINT32(HA_LEADERLESS_RETRY_MS, ha.leaderless_retry_ms); + ha_fini(&ha); +} + /* ── Suite entry point ──────────────────────────────────────────────────── */ void test_ha_failover_prevote(void) @@ -367,6 +499,11 @@ void test_ha_failover_prevote(void) RUN_TEST(test_heartbeat_without_round_is_plain_noop); RUN_TEST(test_failover_prevote_win_reaches_real_election); RUN_TEST(test_config_less_node_does_not_start_prevote); + RUN_TEST(test_leaderless_follower_retries_election_after_short_delay); + RUN_TEST(test_leaderless_retry_waits_for_its_delay); + RUN_TEST(test_leaderless_retry_backoff_is_capped); + RUN_TEST(test_primary_contact_clears_leaderless); + RUN_TEST(test_only_a_config_holder_without_leader_is_leaderless); ha_prevote_rearm_liveness_hook = NULL; }