myxce/.kiro/specs/ha-config-bootstrap/election-trace.md

Election Trace: 3-Node Cold Start (2026-06-04 00:15:58)

Parameters

Parameter	Value
election_timeout_ms	5000
election_priority_step_ms	500
heartbeat_interval_ms	3000
committing_timeout_ms	10000
heartbeat_timeout_ms	10000
cluster size	3 (ctrl-1 idx=0, ctrl-2 idx=1, ctrl-3 idx=2)
initial_state	ha-term.bin wiped, config_tag=4986624fd309142c on all 3

Startup Sequence (myapp_run)

For each node, the startup order is:

1. cluster_init_phase1 (raft_init with n_peers=1 placeholder, term=0)
2. SSL context
3. iomgr_init + iomgr_start ← iomgr thread RUNNING
4. cluster_register_listener ← listener in epoll
5. delaymgr_init + start
6. persist_init + start
7. load_primary_config
8. stagger nap + ha_start_election_async
9. cluster_run

Key: iomgr is running (step 3) BEFORE the stagger nap (step 8). This means incoming vote requests are processed during the nap.

Detailed Trace

T+0.000s — ctrl-1 starts (pid 532871)

restored term=0 from ha-term.bin
ha->term=0, voted_for_name=""
raft STATE (from ha_init): n_peers=1, self_idx=0, term=0, role=FOLLOWER, voted_for=-1

myapp_run step 7: Pre-election config loaded: tag=4986624fd309142c

ha_start_election_async:
  ha->raft_c = c  ← SET to non-NULL
  rcfg.initial_term = atomic_load(&ha->term) = 0
  rcfg.initial_voted_for = -1 (voted_for_name="")
  raft_init: n_peers=3, self_idx=0, s->term=0, s->role=FOLLOWER
  raft_start_election:
    s->term: 0 → 1
    s->voted_for = 0 (self)
    s->voted_for_term = 1
    s->votes_granted = 1
    s->role = CANDIDATE
    on_persist(term=1, voted_for=0):
      ha->term = 1
      ha->voted_for_name = "ctrl-1" (c is non-NULL)
    on_send_vote_request to peer 1 (ctrl-2), term=1
    on_send_vote_request to peer 2 (ctrl-3), term=1
    on_schedule_timeout(5000ms)

  CMD: INFO "→ CTRL_ELECTING (async, n_peers=3)"
  CMD: INFO "returning (n_peers=3, raft election started)"

→ cluster_run() starts iomgr event loop
→ vote connections to ctrl-2 and ctrl-3 attempted
→ ctrl-2 and ctrl-3 NOT STARTED YET → connection refused → peer counted as DENY
→ ctrl-1 waits for election timeout (5000ms)
  votes_granted=1 (self only), quorum=2, not reached

T+0.301s — ctrl-2 starts (pid 532883)

restored term=0
ha->term=0, voted_for_name=""
raft STATE (from ha_init): n_peers=1, self_idx=0, term=0, role=FOLLOWER, voted_for=-1

myapp_run steps 1-7 complete. iomgr running. listener in epoll.

→ enters 500ms stagger nap (my_priority=1 × 500ms)

DURING NAP: iomgr is running, listener accepting connections.
  But ctrl-1's vote connections already failed (ctrl-2 wasn't up yet).
  No new vote requests arrive during this nap window.
  ha->term stays at 0.
  voted_for_name stays at "".

T+0.603s — ctrl-3 starts (pid 532895)

restored term=0
ha->term=0, voted_for_name=""
raft STATE (from ha_init): n_peers=1, self_idx=0, term=0, role=FOLLOWER, voted_for=-1

→ enters 1000ms stagger nap (my_priority=2 × 500ms)

T+0.801s — ctrl-2 nap ends, starts election

already_voted check: voted_for_name="" (EMPTY!) → NO → starts election

ha_start_election_async:
  ha->raft_c = c  ← SET to non-NULL
  rcfg.initial_term = ha->term = 0
  raft_init: n_peers=3, self_idx=1, s->term=0
  raft_start_election:
    s->term: 0 → 1
    s->voted_for = 1 (self)
    s->votes_granted = 1
    on_persist(term=1, voted_for=1):
      ha->term = 1
      ha->voted_for_name = "ctrl-2" (c non-NULL)
    on_send_vote_request to peer 0 (ctrl-1), term=1
    on_send_vote_request to peer 2 (ctrl-3), term=1

  CMD: INFO "→ CTRL_ELECTING"
  CMD: INFO "returning"
→ cluster_run

T+0.810s — ctrl-2's votes arrive

To ctrl-1 (index 0):

