fix(ha): close standby election-freeze (bug-1562) + flusher retry storm (bug-1563)
bug-1562: ha_on_primary_ctrl_fd_rdhup's 5.10b debounce branch (ha.c) returned without re-arming the liveness watchdog when a debounced RDHUP landed after the in-flight PreVote round had already concluded (e.g. a lone cold-booting node whose first round loses in milliseconds with no peers up yet). That was the last timer ever scheduled -- the node froze permanently in CTRL_STANDBY, so a 3-node cluster with a long inter-node start stagger could never elect a primary. Root-caused via a live local reproduction matching the reporting user's exact timing (byte-for-byte match of their hung ctrl-1.log), fixed by re-arming the watchdog in that branch (mirroring the function's own 5.2 branch), and confirmed end-to-end: the same scenario now reaches CTRL_PRIMARY and full 3-node config convergence. bug-1563: fsync_worker's retry loop (persist.c) only backs off when no work is pending, but flusher_work_pending_locked() can't distinguish "fresh work just landed" from "still stuck from the last failed fdatasync" -- a sustained sync failure left durable_lsn permanently behind tip, so the loop skipped its wait every iteration and spun fdatasync as fast as the CPU/lock allowed (a 40-round chaotic /xce-test-ha soak hit 300k+ failed attempts on one node in under a minute). Fixed by waiting out the normal wal_sync_ms cadence when a flush was pending but made no progress, leaving the legitimate idle and just-succeeded fast paths untouched. Both fixed via TDD (RED test before the fix, GREEN after) and live-validated by re-running 40-round sequential and chaotic HA soaks end-to-end: both pass cleanly, and the chaotic run's excluded fdatasync-error count dropped from 304,689 to 0. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
parent
f8a4b1e668
commit
846713ab92
5 changed files with 202 additions and 0 deletions
|
|
@ -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;
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
|
|
|
|||
|
|
@ -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) */
|
||||
|
|
|
|||
|
|
@ -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);
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue