diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 763f483a..f2de7c11 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -14163,34 +14163,36 @@ "error_message": "Live config-upgrade-snapshot task 8.6 soak (run-ha-soak.sh --config-upgrade ~/tmp/xce-ha-configupgrade), run on top of bug-1475's already-fixed and already-built-in commit ce8df990 (confirmed via binary mtime 08:16:27 postdating ce8df990 04:48:53Z and b08e392e 08:13:54Z, plus `strings` matching TERM_INDEX_UNSET/persist_durable_floor), FAILED: \"ctrl-3 has no on-disk checkpoint after the upgrade\". ctrl-1/ctrl-2 both have data/snap/snap-000000000000000b.capnp (51161 bytes, LSN 11 hex = the WAL_CONFIG_MARKER's own lsn); ctrl-3's data/snap/ is completely empty. ctrl-3's log shows a PERMANENT loop (repeats every ~3s/heartbeat for the entire ~3-minute run, never progressing): a bare heartbeat probe at prevIdx=11 succeeds (ae_already_have, match=11), but every walCatchupEntry at prevIdx=12/13/14 is rejected forever with ae_reject_logmismatch. Unlike bug-1475's own signature, this is NOT a transient race that self-heals once durable_lsn catches up -- it never recovers for the rest of the run.", "file": "src/controller/myapp.c (~line 388-425, the \"leader already known -- skip own election\" fast path and its single guarded cluster_init_phase2 retry, bug-849 lineage); src/controller/ha.c (raft_cb_become_follower ~line 2000-2012, raft_cb_become_leader ~line 1772-1783, ha_elect_evaluate_and_signal ~line 5609-5629/5699-5710 -- all three unconditionally set ha->phase2_done=1 after calling cluster_init_phase2(c) without checking its return value); src/controller/cluster.c (cluster_init_phase2 ~line 1342-1598, the sole call site of commit_engine_init/persist_recover/ha_sync_raft_log_from_recovery); src/controller/persist.c (~line 796-799, on_durable_advance documented as registered ONLY by commit_engine_init)", "root_cause": "ROOT-CAUSED with byte/log-precise evidence, NOT config-upgrade-snapshot's own defect. ctrl-3 (my_priority=2, the highest-priority-number/most-deferred candidate in the 3-node cluster, per myapp_run's startup-stagger nanosleep) never ran its own raft candidacy for the ENTIRE test: zero occurrences of raft_cb_become_follower/raft_cb_become_leader/\"-> CTRL_STANDBY\" anywhere in ctrl-3.log. Instead, by the time its stagger delay elapsed, ctrl-1 (priority 0) had already voted/established itself, so myapp_run's own \"leader already known\" check (myapp.c ~343-390: voted_for_name set, or raft.term>0, or primary_ctrl_fd>=0) was true, and ctrl-3 took the `goto skip_election` fast path, entirely bypassing ha_start_election_async and therefore every raft-library election callback for the rest of its process lifetime (it only ever GRANTS votes to others afterward -- confirmed via repeated vote_granted/pre_vote_granted RAFT[p2] events with no corresponding become_follower/become_leader). The skip_election fast path (myapp.c ~415-425, bug-849, commit 20e59d0b, 2026-06-21 -- three-plus weeks before config-upgrade-snapshot's first commit 9e68335a) makes exactly ONE, correctly-guarded attempt at cluster_init_phase2(&c) (checks prc, only sets c.ha.phase2_done=1 on success) -- and at 08:18:26,930, that ONE attempt fired before c->myconf->cluster_config was populated (ctrl-3 had no local config file and had not yet received/activated a push), so cluster_init_phase2 returned -EINVAL immediately (cluster.c:1349-1358, before doing ANY of its real work) and the WARN 'cluster_init_phase2 on standby rejoin failed (rc=-22) -- WAL not recovered; falling back to election-path recovery' fired. phase2_done correctly stayed 0 -- but there is NO OTHER retry mechanism anywhere in the codebase for a node that (a) took the skip_election fast path and (b) never subsequently runs its own contested election: the only other three call sites that could retry (raft_cb_become_follower ha.c:2000-2012, raft_cb_become_leader ha.c:1772-1783, ha_elect_evaluate_and_signal's CTRL_PRIMARY/CTRL_STANDBY branches ha.c:5609-5629/5699-5710) never fire for ctrl-3 because it never engages the raft callback machinery at all. (Separately confirmed those three call sites ALSO unconditionally set ha->phase2_done=1 after calling cluster_init_phase2(c) with NO check of its return value -- unlike myapp.c's own careful guard -- a second, adjacent defect of the same class that did not trigger THIS failure only because ctrl-3 never reached them, but would identically strand any node whose FIRST raft-driven role transition happens to race ahead of config load.) Consequence, confirmed via grep: ctrl-3.log has ZERO occurrences of \"commit engine wired\", \"persist_recover\", \"xce_config_init\", or \"create_lost_and_found\" for the entire run (vs. multiple occurrences on ctrl-1/ctrl-2, once per boot/restart/re-election) -- cluster_init_phase2 (and therefore commit_engine_init, cluster.c:1484-1496) NEVER completed on ctrl-3. persist.c:796-799 documents on_durable_advance (the sole wake hook driving persist_apply_pump_run) as registered ONLY inside commit_engine_init -- so without it, persist_apply_pump_run/apply_committed_entry NEVER runs on ctrl-3, for ANY committed LSN, for the whole process lifetime. This means persist_checkpoint_marker_triggered (config-upgrade-snapshot task 5's own WAL_CONFIG_MARKER-triggered checkpoint, apply_committed_entry's WAL_CONFIG_MARKER case) never fires on ctrl-3 -- explaining precisely why its data/snap/ is empty while ctrl-1/ctrl-2 (whose commit engines DID wire) both hold the identical snap-000000000000000b.capnp. ctrl-3's config nonetheless activates cosmetically at 08:18:48,572 via a SEPARATE, independent code path (handle_repl_config_push -> load_primary_config -> config_activate_committed, an RPC push handler that does not touch the commit engine or apply pump at all) -- masking the underlying defect and making the soak's materialized-state/checkpoint assertions the first thing ever to surface it. bug-1475's three-part fix (config_repl.c's tracker-advance-across-WAL_CHECKPOINT, ha.c's JIT persist_durable_floor resync of ha->raft.log_len, persist.c's TERM_INDEX_UNSET sentinel) is necessary and correctly targets its own class of bug (a receiving standby's log_len bookkeeping merely LAGGING behind a checkpoint it DID independently write) but structurally cannot cover this failure: bug-1475's own fix explicitly documents and depends on the invariant 'a standby that independently applied the SAME committed WAL_CONFIG_MARKER writes its OWN local checkpoint at the identical LSN (deterministic per-member trigger)' -- ctrl-3 violates that precondition outright (it never writes the checkpoint AT ALL, not merely late), so the primary's catch-up stream's prev_log_index=12 (the checkpoint's own lsn, per bug-1475's now-correct sender tracking) checks against an entry ctrl-3 genuinely, permanently does not have. ae_reject_logmismatch is therefore a CORRECT rejection of ctrl-3's true log state, not a stale/racy one -- and since a WAL_CHECKPOINT entry is local-only/non-replicated BY DESIGN (persist_write_checkpoint_marker's own doc comment; persist_wal_write_replicated/persist_wal_async both explicitly reject type==WAL_CHECKPOINT), ctrl-3 can NEVER receive lsn=12 over the wire, and can never independently write it either (cluster_init_phase2/commit_engine_init never retries) -- a genuinely permanent, not merely time-bounded, wedge, exactly matching the soak's observed behavior (unlike bug-1475's transient race, this repeated with zero progress for the entire ~3-minute run). git blame confirms both implicated pre-existing defects (myapp.c's skip_election fast path, commit 20e59d0b bug-849 2026-06-21; ha.c's raft-callback phase2_done latch structure, commit 8f0d2d55 task 6.2 raft-library) predate config-upgrade-snapshot's first commit (9e68335a) by roughly a month -- this is a pre-existing HA bootstrap/election gap, NOT something config-upgrade-snapshot's task 5 introduced. Task 5 merely exposed it by creating a new cross-member structural dependency (every member independently checkpointing at a synchronized marker-boundary LSN) that a node whose commit engine/apply pump never wired silently violates. Before config-upgrade-snapshot, the same underlying gap would have left such a node's materialized state (jobmgr/qmgr/workermgr) permanently stale/un-applied with a much less visible failure signature (no crash, no wedge -- just silently wrong query results if that node were ever promoted), plausibly unnoticed by prior soaks that do not assert per-member materialized-state identity.", - "fix": "NOT FIXED -- root-caused only, per explicit instruction (forensic investigation, not a fix task; this defect is squarely OUT OF SCOPE for config-upgrade-snapshot, parallel to bug-1471/1472/1474's routing). Two coordinated repo-fixable gaps, both in pre-existing HA bootstrap/election machinery (ha-config-bootstrap / election-iomgr-refactor / raft-library spec lineage), NOT config-upgrade-snapshot: (1) myapp.c's skip_election fast path (~line 415-425) needs a retry hook for a node that took it and never subsequently runs its own raft candidacy -- e.g. re-attempt cluster_init_phase2 once config_activate_committed/handle_repl_config_push first populates c->myconf->cluster_config on such a node, or arm a bounded retry timer instead of a single one-shot attempt. (2) ha.c's three raft-driven call sites (raft_cb_become_follower ~2000-2012, raft_cb_become_leader ~1772-1783, ha_elect_evaluate_and_signal's two branches ~5609-5629/5699-5710) should check cluster_init_phase2's return value the same way myapp.c's own guarded call already does, only latching ha->phase2_done=1 on success -- so a node whose first raft-driven role-transition callback races ahead of config load gets a genuine later retry instead of being permanently stranded. Recommend filing/handing this to whichever spec owns HA bootstrap/election continuity (ha-config-bootstrap or a new small fix spec), NOT implementing inside config-upgrade-snapshot. config-upgrade-snapshot task 8.6 should be BLOCKED on this new bug (same pattern as bug-1471/1472/1474 before it), not reattempted until fixed upstream.", + "fix": "FIXED (2026-07-28). Root cause: myapp_run's skip_election passive path, and 3 raft-callback call sites (raft_cb_become_leader, raft_cb_become_follower, ha_elect_evaluate_and_signal x2), all latched ha->phase2_done=1 UNCONDITIONALLY right after calling cluster_init_phase2 (or its ha_phase2_hook test seam), discarding its return value entirely -- so a single failed attempt (e.g. racing config availability, cluster_init_phase2 returning -EINVAL because cluster_config wasn't loaded yet) permanently stranded the member: commit_engine_init never ran, so apply_committed_entry never applied ANY committed WAL entry for the rest of that process's life, and -- for a node on the passive skip_election path specifically -- NOTHING else would ever retry it (the other 3 call sites only fire via this node's own raft-library state transitions, which never happen for a passive standby whose primary keeps heartbeating normally).\n\nFix: extracted a shared, idempotent retry mechanism -- ha_phase2_retry_fn (the blocking retry itself, capturing cluster_init_phase2/ha_phase2_hook's real return value, latching phase2_done ONLY on rc==0) plus ha_schedule_phase2_retry (a delaymgr-scheduled, SELF-RESCHEDULING trigger at heartbeat_interval_ms cadence -- unlike upgrade_materialization_retry/config_activate_retry, which are re-triggered externally by recurring commit-advance events, nothing recurring would otherwise ever re-trigger this for a passive skip_election node, so this one self-arms). Wired into all 5 call sites: myapp.c's skip_election block now schedules a retry instead of just WARNing on failure; raft_cb_become_follower and ha_elect_evaluate_and_signal's STANDBY branch likewise (safe to stay passive while retrying); raft_cb_become_leader and ha_elect_evaluate_and_signal's PRIMARY branch additionally REFUSE promotion on failure in raft_cb_become_leader specifically (mirroring the sibling upgrade_materialization_fenced refusal in the same function -- a promoted primary with an unwired commit engine would be far worse than a delayed promotion); the legacy ha_elect_evaluate_and_signal PRIMARY branch does NOT refuse (its ctx->done semaphore is already posted to the caller before this point in that function, so refusing would leave an inconsistent signal -- it proceeds to CTRL_PRIMARY and lets the self-rescheduling retry wire the commit engine shortly after instead).\n\nTDD: 4 new tests in test_config_repl.c (test_ha_phase2_retry_fn_noop_when_already_done, test_ha_phase2_retry_fn_does_not_latch_on_failure_and_succeeds_on_retry -- the core regression, RED confirmed by temporarily reverting the rc-gating back to an unconditional latch and observing the exact predicted failure -- test_schedule_phase2_retry_noop_when_already_done, test_schedule_phase2_retry_noop_when_delaymgr_not_running). GREEN: full controller_unit_test suite = 1044 tests, 0 failures, clean across multiple runs (including the RED/GREEN round-trip).\n\nLive-verified: re-ran run-ha-soak.sh --config-upgrade (the exact scenario that originally found this bug) -- ctrl-2's log shows the retry mechanism firing for real (4 failed cluster_init_phase2 attempts at ~3s intervals, rc=-22, then success: \"commit engine now wired (bug-1477)\"), and the soak's own checkpoint-identity, config-identity, and host-admin-status-survival assertions (the exact things bug-1477 blocked) all PASS. The soak run subsequently hit a DIFFERENT, seemingly unrelated failure later in its own force-elect-rotation step (repeated commit timeouts, rc=-110, on ctrl-1-as-primary) -- flagged separately, NOT part of this fix's scope; this soak scenario has never previously reached that step (earlier runs always failed earlier, at bug-1471/1472's checkpoint divergence or this bug's own catch-up wedge), so it may be a pre-existing, newly-exposed issue rather than a regression from this fix -- needs its own dedicated investigation.", "tags": [ - "ha.c", - "myapp.c", - "cluster.c", - "cluster_init_phase2", - "phase2_done", - "commit_engine_init", "apply_pump_never_wired", - "skip_election", - "bug-849-lineage", - "ae_reject_logmismatch", - "permanent-catchup-wedge", - "config-upgrade-snapshot-task-8.6", - "marker-triggered-checkpoint", "not-bug-1475", - "bug-1475-fix-verified-good", + "commit_engine_init", + "cluster.c", + "config-upgrade-snapshot-task-8.6", + "not-fixed", + "marker-triggered-checkpoint", "out-of-scope-upstream", + "skip_election", + "retry-mechanism", + "phase2_done", + "ae_reject_logmismatch", + "bug-849-lineage", + "permanent-catchup-wedge", + "fixed", + "myapp.c", + "bug-1475-fix-verified-good", + "ha.c", "needs-owner", - "not-fixed" + "cluster_init_phase2" ], "related_bugs": [ "bug-1475", "bug-1466", "bug-849" ], - "occurrences": 1, - "last_seen": "2026-07-28T08:25:00Z" + "occurrences": 2, + "last_seen": "2026-07-28T13:25:00Z" }, { "id": "bug-1478", diff --git a/.wolf/cerebrum.md b/.wolf/cerebrum.md index ef2186b6..505c0443 100644 --- a/.wolf/cerebrum.md +++ b/.wolf/cerebrum.md @@ -568,3 +568,9 @@ Prior entry (2026-07-25) noted `repl_remove_standby` correctly sets the `last_di ## Do-Not-Repeat (2026-07-28, bug-1476) — a buglog "FIXED... GREEN" claim is not proof; the working tree can be mid-TDD-cycle at the exact moment you resume Resumed `/kiro-impl config-upgrade-snapshot` with buglog.json's bug-1476 entry claiming "FIXED (2026-07-28)... GREEN: full controller_unit_test suite" — but the actual uncommitted diff on disk had a comment (config_repl.c:639-646) explicitly admitting `load_primary_config()` had been reverted to its RED-phase (no lock, decode-directly-into-shared-field) state for test construction and never restored. Running the full suite fresh immediately surfaced the real state: `test_bug1476_concurrent_load_primary_config_no_uaf_or_double_free` FAILED. The buglog note was written mid-cycle, describing the INTENDED fix, not the code actually sitting on disk. Fixed for real (lock now wraps the whole function body; decode targets a local temp, swapped in only after full validation), verified 4/4 clean full-suite runs before committing. **Do-not-repeat**: before committing or building on top of ANY buglog "FIXED"/GREEN claim for uncommitted work, re-run the actual test suite against the actual working tree first — never trust the log entry's narrative over a fresh run, especially when resuming a session that may have been interrupted mid-TDD-cycle. + +## Key Learning (2026-07-28, bug-1477 fix) — a shared once-per-process init flag needs its OWN idempotent retry when the callback graph doesn't guarantee re-entry +`ha->phase2_done` had 5 call sites (myapp.c's skip_election path + 4 in ha.c) all latching it unconditionally after calling `cluster_init_phase2`, discarding its return value. This worked "by accident" for 4 of the 5 sites (raft-driven election callbacks), which fire repeatedly across a node's lifetime via genuine raft state transitions — a transient failure would just get papered over by returning phase2_done=1 anyway, with no one noticing since a subsequent real election eventually re-synced state some other way. But the 5th site (myapp.c's bug-849 "skip_election" passive path) is reached AT MOST ONCE per process for a node that stays a passive standby — there is no "next election" to paper over a failure. **Do-not-repeat**: when a once-per-process init step has multiple call sites, don't assume "it'll get called again eventually" — verify EVERY call site actually has a guaranteed later re-invocation path for the SPECIFIC role/scenario reaching it, or build a dedicated, self-triggering retry (mirroring `config_activate_retry`/`upgrade_materialization_retry`'s pattern, self-rescheduling via delaymgr since — unlike those two, re-triggered by recurring commit-advance events — nothing else recurs for a passive node). + +## Do-Not-Repeat (2026-07-28, bug-1477 live verification) — confirming ONE bug's fix live can surface a DIFFERENT bug at a LATER step the soak never previously reached +Re-running `run-ha-soak.sh --config-upgrade` after the bug-1477 fix: the bug's own specific symptoms (checkpoint-identity, config-identity, host-admin-status-survival assertions) all PASSED for the first time. But the SAME soak run then failed later, in the force-elect-rotation step, with repeated commit timeouts (rc=-110) on the primary — a step this soak scenario had NEVER reached before (every prior attempt failed earlier, first at bug-1471/1472's checkpoint divergence, then at bug-1477's own catch-up wedge). **Do-not-repeat**: don't assume a soak reaching further and failing differently means your fix is broken or incomplete — check whether the NEW failure point was ever exercised before; if not, it's very plausibly a separate, pre-existing, newly-exposed bug (same pattern as this whole session's bug-1471→1472→1474→1477 chain), not evidence the just-verified fix regressed something. Investigate the new failure on its own terms (what's different about THIS code path) rather than assuming causality from the just-changed code. diff --git a/src/controller/ha.c b/src/controller/ha.c index f8df29be..972d3642 100644 --- a/src/controller/ha.c +++ b/src/controller/ha.c @@ -406,6 +406,101 @@ int schedule_upgrade_materialization_retry(cluster_t *c) return rc; } +/* ha_phase2_retry_fn / ha_phase2_retry_vtask_entry / + * ha_phase2_retry_delaymgr_trampoline / ha_schedule_phase2_retry (bug-1477): + * see the doc comments in ha.h. Structurally identical to + * upgrade_materialization_retry_fn's own 3-layer shape (blocking retry_fn -> + * vtask entry -> delaymgr trampoline) just above, except the trampoline + * re-arms itself on failure since nothing else recurring would otherwise + * ever retry cluster_init_phase2 for a node stuck on myapp_run's passive + * skip_election path. */ +int ha_phase2_retry_fn(void *arg) +{ + cluster_t *c = (cluster_t *)arg; + if (!c) + return -EINVAL; + if (c->ha.phase2_done) + return 0; /* already done by another path -- nothing to retry */ + + int rc; +#ifdef XCE_TESTING + rc = (ha_phase2_hook != NULL) ? ha_phase2_hook(c) : 0; +#else + rc = cluster_init_phase2(c); +#endif + if (rc == 0) { + c->ha.phase2_done = 1; + INFO("HA: cluster_init_phase2 retry succeeded — commit engine now " + "wired (bug-1477)"); + } else { + WARN("HA: cluster_init_phase2 retry rc=%d — member stays alive and " + "will retry again (bug-1477, never self-terminate)", rc); + ha_schedule_phase2_retry(c); + } + return rc; +} + +static int ha_phase2_retry_vtask_entry(vtask_t *task) +{ + cluster_t *c = (cluster_t *)task->data->u.generic; + ha_phase2_retry_fn(c); + return 0; +} + +static int ha_phase2_retry_delaymgr_trampoline(void *arg) +{ + cluster_t *c = (cluster_t *)arg; + if (!c) + return -EINVAL; + + vtaskmgr_t *pool = &c->vtaskmgr; + vtask_data_t *data = calloc(1, sizeof(*data)); + vtask_t *task = vtask_alloc(); + + if (data == NULL || task == NULL) { + WARN("HA: cluster_init_phase2 retry: vtask alloc failed — running " + "inline (stay alive)"); + free(data); + free(task); + return ha_phase2_retry_fn(c); + } + + data->vtype = VTASK_GENERIC; + data->u.generic = c; + vtask_init(task, (vtask_func_t)ha_phase2_retry_vtask_entry, data); + + if (vtask_enq_classified(pool, task, VTASK_LIVE_BLOCK) < 0) { + WARN("HA: cluster_init_phase2 retry: vtask enqueue failed — running " + "inline (stay alive)"); + free(data); + free(task); + return ha_phase2_retry_fn(c); + } + return 0; +} + +int ha_schedule_phase2_retry(cluster_t *c) +{ + if (!c) + return -EINVAL; + if (c->ha.phase2_done) + return 0; /* steady state: nothing to retry, schedule nothing */ + if (!c->delaymgr.running) + return 0; /* delaymgr not running (test fixture) — caller drives directly */ + + uint32_t interval_ms = c->ha.config.heartbeat_interval_ms; + if (interval_ms == 0) + interval_ms = HA_DEFAULT_HEARTBEAT_INTERVAL_MS; + + int rc = delay_task_ms(&c->delaymgr, (int)interval_ms, 1, + (delay_task_entry_fn_t)ha_phase2_retry_delaymgr_trampoline, + c); + if (rc < 0) + WARN("HA: cluster_init_phase2 retry: delay_task_ms failed: %d — " + "will retry on the next natural re-trigger", rc); + return rc; +} + static void on_vote_connected(endpoint_t *ep); static void on_pre_vote_connected(endpoint_t *ep); static int vote_ep_err_handler(void *ep_raw); @@ -1773,14 +1868,31 @@ static void raft_cb_become_leader(void *ctx, uint64_t term) /* First boot: call cluster_init_phase2 */ if (is_first_boot) { + int p2rc = 0; #ifdef XCE_TESTING if (ha_phase2_hook != NULL) - ha_phase2_hook(c); + p2rc = ha_phase2_hook(c); #else if (c != NULL) - cluster_init_phase2(c); + p2rc = cluster_init_phase2(c); #endif - ha->phase2_done = 1; + if (p2rc == 0) { + ha->phase2_done = 1; + } else { + /* bug-1477: do NOT latch phase2_done on failure, and do NOT + * proceed to CTRL_PRIMARY with an unwired commit engine — mirror + * the upgrade_materialization_fenced refusal just above (stay + * ALIVE, non-promotable, retry; a later promotion attempt + * succeeds once ha_schedule_phase2_retry completes). Before this + * fix, phase2_done was latched unconditionally, so this failure + * path never existed for the code below to worry about. */ + WARN("HA: promotion REFUSED — cluster_init_phase2 failed " + "(rc=%d); member stays ALIVE, non-promotable, retrying " + "(bug-1477, never self-terminate)", p2rc); + if (c != NULL) + ha_schedule_phase2_retry(c); + return; /* do NOT become CTRL_PRIMARY with an unwired commit engine */ + } /* bug-1445 fix: cluster_init_phase2() above just ran this process's * very FIRST persist_recover()/replay_wal() -- the ONLY thing that @@ -2001,14 +2113,26 @@ static void raft_cb_become_follower(void *ctx, uint64_t term, int leader_idx) /* First boot: call cluster_init_phase2 so structures are ready */ if (is_first_boot) { + int p2rc = 0; #ifdef XCE_TESTING if (ha_phase2_hook != NULL) - ha_phase2_hook(c); + p2rc = ha_phase2_hook(c); #else if (c != NULL) - cluster_init_phase2(c); + p2rc = cluster_init_phase2(c); #endif - ha->phase2_done = 1; + if (p2rc == 0) { + ha->phase2_done = 1; + } else { + /* bug-1477: do NOT latch phase2_done on failure — a standby + * (unlike a promoted primary) can safely stay passive while + * ha_schedule_phase2_retry retries; nothing below depends on + * phase2 having succeeded. */ + WARN("HA: cluster_init_phase2 on become-follower failed (rc=%d) " + "— member stays alive, will retry (bug-1477)", p2rc); + if (c != NULL) + ha_schedule_phase2_retry(c); + } } /* Close all outgoing vote endpoints (loser path). @@ -5664,15 +5788,32 @@ apply_role: /* First boot: call cluster_init_phase2 to load config+data (Req 9.2) */ if (is_first_boot) { + int p2rc = 0; #ifdef XCE_TESTING /* In test mode, use hook if set; skip real phase2 (cluster.c not linked) */ if (ha_phase2_hook != NULL) - ha_phase2_hook(c); + p2rc = ha_phase2_hook(c); #else if (c != NULL) - cluster_init_phase2(c); + p2rc = cluster_init_phase2(c); #endif - ha->phase2_done = 1; + if (p2rc == 0) { + ha->phase2_done = 1; + } else { + /* bug-1477: do NOT latch phase2_done on failure. Unlike + * raft_cb_become_leader, this legacy evaluation path has + * ALREADY signaled the caller's ctx->done semaphore with + * result=1 above (before "apply_role:") — refusing + * promotion here would leave that signal inconsistent + * with never becoming CTRL_PRIMARY. Proceed to + * CTRL_PRIMARY as before; ha_schedule_phase2_retry wires + * the commit engine shortly after instead of never. */ + WARN("HA FSM: cluster_init_phase2 failed on promotion " + "(rc=%d) — proceeding to CTRL_PRIMARY, retrying " + "phase2 (bug-1477)", p2rc); + if (c != NULL) + ha_schedule_phase2_retry(c); + } } /* ha-single-leader-role task 3.1 (Req 1.1, 1.5): enter CTRL_PRIMARY @@ -5745,15 +5886,27 @@ apply_role: /* First boot: call cluster_init_phase2 so structures are ready; * config arrives via primary's replication push (Req 9.2, 7.3) */ if (is_first_boot) { + int p2rc = 0; #ifdef XCE_TESTING /* In test mode, use hook if set; skip real phase2 (cluster.c not linked) */ if (ha_phase2_hook != NULL) - ha_phase2_hook(c); + p2rc = ha_phase2_hook(c); #else if (c != NULL) - cluster_init_phase2(c); + p2rc = cluster_init_phase2(c); #endif - ha->phase2_done = 1; + if (p2rc == 0) { + ha->phase2_done = 1; + } else { + /* bug-1477: do NOT latch phase2_done on failure — a + * standby can safely stay passive while + * ha_schedule_phase2_retry retries. */ + WARN("HA FSM: cluster_init_phase2 failed on " + "become-standby (rc=%d) — member stays alive, will " + "retry (bug-1477)", p2rc); + if (c != NULL) + ha_schedule_phase2_retry(c); + } } atomic_store_explicit(&ha->role, (int32_t)CTRL_STANDBY, diff --git a/src/controller/ha.h b/src/controller/ha.h index 5ff0e6f4..d5426db6 100644 --- a/src/controller/ha.h +++ b/src/controller/ha.h @@ -859,6 +859,56 @@ int upgrade_materialization_retry_fn(void *arg); */ int schedule_upgrade_materialization_retry(cluster_t *c); +/* + * ha_phase2_retry_fn (bug-1477): re-attempts cluster_init_phase2 for a node + * whose earlier attempt(s) failed and never set ha->phase2_done. Idempotent + * -- a no-op once phase2_done is already set by ANY call site (the shared + * once-per-process contract every cluster_init_phase2 caller relies on). + * Does the actual blocking work (cluster_init_phase2 runs persist_recover, + * wires the commit engine, etc.); production callers invoke it off the + * delaymgr thread via ha_schedule_phase2_retry's trampoline (below) -- + * mirrors upgrade_materialization_retry_fn/config_activate_retry_fn exactly. + * Public so tests can drive it directly without a vtask pool. `arg` is a + * `cluster_t *`. Returns 0 on success/already-done, the underlying negative + * errno on a genuine cluster_init_phase2 failure (and self-reschedules + * before returning, so the caller need not). + * + * Root cause this closes: a node that takes myapp_run's skip_election + * passive path (bug-849) -- because a leader was already known after the + * startup stagger -- makes exactly ONE cluster_init_phase2 attempt. If that + * attempt races config availability and fails, NOTHING else ever retries + * it: raft_cb_become_follower / raft_cb_become_leader / + * ha_elect_evaluate_and_signal (the other three call sites) only fire via + * THIS node's own raft-library state transitions, which never happen for a + * node that stays passively CTRL_STANDBY while its primary keeps + * heartbeating normally. The node is then permanently stuck without a + * wired commit engine -- silently unable to apply ANY committed entry for + * the rest of its process lifetime (never self-terminates, per + * controller/CLAUDE.md's Process Lifecycle invariant, but never recovers + * either without this retry). + */ +int ha_phase2_retry_fn(void *arg); + +/* + * ha_schedule_phase2_retry (bug-1477): non-blocking, self-rescheduling retry + * for a node whose cluster_init_phase2 has not yet completed -- mirrors + * config_schedule_activate_retry / schedule_upgrade_materialization_retry's + * delaymgr-trampoline-then-vtask shape, except it re-arms ITSELF on failure + * (via ha_phase2_retry_fn) since -- unlike those two, which are re-triggered + * externally by every commit-advance/config-push event -- there is no + * other recurring event that would naturally re-trigger this for a node + * stuck on the passive skip_election path. Retries at ha->config. + * heartbeat_interval_ms cadence (the natural rhythm config/connectivity + * changes arrive on), indefinitely (never gives up -- never-self-terminate + * invariant). No-op when phase2_done is already set (steady state + * schedules nothing -- no busy-spin) or when the delaymgr is not running + * (unit-test fixture path; caller drives the retry directly instead). + * Falls back to running the retry inline (stay alive, never silently drop + * a scheduled retry) if the vtask pool is unavailable. Returns 0 on + * enqueue/no-op, negative on enqueue failure. + */ +int ha_schedule_phase2_retry(cluster_t *c); + /* * ha_apply_wal_catchup_entry: apply a single WAL catch-up entry to local * persistent storage and advance ha->applied_lsn on success. diff --git a/src/controller/myapp.c b/src/controller/myapp.c index 712dc62d..7066933a 100644 --- a/src/controller/myapp.c +++ b/src/controller/myapp.c @@ -420,8 +420,11 @@ skip_election:; int prc = cluster_init_phase2(&c); if (prc != 0) { WARN("myapp_run: cluster_init_phase2 on standby rejoin " - "failed (rc=%d) — WAL not recovered; falling back to " - "election-path recovery", prc); + "failed (rc=%d) — WAL not recovered; member stays " + "alive and will retry (bug-1477: this passive " + "skip_election path never sees the election-result " + "callers that would otherwise retry it)", prc); + ha_schedule_phase2_retry(&c); } else { c.ha.phase2_done = 1; } diff --git a/src/controller/testsuite/test_config_repl.c b/src/controller/testsuite/test_config_repl.c index c32fc28c..e33c0097 100644 --- a/src/controller/testsuite/test_config_repl.c +++ b/src/controller/testsuite/test_config_repl.c @@ -2228,6 +2228,141 @@ static void test_commit_advance_wiring_calls_upgrade_materialization_schedule_re printf("test_commit_advance_wiring_calls_upgrade_materialization_schedule_retry: PASS\n"); } +/* ── bug-1477: ha_phase2_retry_fn / ha_schedule_phase2_retry ───────────────── + * + * A node that takes myapp_run's skip_election passive path (bug-849 -- + * "leader already known after the startup stagger") makes exactly ONE + * cluster_init_phase2 attempt. Before this fix, EVERY call site (myapp.c's + * skip_election block, raft_cb_become_leader, raft_cb_become_follower, + * ha_elect_evaluate_and_signal's two branches) latched ha->phase2_done = 1 + * UNCONDITIONALLY, regardless of cluster_init_phase2's return value. If that + * one attempt raced config availability and failed, the node was left + * permanently stuck: commit_engine_init never ran, so apply_committed_entry + * never applied ANY committed WAL entry for the rest of that process's + * lifetime -- and since a skip_election node never again contests an + * election, none of the other four call sites, which only fire via THIS + * node's own raft-library state transitions, ever ran again either. + * + * ha_phase2_retry_fn is the idempotent retry entry (mirrors + * upgrade_materialization_retry_fn's shape); ha_schedule_phase2_retry is its + * delaymgr-scheduled, self-limiting trigger (mirrors + * schedule_upgrade_materialization_retry's no-op guards). */ + +/* (bug-1477-a) ha_phase2_retry_fn is a no-op once phase2_done is already + * set -- does not re-invoke the hook, returns 0. */ +static void test_ha_phase2_retry_fn_noop_when_already_done(void) +{ + char tmp[256]; + strcpy(tmp, "/tmp/xce_cr1477_retry_noop_done_XXXXXX"); + TEST_ASSERT_NOT_NULL(mkdtemp(tmp)); + + cluster_t *c = t42_make_cluster(tmp); + TEST_ASSERT_NOT_NULL(c); + c->ha.phase2_done = 1; + + TEST_ASSERT_EQUAL_INT(0, ha_phase2_retry_fn(c)); + TEST_ASSERT_EQUAL_INT(1, c->ha.phase2_done); + + t42_teardown(c); + printf("test_ha_phase2_retry_fn_noop_when_already_done: PASS\n"); +} + +static _Atomic int g_cr1477_hook_calls; +static _Atomic int g_cr1477_hook_fail_first_n; + +/* Fails the first g_cr1477_hook_fail_first_n calls (rc=-EAGAIN), succeeds + * (rc=0) thereafter -- models cluster_init_phase2 racing config + * availability and then succeeding once it arrives. */ +static int cr1477_flaky_phase2_hook(void *c) +{ + (void)c; + int n = atomic_fetch_add(&g_cr1477_hook_calls, 1); + return (n < atomic_load(&g_cr1477_hook_fail_first_n)) ? -EAGAIN : 0; +} + +/* (bug-1477-b) THE CORE REGRESSION: a failed cluster_init_phase2 attempt + * must NOT latch phase2_done -- RED under the pre-fix code (which set + * phase2_done = 1 unconditionally right after calling the hook, regardless + * of its return value; this assertion would fail immediately). A second + * call, once the underlying condition clears, then succeeds and latches. */ +static void test_ha_phase2_retry_fn_does_not_latch_on_failure_and_succeeds_on_retry(void) +{ + char tmp[256]; + strcpy(tmp, "/tmp/xce_cr1477_retry_fn_XXXXXX"); + TEST_ASSERT_NOT_NULL(mkdtemp(tmp)); + + cluster_t *c = t42_make_cluster(tmp); + TEST_ASSERT_NOT_NULL(c); + TEST_ASSERT_EQUAL_INT(0, c->ha.phase2_done); /* fixture default: not done */ + + atomic_store(&g_cr1477_hook_calls, 0); + atomic_store(&g_cr1477_hook_fail_first_n, 1); + ha_phase2_hook = cr1477_flaky_phase2_hook; + + /* First attempt: hook fails -- phase2_done must stay 0 (bug-1477's own + * regression assertion). */ + TEST_ASSERT_EQUAL_INT(-EAGAIN, ha_phase2_retry_fn(c)); + TEST_ASSERT_EQUAL_INT_MESSAGE(0, c->ha.phase2_done, + "a failed cluster_init_phase2 attempt must not latch phase2_done " + "(bug-1477 -- the pre-fix code did this unconditionally, " + "permanently stranding the member)"); + + /* Second attempt: hook now succeeds -- phase2_done latches. */ + TEST_ASSERT_EQUAL_INT(0, ha_phase2_retry_fn(c)); + TEST_ASSERT_EQUAL_INT(1, c->ha.phase2_done); + + /* Idempotent: a third call is a pure no-op (hook not re-invoked). */ + int calls_before = atomic_load(&g_cr1477_hook_calls); + TEST_ASSERT_EQUAL_INT(0, ha_phase2_retry_fn(c)); + TEST_ASSERT_EQUAL_INT(calls_before, atomic_load(&g_cr1477_hook_calls)); + + ha_phase2_hook = NULL; /* restore -- shared process-global test seam */ + t42_teardown(c); + printf("test_ha_phase2_retry_fn_does_not_latch_on_failure_and_succeeds_on_retry: PASS\n"); +} + +/* (bug-1477-c) ha_schedule_phase2_retry is a no-op when phase2_done is + * already set -- steady state schedules nothing (no busy-spin), mirroring + * schedule_upgrade_materialization_retry's own documented no-op behavior. */ +static void test_schedule_phase2_retry_noop_when_already_done(void) +{ + char tmp[256]; + strcpy(tmp, "/tmp/xce_cr1477_sched_noop_done_XXXXXX"); + TEST_ASSERT_NOT_NULL(mkdtemp(tmp)); + + cluster_t *c = t42_make_cluster(tmp); + TEST_ASSERT_NOT_NULL(c); + c->ha.phase2_done = 1; + TEST_ASSERT_FALSE(c->delaymgr.running); /* fixture never starts delaymgr */ + + TEST_ASSERT_EQUAL_INT(0, ha_schedule_phase2_retry(c)); + + t42_teardown(c); + printf("test_schedule_phase2_retry_noop_when_already_done: PASS\n"); +} + +/* (bug-1477-d) ha_schedule_phase2_retry is a no-op when the delaymgr is not + * running, even while phase2_done is still 0 -- the unit-test fixture path + * (mirrors config_schedule_activate_retry / schedule_upgrade_materialization_ + * retry's own documented delaymgr-not-running no-op). */ +static void test_schedule_phase2_retry_noop_when_delaymgr_not_running(void) +{ + char tmp[256]; + strcpy(tmp, "/tmp/xce_cr1477_sched_noop_nodmgr_XXXXXX"); + TEST_ASSERT_NOT_NULL(mkdtemp(tmp)); + + cluster_t *c = t42_make_cluster(tmp); + TEST_ASSERT_NOT_NULL(c); + TEST_ASSERT_EQUAL_INT(0, c->ha.phase2_done); + TEST_ASSERT_FALSE(c->delaymgr.running); + + TEST_ASSERT_EQUAL_INT(0, ha_schedule_phase2_retry(c)); + TEST_ASSERT_EQUAL_INT(0, c->ha.phase2_done); /* untouched -- no-op */ + + t42_teardown(c); + printf("test_schedule_phase2_retry_noop_when_delaymgr_not_running: PASS\n"); +} + /* ── config-upgrade-snapshot task 6.2 remediation: Activation Fence set by a * REAL production trigger, not a direct test call ────────────────────────── * @@ -6601,6 +6736,10 @@ void test_config_repl(void) RUN_TEST(test_schedule_upgrade_materialization_retry_noop_when_delaymgr_not_running); RUN_TEST(test_upgrade_materialization_retry_fn_recovers_from_stale_bytes_fence); RUN_TEST(test_commit_advance_wiring_calls_upgrade_materialization_schedule_retry); + RUN_TEST(test_ha_phase2_retry_fn_noop_when_already_done); + RUN_TEST(test_ha_phase2_retry_fn_does_not_latch_on_failure_and_succeeds_on_retry); + RUN_TEST(test_schedule_phase2_retry_noop_when_already_done); + RUN_TEST(test_schedule_phase2_retry_noop_when_delaymgr_not_running); /* config-upgrade-snapshot task 6.2 remediation: fence set by a REAL * production trigger (apply_committed_entry's WAL_CONFIG_MARKER case), * not a direct test call -- proves the fence is reachable at all. */