ctrl-1 raft state: s->term=1, s->role=CANDIDATE, s->voted_for=0(self)
raft_on_vote_request(term=1, from_idx=1):
  Step 1: term(1) < s->term(1)? NO (equal)
  Step 2: term(1) > s->term(1)? NO (equal)
  Step 3: role is CANDIDATE → passes (not LEADER)
  Step 4: s->voted_for(0) != from_idx(1) && s->voted_for_term(1) == term(1)
          → "already voted for different candidate" → DENY
Result: DENY (already voted for self at term=1)

To ctrl-3 (index 2) — ctrl-3 is in 1000ms nap, iomgr running:

ctrl-3 raft state: n_peers=1, self_idx=0, s->term=0, s->role=FOLLOWER, s->voted_for=-1
(placeholder from ha_init — n_peers/selx are WRONG for this context)

raft_on_vote_request(term=1, from_idx=1):
  Step 1: term(1) < s->term(0)? NO
  Step 2: term(1) > s->term(0)? YES
          s->term = 1
          s->voted_for = -1
          s->voted_for_term = 0
          s->role = FOLLOWER
          was_leader = false
  Step 3: role is FOLLOWER → passes
  Step 4: voted_for(-1) != from_idx(1)? NO (voted_for is -1 → doesn't match "!= -1" check)
  Step 5: on_vote_eligible → always returns 1
  Step 6: on_persist(term=1, from_idx=1):
    ha->term = 1  ← SET!
    c = ha->raft_c = NULL!  ← NOT YET SET (ha_start_election_async not called)
    voted_for(1) != my_priority(2) → memset(voted_for_name, 0, ...) ← CLEARED!
Result: GRANT ← VOTE GRANTED

SIDE EFFECT: ha->term=1, BUT voted_for_name is EMPTY (BUG)

T+0.865s (00:15:59.374) — ctrl-2 wins term=1

ctrl-2 receives ctrl-3's vote reply: vote_granted=1
votes_granted: self(1) + ctrl-3(1) = 2 = quorum (ceil(3/2)=2)

raft_on_vote_reply → quorum reached → on_become_leader(term=1):
  raft_cb_become_leader(term=1):
    is_first_boot = !phase2_done = true
    cluster_init_phase2(c)  ← first boot init
    phase2_done = 1
    ha->role = CTRL_PRIMARY_COMMITTING
    CMD: INFO "→ CTRL_PRIMARY_COMMITTING (term=1, first_boot=1)"
    
    Promote vote eps → standby channels
    CMD: INFO "promoted vote ep[0] → standby channel"
    CMD: INFO "promoted vote ep[1] → standby channel"
    
    push_config_to_standbys: config blob sent to ctrl-1 and ctrl-3
    ha_send_ctrlhello_to_all_standbys: ctrlhello sent
    
    ha_start_primary_heartbeat: armed every 3000ms
    
    Schedule committing_timeout(10000ms):
      deadline: T+10.865s (00:16:09.374)
    
    CMD: INFO "Config committed on majority (tag=4986624fd309142c, pushed=2/2)"
    CMD: INFO "primary heartbeat armed (interval=3000ms)"

T+0.915s (00:15:59.424) — ctrl-3 receives ctrlhello (still in nap)

During ctrl-3's nap (iomgr running):
  ctrl-2 sends ctrlhello on promoted vote ep → arrives at ctrl-3 listener
  
  handle_ctrlhello:
    primary_ctrl_fd = fd ← SET
    CMD: INFO "primary control channel established (fd=6)"
    CMD: INFO "standby ctrl-2 catch-up complete (applied_lsn=0 → committed_lsn=0)"
    
  handle_repl_config_push:
    config saved and loaded (tag=4986624fd309142c)
    
  ha_arm_heartbeat_timeout_vtask:
    liveness poll armed (timeout=10000ms, poll=1500ms)
    
  NOTE: ha->role stays at CTRL_STANDBY (set by ha_init).
  voted_for_name stays at "" (cleared by BUG).
  ha->term stays at 1 (set by raft_cb_persist).

T+1.603s (00:16:00.119) — ctrl-3 nap ends

already_voted check: voted_for_name="" (EMPTY!) → NO → starts election
  NOTE: primary_ctrl_fd != -1, raft.term = 1, but these aren't checked!

ha_start_election_async:
  ha->raft_c = c  ← NOW non-NULL
  rcfg.initial_term = ha->term = 1  ← SET TO 1!
  rcfg.initial_voted_for = -1 (voted_for_name is empty)
  raft_init: n_peers=3, self_idx=2, s->term=1
  raft_start_election:
    s->term: 1 → 2  ← TERM=2!
    s->voted_for = 2 (self)
    s->votes_granted = 1
    on_persist(term=2, voted_for=2):
      ha->term = 2
      ha->voted_for_name = "ctrl-3"

  CMD: INFO "→ CTRL_ELECTING"
  CMD: INFO "returning"
→ cluster_run
→ sends vote requests at TERM=2 to ctrl-1 and ctrl-2

T+1.610s — ctrl-3's votes at term=2 arrive

To ctrl-1:

ctrl-1: s->term=1, role=CANDIDATE, voted_for=0(self)
raft_on_vote_request(term=2, from_idx=2):
  term(2) > s->term(1) → term upgrade:
    s->term = 2, voted_for = -1, role = FOLLOWER
    was_leader = false (was CANDIDATE)
  role=FOLLOWER → passes
  voted_for=-1 → passes
  on_persist(term=2, from_idx=2):
    ha->term = 2
    ha->voted_for_name = "ctrl-3" (c is non-NULL for ctrl-1)
Result: GRANT

To ctrl-2:

ctrl-2: s->term=1, role=LEADER (in COMMITTING), voted_for=1(self)
raft_on_vote_request(term=2, from_idx=2):
  term(2) > s->term(1) → term upgrade:
    s->term = 2, voted_for = -1, role = FOLLOWER
    was_leader = true → on_become_follower!
      raft_cb_become_follower:
        cancel election timeout (none active)
        ha->role = CTRL_STANDBY  ← STEPS DOWN!
        CMD: INFO "→ CTRL_STANDBY"  (NOT IN LOG!)
        ha_arm_heartbeat_timeout_vtask
  role=FOLLOWER → passes
  on_persist(term=2, from_idx=2):
    result: ha->term=2, voted_for_name="ctrl-3"
Result: GRANT

NOTE: committing timeout from term=1 is NOT cancelled!
      It will fire at T+10.865s (00:16:09.374).

T+1.615s (00:16:00.170) — ctrl-3 wins term=2

ctrl-3: self(1) + ctrl-1(1) = 2 = quorum
raft_cb_become_leader(term=2):
  ha->role = CTRL_PRIMARY_COMMITTING
  CMD: INFO "→ CTRL_PRIMARY_COMMITTING (term=2, first_boot=1)"
  
  push_config_to_standbys: 
    repl_wait_majority_ack TIMEOUT (500ms)
    CMD: WARN "timeout waiting for majority quorum"
    CMD: WARN "Config push: timeout waiting for majority ACK"
  
  ha_start_primary_heartbeat(3000ms)
  
  Schedule committing_timeout(10000ms):
    deadline: T+11.615s (00:16:10.725)

T+5.200s (00:16:03.722) — ctrl-1 election timeout

ctrl-1's initial election timeout fires (5000ms from T+0.000s)
But ctrl-1 already stepped down to FOLLOWER at T+1.610s (saw term=2).
raft_cb_become_follower:
  cluster_init_phase2 (first_boot)
  ha->role = CTRL_STANDBY
  CMD: INFO "→ CTRL_STANDBY (term=2, first_boot=1)"
  ha_arm_heartbeat_timeout_vtask (10000ms)

T+10.865s (00:16:09.425) — ctrl-2 committing timeout FIRES

committing_timeout_fn checks t->ha->role:
  If raft.c fix worked: ha->role = CTRL_STANDBY → NO-OP (correct!)
  If raft.c fix didn't work: ha->role = CTRL_PRIMARY_COMMITTING → promotes

Actual log: ctrl-2 → CTRL_PRIMARY (term=2)
  CMD: WARN "committing timeout — majority ack not received..."
  CMD: INFO "→ CTRL_PRIMARY (term=2)"
  
CONCLUSION: raft.c fix did NOT work in this test run,
  or ctrl-2 never received ctrl-3's vote request at term=2.

T+11.615s (00:16:10.725) — ctrl-3 committing timeout fires

committing_timeout_fn: ha->role = CTRL_PRIMARY_COMMITTING → promotes
ha_do_promote: term 2→3
CMD: INFO "→ CTRL_PRIMARY (term=3)"

Root Causes Identified

Bug 1: ha->raft_c is NULL during vote processing in nap

During the stagger nap, other nodes' vote requests arrive and are processed. raft_cb_persist uses ha->raft_c to look up candidate names, but this is NULL until ha_start_election_async runs (after the nap).

Effect: ha->term is correctly set, but ha->voted_for_name is CLEARED. The already_voted check in myapp_run sees an empty voted_for_name and starts an unnecessary election.

Fix: Set ha->raft_c = c earlier, at startup, before iomgr starts.

Bug 2: Committing timeout not cancelled on step-down

When raft_on_vote_request (with my fix) calls on_become_follower for a node that was LEADER/COMMITTING, the committing timeout is not cancelled. The delaymgr task still fires later.

Fix: In raft_cb_become_follower, cancel any pending committing timeout.

Bug 3: already_voted check incomplete

Only checks ha->voted_for_name — misses the case where:

• ha->raft.term > 0 (saw a higher term from another candidate)
• ha->primary_ctrl_fd >= 0 (ctrlhello already received from winner)

Fix: Also check raft.term > 0 and primary_ctrl_fd >= 0.