Rongsong Shen
e31673dd88
Captures all uncommitted work from ha-config-bootstrap, ha-heartbeat-liveness, and associated spec/tooling updates: - src: ha.c, ha.h, cluster.c, config_repl.c, myapp.c, raft.c — heartbeat liveness, RDHUP integration, committing phase fixes - tests: test_ha_role.c, test_config_repl.c, test_ha_rdhup_integration.c, test_p1_integration.c, test_p3_hardening.c, scheduler test - specs: election-iomgr-refactor, ha-heartbeat-liveness, ha-peer-connection-reuse, raft-library (new); ha-config-bootstrap and election-iomgr-refactor task/research updates - tooling: .wolf/ state, ha/data cluster fixtures, raft/raft.tla, src/build symlink, xce-build skill update
358 lines
12 KiB
Markdown
358 lines
12 KiB
Markdown
# 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`.
|