diff --git a/src/controller/ha.c b/src/controller/ha.c index 092c8d3f..928fbf80 100644 --- a/src/controller/ha.c +++ b/src/controller/ha.c @@ -8585,6 +8585,18 @@ void ha_on_primary_ctrl_fd_rdhup(ha_state_t *ha, cluster_t *c) "failover (5.10b: a sustained RDHUP cadence must not ladder the " "term; the in-flight election's own jittered retry handles it)", (unsigned long)(now_ms - last), (unsigned long)cooldown_ms); + /* bug-1562: unlike the 5.6 guard above (which only skips re-arming + * when it has VERIFIED an election is still in flight), this branch + * only checks elapsed time -- the earlier round may have already + * concluded (e.g. a lone node's PreVote loses in milliseconds with + * no peers up yet). Without re-arming, a debounced trigger that + * lands after that round's own conclusion drops the ONLY remaining + * retry mechanism, freezing the node in CTRL_STANDBY forever with + * no timer ever scheduled again. ha_arm_heartbeat_timeout_vtask is + * safe to call with c == NULL (unit-test mode): it still stamps + * ha->last_activity and simply cannot schedule via a live delaymgr, + * mirroring how the rest of this function already treats c == NULL. */ + ha_arm_heartbeat_timeout_vtask(ha, c); return; } } diff --git a/src/controller/persist.c b/src/controller/persist.c index e65ca8f2..91f1d704 100644 --- a/src/controller/persist.c +++ b/src/controller/persist.c @@ -354,6 +354,10 @@ static bool flusher_work_pending_locked(persist_t* p) * durable_lsn (unchanged if there was nothing to sync). */ static uint64_t flusher_flush_once(persist_t* p) { +#ifdef XCE_TESTING + atomic_fetch_add_explicit(&p->test_flusher_flush_attempt_count, 1, + memory_order_relaxed); +#endif pthread_mutex_lock(&p->lock); uint64_t tip = (p->current_lsn > 0) ? p->current_lsn - 1 : 0; @@ -491,6 +495,36 @@ static void* fsync_worker(void* arg) } pthread_mutex_lock(&p->fsync_mutex); + + /* bug-1563: a sustained fdatasync failure leaves durable_lsn < tip + * forever (the fail-loud gate above deliberately never advances it + * on failure — that part is correct and unchanged). flusher_work_ + * pending_locked() can therefore never distinguish "genuine fresh + * work just landed" from "still stuck from the last failed attempt" + * — both read as pending=true, so without this check the loop above + * would skip the wait on EVERY iteration and spin flusher_flush_once + * (and thus fdatasync) as fast as the CPU/lock allow. Live evidence: + * a 40-round chaotic /xce-test-ha soak hit 300k+ failed attempts on + * one node in well under a minute (one core pinned, log flooded). + * Only skip the wait when the flush actually made progress (pending + * was true and it succeeded) or there was nothing pending to begin + * with (the pre-existing, correct fast path); a flush that was + * pending but made no progress (after == before) still waits out the + * normal wal_sync_ms cadence before retrying — same bounded-latency + * budget the idle path already uses, no new tunable needed. */ + if (pending && after == before && + !atomic_load_explicit(&p->fsync_stop, memory_order_acquire)) { + long ms = (long)p->config.wal_sync_ms; + struct timespec dl; + clock_gettime(CLOCK_REALTIME, &dl); + dl.tv_sec += ms / 1000; + dl.tv_nsec += (ms % 1000) * 1000000L; + if (dl.tv_nsec >= 1000000000L) { + dl.tv_sec += 1; + dl.tv_nsec -= 1000000000L; + } + pthread_cond_timedwait(&p->fsync_cond, &p->fsync_mutex, &dl); + } } pthread_mutex_unlock(&p->fsync_mutex); return NULL; diff --git a/src/controller/testsuite/test_ha_rdhup_integration.c b/src/controller/testsuite/test_ha_rdhup_integration.c index e1999936..eadad4d7 100644 --- a/src/controller/testsuite/test_ha_rdhup_integration.c +++ b/src/controller/testsuite/test_ha_rdhup_integration.c @@ -642,11 +642,83 @@ static void test_rdhup_within_cooldown_is_debounced(void) printf("test_rdhup_within_cooldown_is_debounced: PASS\n"); } +/* ═══════════════════════════════════════════════════════════════════════════ + * Test: a debounced RDHUP must still re-arm the liveness watchdog (bug-1562) + * + * The 5.10b debounce branch (sibling test above) correctly suppresses a + * fresh failover attempt when an RDHUP lands within the cooldown window. But + * unlike the 5.6 guard right above it in the function (which only skips + * re-arming when it has VERIFIED an election is actually in flight, + * role==CTRL_ELECTING || pre_vote_in_progress), the 5.10b branch only checks + * elapsed time since last_failover_ms -- it never checks whether an election + * is still running. On a lone cold-booting node, the first PreVote round + * loses within milliseconds (no peers reachable yet -> connect failures + * count as "no" votes), which re-arms the watchdog once. When that watchdog + * fires again ~heartbeat_timeout_ms later, last_failover_ms is still inside + * the 2x-election_timeout cooldown even though no election is in flight + * anymore -- so pre-fix, the debounce branch returns without re-arming + * anything. That is the LAST timer ever scheduled in the process: a live + * repro (matching a real user's failed 3-node deploy exactly) confirmed + * every vtask worker thread idling on an empty queue and the io_worker + * parked in epoll_wait with zero pending connections, 9+ minutes of total + * silence -- the node is permanently stuck CTRL_STANDBY, and since it is the + * only node holding a local config, the whole cluster never elects a + * primary. + * + * ha_arm_heartbeat_timeout_vtask stamps ha->last_activity to "now" as its + * first, delaymgr-independent side effect (ha.c) -- the same observable + * test_ha_arm_no_crash_no_thread (test_ha_liveness.c) already uses to prove + * arming happened without a live delaymgr thread (c == NULL here). + * ═════════════════════════════════════════════════════════════════════════ */ +static void test_rdhup_debounce_still_rearms_liveness_watchdog(void) +{ + ha_state_t ha; + TEST_ASSERT_EQUAL_INT(0, ha_init(&ha, &g_cfg, 0)); + ha_do_demote(&ha); /* role = CTRL_STANDBY */ + + /* Sentinel the debounce branch itself never writes -- a change proves + * ha_arm_heartbeat_timeout_vtask actually ran. */ + ha.last_activity = 1; + + /* A failover was triggered "just now" -> this RDHUP lands inside the + * cooldown window and must be debounced (mirrors the sibling test). */ + struct timespec ts; + clock_gettime(CLOCK_MONOTONIC, &ts); + uint64_t now_ms = (uint64_t)ts.tv_sec * 1000u + (uint64_t)(ts.tv_nsec / 1000000L); + atomic_store_explicit(&ha.last_failover_ms, now_ms, memory_order_release); + + int sv[2]; + TEST_ASSERT_EQUAL_INT(0, socketpair(AF_UNIX, SOCK_STREAM, 0, sv)); + ha.primary_ctrl_fd = sv[0]; + + ha_on_primary_ctrl_fd_rdhup(&ha, NULL); + close(sv[1]); + + /* Still debounced -- no fresh failover, stays CTRL_STANDBY (same + * guarantee as the sibling test). */ + TEST_ASSERT_EQUAL_INT_MESSAGE((int)CTRL_STANDBY, + (int)atomic_load_explicit(&ha.role, memory_order_acquire), + "a debounced RDHUP must not itself trigger a fresh failover"); + + /* The watchdog must have been re-armed even though this trigger was + * debounced -- last_activity must have moved off the sentinel. */ + TEST_ASSERT_TRUE_MESSAGE((int)ha.last_activity != 1, + "a debounced RDHUP must still re-arm the liveness watchdog (bug-1562) " + "-- otherwise a lone node whose first PreVote loses fast then hits a " + "second liveness timeout inside the cooldown window freezes forever, " + "with no timer ever scheduled again"); + + ha_disarm_heartbeat_timeout_vtask(&ha); + ha_fini(&ha); + printf("test_rdhup_debounce_still_rearms_liveness_watchdog: PASS\n"); +} + void test_ha_rdhup_integration(void) { UnitySetTestFile(__FILE__); RUN_TEST(test_rdhup_candidate_advertises_freshness_floor_not_stale_committed); RUN_TEST(test_rdhup_within_cooldown_is_debounced); + RUN_TEST(test_rdhup_debounce_still_rearms_liveness_watchdog); RUN_TEST(test_rdhup_full_path_reaches_primary); /* ack-driven promotion test deleted (ha-single-leader-role 4.1: * ack-driven promotion machinery removed, no shim) */ diff --git a/src/controller/testsuite/test_term_safety_adapter.c b/src/controller/testsuite/test_term_safety_adapter.c index d241218c..972a2ff1 100644 --- a/src/controller/testsuite/test_term_safety_adapter.c +++ b/src/controller/testsuite/test_term_safety_adapter.c @@ -2340,6 +2340,82 @@ static void test_every_callback_and_marker_path_end_to_end(void) printf("test_every_callback_and_marker_path_end_to_end: PASS\n"); } +/* ================================================================== */ +/* bug-1563 — fsync_worker must back off on a sustained fdatasync fail */ +/* ================================================================== */ + +/* + * Live 40-round chaotic /xce-test-ha soak evidence: a freshly-promoted + * primary's local fdatasync started failing (errno=22) and never recovered. + * flusher_work_pending_locked() (durable_lsn < tip) stays true forever once + * fdatasync starts failing -- the fail-loud gate in flusher_flush_once() + * deliberately never advances durable_lsn on failure (that part is correct + * and unchanged). But fsync_worker's loop only waits (pthread_cond_timedwait) + * when NOT pending -- "pending" looks identical whether it means "genuine + * fresh work just landed" or "still stuck from last attempt", so a sustained + * failure makes the loop skip the wait every single iteration and spin + * flusher_flush_once() as fast as the CPU/lock allow: the live soak hit + * 300k+ failed attempts in well under a minute on one node (one core pinned, + * log flooded). This test reproduces the mechanism directly (force every + * fdatasync to fail via the existing test_force_fsync_fail seam, on a + * PRIMARY so the entry's only sync path is the async flusher under test -- + * a standby's on_persist_entry does its own separate inline persist-before- + * ACK sync, see test_on_persist_entry_failure_propagates_no_ack) and asserts + * the attempt count over a fixed wall-clock window stays close to the + * wal_sync_ms cadence, not an unbounded spin. + */ +static void test_flusher_backs_off_on_sustained_fsync_failure(void) +{ + char tmp[256]; + strcpy(tmp, "/tmp/xce_ts_flusher_backoff_XXXXXX"); + TEST_ASSERT_NOT_NULL(mkdtemp(tmp)); + + cluster_t* c = calloc(1, sizeof(cluster_t)); + TEST_ASSERT_NOT_NULL(c); + + persist_config_t cfg = persist_config_defaults(); + cfg.wal_sync_ms = 20; /* short cadence so backoff is observable quickly */ + cfg.snap_keep_n = 2; + + persist_set_workdir(&c->persist, tmp, "ctrl-test"); + TEST_ASSERT_EQUAL_INT(0, persist_init(&c->persist, &cfg, c)); + TEST_ASSERT_EQUAL_INT(0, persist_start(&c->persist)); + c->ha.raft_c = c; + atomic_store(&c->ha.role, CTRL_PRIMARY); + + /* Force every fdatasync to fail BEFORE appending, so the entry created + * below is genuinely pending/undurable for the entire observation + * window -- the async fsync_worker thread is the only thing that could + * ever sync it. */ + atomic_store(&c->persist.test_force_fsync_fail, 1); + + uint8_t blob[64]; + size_t n = pack_entry(blob, WAL_JOB_UPDATE, "y", 1); + TEST_ASSERT_EQUAL_INT(0, + ha_cb_persist_entry_for_test(&c->ha, /*index*/1, /*term*/1, blob, n)); + + struct timespec ts = { .tv_sec = 0, .tv_nsec = 300 * 1000 * 1000L }; + nanosleep(&ts, NULL); + + unsigned attempts = + atomic_load(&c->persist.test_flusher_flush_attempt_count); + + atomic_store(&c->persist.test_force_fsync_fail, 0); + teardown_cluster(c); + + /* 300ms / 20ms cadence -> ~15 attempts expected once backed off; a + * generous upper bound absorbs scheduling jitter without being loose + * enough to miss a genuine busy-spin (pre-fix: thousands of attempts in + * the same window). */ + TEST_ASSERT_TRUE_MESSAGE(attempts < 60, + "fsync_worker must back off between failed fdatasync attempts " + "(bug-1563) -- a sustained sync failure must not spin the flusher " + "thread at full CPU with zero delay between retries"); + + printf("test_flusher_backs_off_on_sustained_fsync_failure: PASS " + "(attempts=%u)\n", attempts); +} + /* ------------------------------------------------------------------ */ /* Suite entry point */ /* ------------------------------------------------------------------ */ @@ -2355,6 +2431,7 @@ void test_term_safety_adapter(void) RUN_TEST(test_on_persist_entry_stamps_term_standby); RUN_TEST(test_on_persist_entry_stamps_term_primary); RUN_TEST(test_on_persist_entry_failure_propagates_no_ack); + RUN_TEST(test_flusher_backs_off_on_sustained_fsync_failure); RUN_TEST(test_on_get_entry_term_present_legacy_absent); RUN_TEST(test_on_truncate_from_drops_suffix); RUN_TEST(test_on_truncate_from_removes_all); diff --git a/src/include/persist.h b/src/include/persist.h index 38581342..ec8d7d62 100644 --- a/src/include/persist.h +++ b/src/include/persist.h @@ -536,6 +536,13 @@ struct persist_s { * must NOT advance and the failure is logged loudly. Compiled out of * production (xce_controller is built without -DXCE_TESTING). */ atomic_int test_force_fsync_fail; + /* Flusher attempt counter (bug-1563): incremented once per + * flusher_flush_once() invocation, regardless of outcome. A sustained + * fdatasync failure must not spin the async fsync_worker thread at full + * CPU with zero backoff between retries -- this proves attempt rate + * stays bounded to roughly the wal_sync_ms cadence even while durable_lsn + * is stuck. Compiled out of production. */ + atomic_uint test_flusher_flush_attempt_count; /* fdatasync observability counter (ha-commit-durability task 2.3): * incremented at the standby-path inline sync in * persist_wal_write_replicated, BEFORE that function returns (and thus