fix(xce-test-ha): retry chaotic-mode verify_classify before counting job loss (bug-1487)

30-round chaotic soak reported committed_job_loss=1 at round 25, but the
flagged job was confirmed present on every later verify and the final
sweep -- a real loss never comes back. Root-caused from ctrl-1/ctrl-2/ctrl-3
logs, no controller change needed: a newly-elected primary cannot fold a
prior-term entry into its own committed_lsn merely because it holds it
durably (Raft Figure-8 safety via ha_arm_own_term_gate) -- it needs a fresh
majority ack for its own-term WAL_NOOP first. That normally closes in
<200ms, but chaotic mode's overlapping-restart design let it stretch to
6.232s this run (the peer whose ack was needed was itself mid-catch-up from
its own recent restart). verify_classify ran its expect-job check
immediately on primary detection with no settle/retry, unlike verify_no_loss
(bug-1422) or wait_for_full_convergence, so it landed inside that window.

Added a bounded retry (5 attempts, 2s settle) around the LOSS classification
only, mirroring verify_no_loss's precedent -- a job still missing after that
still counts as a genuine loss. Verified with a fresh 30-round chaotic
re-soak: committed_divergence=0 committed_job_loss=0 result=PASS.
This commit is contained in:
Rongsong Shen 2026-07-31 05:16:14 +00:00
parent 4835cf2b30
commit 0206b9e166
3 changed files with 142 additions and 6 deletions

View file

@ -919,8 +919,44 @@ walcheck_count() {
# the expect-job result via the verdict parser. Increments V_JOBLOSS on a REAL
# loss (reachable primary, tracked job "not found") and V_BUG854 when the client
# cannot locate the primary (discovery fault — EXCLUDED). Never hard-fails.
#
# Retries a LOSS classification up to 5 times (2s settle between attempts) before
# counting it, mirroring verify_no_loss's bug-1422 "whole check" retry — same
# rationale, sharpened by a real bug-1487 live-repro measurement specific to
# chaotic mode: unlike wait_for_new_primary (which only waits for the new
# primary to be SERVING at a higher term) and unlike the sequential loop's
# wait_for_full_convergence (which waits for 2 consecutive fully-converged
# probes before the NEXT kill), this function runs immediately once a new
# primary is detected, with no settle window of its own.
#
# A newly-elected primary cannot advance its OWN committed_lsn past entries
# inherited from a PRIOR term merely because it holds them durably (Raft
# Figure-8 safety, `ha_arm_own_term_gate` in ha.c: "the universal commit
# barrier still requires per-entry majority of a new-term entry"). It appends
# an own-term WAL_NOOP on promotion and only folds in the earlier, already-
# majority-committed prefix once THAT noop itself gets a fresh majority ack
# under the new term. In steady state this closes in well under 200ms (round
# 24 of this same run: safe_committed_lsn -> committed_lsn advance in 167ms).
# But chaotic mode deliberately restarts the PREVIOUS round's downed node
# without waiting for it to reconverge before landing the NEXT kill (the
# "overlapping" design) -- so if that still-catching-up node is the one whose
# ack the new leader needs for its own-term barrier, the window stretches to
# however long that node's WAL catch-up stream takes. Live-repro evidence
# (bug-1487, this exact run): round 25 killed ctrl-1 while ctrl-3 was still
# reconnecting from round 25's own overlapping restart; ctrl-2 was elected at
# 04:47:52.470 with safe_committed_lsn=99 "(from 2 granted voters)" while its
# OWN committed_lsn (last known as a standby) stayed at 100 -- excluding the 3
# jobs (lsn 101-103) ctrl-1 had already majority-committed (self + ctrl-2's
# own ack) moments before dying. committed_lsn did not jump to 104 (folding in
# 101-103) until ctrl-3's catch-up stream let it ack the new leader's own-term
# noop at 04:47:58.702 -- 6.232s later. verify_classify's single, immediate
# expect-job query landed inside that window and counted a false LOSS for a
# job that was genuinely durable/majority-committed the whole time and was
# confirmed present on every later verify (rounds 26-30 and the final sweep).
# 5 attempts x 2s settle gives ~8s of margin above the measured 6.232s gap
# while staying bounded -- a job still missing after that is a REAL loss.
verify_classify() {
local primary out cls want="${#ALL_JOBIDS[@]}"
local primary out cls want="${#ALL_JOBIDS[@]}" attempt
[ "$want" -eq 0 ] && return 0
primary="$(discover_primary)"
if [ -z "$primary" ]; then
@ -939,8 +975,15 @@ expect-job $jid"
done
script+="
quit"
out="$(printf '%s\n' "$script" | xtest)"
cls="$(printf '%s' "$out" | verdict_classify_verify 1)"
for attempt in 1 2 3 4 5; do
out="$(printf '%s\n' "$script" | xtest)"
cls="$(printf '%s' "$out" | verdict_classify_verify 1)"
[ "$cls" = "LOSS" ] || break
if [ "$attempt" -lt 5 ]; then
log "verify_classify attempt $attempt/5: reachable primary $primary reports a tracked job missing (likely post-election own-term commit-barrier lag while a peer is still catching up, bug-1487 class) — settling 2s and rechecking before counting a loss"
sleep 2
fi
done
case "$cls" in
LOSS)
V_JOBLOSS=$((V_JOBLOSS + 1))