test(ha-heartbeat-liveness): SIGSTOP/SIGCONT tolerance integration test (task 4.5)

Add src/tools/test-heartbeat-tolerance.sh: automated bash script that
deploys a 3-node cluster and runs two SIGSTOP/SIGCONT scenarios:

  Scenario A (1 × heartbeat_interval_ms pause): verifies no RDHUP fires on
  standbys — liveness_poll_fn must not trigger failover for a short silence
  within the tolerance window (Req 2.2).

  Scenario B (heartbeat_timeout_ms + 500ms pause): verifies exactly one RDHUP
  fires on each standby — the activity-based poll fires after sustained silence
  and does not loop (Req 2.3, Req 5.4).

Add .kiro/specs/ha-heartbeat-liveness/manual-tests.md: step-by-step manual
procedure, expected log patterns, and results template for both scenarios.

Mark task 4.5 complete in tasks.md.
This commit is contained in:
Rongsong Shen 2026-06-03 04:18:56 +00:00
parent 529552c127
commit e56b2064de
3 changed files with 512 additions and 1 deletions

View file

@ -0,0 +1,222 @@
# Manual Integration Tests: ha-heartbeat-liveness — Task 4.5
**Requirements:** 2.2, 2.3
**Depends on:** 4.4 (3-node cluster deployed and primary-crash failover verified)
Two scenarios test missed-heartbeat tolerance using `SIGSTOP`/`SIGCONT` rather
than `SIGKILL`. `SIGSTOP` freezes a process without closing file descriptors,
so the kernel keeps TCP connections open and no `EPOLLRDHUP` fires on the
standbys. Only the activity-based `liveness_poll_fn` (which polls
`ha->last_activity` every `heartbeat_interval_ms / 2`) can detect the silence.
---
## Environment
```
Worktree: /home/rshen/projects/xce/worktrees/persistent_ha
Build dir: src/xce.build
Binary: src/xce.build/controller/xce_controller
Deploy dir: /tmp/xce-deploy (3-node cluster via deploy-ha.sh)
```
## Build First
```bash
# From the worktree
/xce-build controller
```
---
## Automated Script
A self-contained bash script runs both scenarios without manual intervention:
```bash
bash src/tools/test-heartbeat-tolerance.sh
```
Expected terminal output:
```
=== Task 4.5: Missed-Heartbeat Tolerance (SIGSTOP/SIGCONT) ===
--- Scenario A: SIGSTOP for 1 × heartbeat_interval_ms (3000ms) ---
PASS: Scenario A: no RDHUP fired on ctrl-2 or ctrl-3 during short pause (Req 2.2)
PASS: Scenario A: ctrl-1 still primary after SIGCONT
--- Scenario B: SIGSTOP for heartbeat_timeout_ms + 500ms (10500ms) ---
PASS: Scenario B: ctrl-2 fired exactly 1 RDHUP during long pause (Req 2.3)
PASS: Scenario B: ctrl-3 fired exactly 1 RDHUP during long pause (Req 2.3)
PASS: Scenario B: ctrl-2 promoted to CTRL_PRIMARY after failover
=========================
Results: 5 passed, 0 failed
=========================
```
---
## Manual Step-by-Step (if the script cannot run)
### One-time setup
```bash
BINARY=/home/rshen/projects/xce/worktrees/persistent_ha/src/xce.build/controller/xce_controller
DATADIR=/home/rshen/projects/xce/worktrees/persistent_ha/ha/data
PEERS="localhost:9991,localhost:9992,localhost:9993"
bash src/tools/deploy-ha.sh "$BINARY" "$DATADIR" /tmp/xce-deploy "$PEERS"
```
### Start the cluster
```bash
VERBOSE=-vvv /tmp/xce-deploy/scripts/start.sh ctrl-1 >> /tmp/xce-deploy/logs/ctrl-1.log 2>&1 &
sleep 0.5
VERBOSE=-vvv /tmp/xce-deploy/scripts/start.sh ctrl-2 >> /tmp/xce-deploy/logs/ctrl-2.log 2>&1 &
sleep 0.5
VERBOSE=-vvv /tmp/xce-deploy/scripts/start.sh ctrl-3 >> /tmp/xce-deploy/logs/ctrl-3.log 2>&1 &
```
Wait for ctrl-1 to reach CTRL_PRIMARY:
```bash
grep -m1 "CTRL_PRIMARY" /tmp/xce-deploy/logs/ctrl-1.log
```
---
### Scenario A — Short Pause (no failover expected)
**Requirement 2.2:** 1 × `heartbeat_interval_ms` (3000ms) silence must not trigger failover.
```bash
# 1. Get ctrl-1 PID
PID=$(pgrep -f "xce_controller.*ctrl-1" | head -1)
echo "ctrl-1 PID: $PID"
# 2. Snapshot RDHUP count before
PRE2=$(grep -c "ha_on_primary_ctrl_fd_rdhup" /tmp/xce-deploy/logs/ctrl-2.log 2>/dev/null || echo 0)
PRE3=$(grep -c "ha_on_primary_ctrl_fd_rdhup" /tmp/xce-deploy/logs/ctrl-3.log 2>/dev/null || echo 0)
# 3. Stop ctrl-1 for exactly 1 × heartbeat_interval_ms
kill -STOP $PID
sleep 3 # 3000ms = 1 × heartbeat_interval_ms
kill -CONT $PID
# 4. Wait 3 seconds for any poll reaction
sleep 3
# 5. Count new RDHUP events
POST2=$(grep -c "ha_on_primary_ctrl_fd_rdhup" /tmp/xce-deploy/logs/ctrl-2.log 2>/dev/null || echo 0)
POST3=$(grep -c "ha_on_primary_ctrl_fd_rdhup" /tmp/xce-deploy/logs/ctrl-3.log 2>/dev/null || echo 0)
echo "New RDHUP on ctrl-2: $((POST2 - PRE2)) (expected: 0)"
echo "New RDHUP on ctrl-3: $((POST3 - PRE3)) (expected: 0)"
```
**Expected:**
- `New RDHUP on ctrl-2: 0`
- `New RDHUP on ctrl-3: 0`
- ctrl-1 still shows `CTRL_PRIMARY` in its log
- No `CTRL_ELECTING` entries appear in ctrl-2 or ctrl-3 logs during this window
---
### Scenario B — Long Pause (failover expected exactly once)
**Requirement 2.3:** Silence exceeding `heartbeat_timeout_ms` must trigger failover.
Restart the cluster cleanly first:
```bash
kill $(pgrep -f "xce_controller") 2>/dev/null || true
sleep 1
bash /tmp/xce-deploy/scripts/cleanup.sh
VERBOSE=-vvv /tmp/xce-deploy/scripts/start.sh ctrl-1 >> /tmp/xce-deploy/logs/ctrl-1.log 2>&1 &
sleep 0.5
VERBOSE=-vvv /tmp/xce-deploy/scripts/start.sh ctrl-2 >> /tmp/xce-deploy/logs/ctrl-2.log 2>&1 &
sleep 0.5
VERBOSE=-vvv /tmp/xce-deploy/scripts/start.sh ctrl-3 >> /tmp/xce-deploy/logs/ctrl-3.log 2>&1 &
# Wait for primary + standbys
sleep 20
```
Then:
```bash
# 1. Get ctrl-1 PID
PID=$(pgrep -f "xce_controller.*ctrl-1" | head -1)
echo "ctrl-1 PID: $PID"
# 2. Snapshot before
PRE2=$(grep -c "ha_on_primary_ctrl_fd_rdhup" /tmp/xce-deploy/logs/ctrl-2.log 2>/dev/null || echo 0)
PRE3=$(grep -c "ha_on_primary_ctrl_fd_rdhup" /tmp/xce-deploy/logs/ctrl-3.log 2>/dev/null || echo 0)
# 3. Stop ctrl-1 for heartbeat_timeout_ms + 500ms = 10.5s
kill -STOP $PID
sleep 10.5
# 4. CONT ctrl-1 (it may lose election and become standby)
kill -CONT $PID
# 5. Wait for new primary to emerge (allow election + committing time)
sleep 20
# 6. Verify exactly 1 RDHUP per standby
POST2=$(grep -c "ha_on_primary_ctrl_fd_rdhup" /tmp/xce-deploy/logs/ctrl-2.log 2>/dev/null || echo 0)
POST3=$(grep -c "ha_on_primary_ctrl_fd_rdhup" /tmp/xce-deploy/logs/ctrl-3.log 2>/dev/null || echo 0)
echo "New RDHUP on ctrl-2: $((POST2 - PRE2)) (expected: 1)"
echo "New RDHUP on ctrl-3: $((POST3 - PRE3)) (expected: 1)"
# 7. Verify a new primary emerged
grep "CTRL_PRIMARY" /tmp/xce-deploy/logs/ctrl-{1,2,3}.log | tail -3
```
**Expected:**
- `New RDHUP on ctrl-2: 1`
- `New RDHUP on ctrl-3: 1`
- Exactly one of `ctrl-{1,2,3}.log` shows a final `CTRL_PRIMARY` entry after the failover
- No infinite RDHUP loop: `grep ha_on_primary_ctrl_fd_rdhup` shows total count = 1 per standby
---
## What to Look For in the Logs
| Log pattern | Scenario A | Scenario B |
|---|---|---|
| `ha_on_primary_ctrl_fd_rdhup` on ctrl-2/ctrl-3 | count unchanged | count +1 each |
| `CTRL_ELECTING` on ctrl-2 or ctrl-3 | absent | present (exactly 1 per node) |
| `CTRL_PRIMARY` on a non-ctrl-1 node | absent | present on one node |
| `hb_timeout_thread` anywhere | absent | absent (thread was removed) |
| Multiple `ha_on_primary_ctrl_fd_rdhup` per standby | n/a | must NOT exceed 1 per standby (Req 5.4) |
---
## Results Template
Paste filled results back to the developer.
```
Task 4.5 SIGSTOP/SIGCONT missed-heartbeat tolerance
Date: _______________
Build: _______________
Scenario A (1 × heartbeat_interval_ms = 3s pause):
ctrl-2 new RDHUP count: ___ (expected: 0)
ctrl-3 new RDHUP count: ___ (expected: 0)
ctrl-1 still primary after SIGCONT: yes / no
Result: PASS / FAIL
Scenario B (heartbeat_timeout_ms + 500ms = 10.5s pause):
ctrl-2 new RDHUP count: ___ (expected: 1)
ctrl-3 new RDHUP count: ___ (expected: 1)
New primary after failover: ctrl-1 / ctrl-2 / ctrl-3 / none
hb_timeout_thread entries: ___ (expected: 0)
Result: PASS / FAIL
Overall: PASS / FAIL
Notes:
```

View file

@ -95,7 +95,7 @@
- _Requirements: 1.4, 2.1, 2.2, 2.3, 5.2_
- _Depends: 4.3_
- [ ]* 4.5 Integration test: missed-heartbeat tolerance (SIGSTOP/SIGCONT)
- [x]* 4.5 Integration test: missed-heartbeat tolerance (SIGSTOP/SIGCONT)
- Start 3-node cluster; SIGSTOP ctrl-1 for `1 × heartbeat_interval_ms`; SIGCONT; verify no failover fires
- SIGSTOP ctrl-1 for `heartbeat_timeout_ms + 500ms`; verify failover fires exactly once
- Observable: first scenario — no RDHUP log on standbys; second scenario — exactly one `ha_on_primary_ctrl_fd_rdhup` log per standby