test(xce-test-ha): scheduler replay-parity gate in sequential/chaotic soaks

When the live worker + scheduler pair is up, the soak now starts the
scheduler with --record-dir, records (xceadmin scheduler record start)
from each scheduler (re)join until just before the next primary kill,
stops it cleanly so the .replay is flushed, and at the end replays every
clean recording through `xce_scheduler --sim --sim-verify`. Any decision
MISMATCH, a failed sim run, or zero clean recordings FAILs the soak:

  [xce-test-ha] SIMVERIFY files=N mismatches=M errors=E unclean=U

Recordings that could not be stopped cleanly are counted as unclean and
never verified (their unflushed tail would give false mismatches), except
a stop whose reply was lost mid-failover: when the same scheduler pid
answers "not recording" and logged no recording abort, the first stop
landed and the file is kept. Mismatches are counted from both the sim's
log file and stderr (the logger creates its file lazily).
XCE_HA_SCHED_REPLAY_VERIFY=0 disables the gate.

First runs caught bug-1851 and bug-1852.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-09-24 08:41:55 +00:00
parent 9c02184fb4
commit d9ff02cdc1
No known key found for this signature in database
GPG key ID: 5BCDAAE0123E9FE2
2 changed files with 185 additions and 4 deletions

View file

@ -499,6 +499,28 @@ invariant is asserted with an immediate `fail()` inside
`run_config_upgrade_wal_trim_round()`, so a violation aborts the run before `run_config_upgrade_wal_trim_round()`, so a violation aborts the run before
this line is ever reached. this line is ever reached.
### Scheduler replay-parity gate (sequential + chaotic, on by default)
Whenever sequential/chaotic mode has the real worker + scheduler pair live,
the soak also proves the scheduler simulator reproduces the live scheduler's
decisions (bug-1846 follow-up). The scheduler starts with
`--record-dir $TOP/replays`; recording starts (`xceadmin scheduler record
start`) at every scheduler (re)join and is stopped cleanly just before the
next primary kill, then moved to `$TOP/replays/complete/`. At the end each
clean recording is replayed with `xce_scheduler --sim --sim-verify`; the run
prints
```
[xce-test-ha] SIMVERIFY files=<n> mismatches=<m> errors=<e> unclean=<u>
```
and FAILs if `files=0`, `mismatches>0` or `errors>0`. `unclean` recordings
(the scheduler was killed or unreachable before a clean stop) are counted
but never verified — their unflushed tail would give false mismatches.
Per-file sim logs: `$TOP/logs/simverify-<n>.log`. Disable with
`XCE_HA_SCHED_REPLAY_VERIFY=0`; it is skipped (with a log line) when
xceadmin isn't built.
### Verdict self-test (no cluster) ### Verdict self-test (no cluster)
The verdict parser has a deterministic, pure-bash self-test that feeds fixture The verdict parser has a deterministic, pure-bash self-test that feeds fixture

167
.claude/skills/xce-test-ha/run-ha-soak.sh Executable file → Normal file
View file

@ -206,6 +206,20 @@
# loss, not a timing coincidence) before the worker's # loss, not a timing coincidence) before the worker's
# own reconnect logic rejoins the new primary. # own reconnect logic rejoins the new primary.
# #
# Scheduler replay-parity gate (sequential/chaotic, whenever the worker +
# scheduler pair above is live; bug-1846 follow-up):
# The live scheduler is started with --record-dir $TOP/replays and records
# (xceadmin scheduler record start) from every (re)join until just before
# the next primary kill, where it is stopped cleanly (record stop) so the
# .replay is fully flushed. After the run, every cleanly-stopped recording
# is replayed through `xce_scheduler --sim --sim-verify`; any decision
# MISMATCH (or a sim run that fails/crashes, or zero clean recordings) FAILs
# the soak. A recording that could not be stopped cleanly (scheduler not
# reachable before its kill) is counted as "unclean" and skipped, never
# verified -- its unflushed tail would produce false mismatches.
# XCE_HA_SCHED_REPLAY_VERIFY 1 (default) | 0 disables the gate.
# Artifacts: $TOP/replays/complete/*.replay + $TOP/logs/simverify-*.log.
#
# Env overrides: # Env overrides:
# XCE_HA_TOP deploy dir (default /home/claude/tmp/xce-ha-deploy) # XCE_HA_TOP deploy dir (default /home/claude/tmp/xce-ha-deploy)
# XCE_HA_MODE sequential | chaotic | force-snapshot (default sequential) # XCE_HA_MODE sequential | chaotic | force-snapshot (default sequential)
@ -446,6 +460,17 @@ WORKER_RESYNC_SLEEP="${XCE_HA_WORKER_RESYNC_SLEEP:-20}"
WORKER_RESYNC_JOBIDS=() # chaotic mode: jobids tracked for the final settled sweep WORKER_RESYNC_JOBIDS=() # chaotic mode: jobids tracked for the final settled sweep
V_RESYNC_STUCK=0 # chaotic mode: worker-resync jobs still non-terminal at final sweep V_RESYNC_STUCK=0 # chaotic mode: worker-resync jobs still non-terminal at final sweep
# ── Scheduler replay-parity gate (see header "Scheduler replay-parity gate") ─
SCHED_REPLAY_VERIFY="${XCE_HA_SCHED_REPLAY_VERIFY:-1}"
case "$MODE" in sequential|chaotic) ;; *) SCHED_REPLAY_VERIFY=0 ;; esac
SCHED_REPLAY_DIR="$TOP/replays"
SCHED_REC_FILE="" # basename of the in-progress recording, "" when idle
SCHED_REC_PID="" # xce_scheduler pid that owns SCHED_REC_FILE
V_SIMVERIFY_FILES=0 # clean recordings replayed through --sim-verify
V_SIMVERIFY_MISMATCH=0 # total decision MISMATCH lines across all of them
V_SIMVERIFY_ERR=0 # sim runs that exited non-zero / timed out
V_SIMVERIFY_UNCLEAN=0 # recordings abandoned without a clean record stop
log() { echo "[xce-test-ha] $*"; } log() { echo "[xce-test-ha] $*"; }
fail() { echo "[xce-test-ha] FAIL: $*" >&2; cleanup; exit 1; } fail() { echo "[xce-test-ha] FAIL: $*" >&2; cleanup; exit 1; }
@ -562,13 +587,18 @@ worker_log_count() {
restart_scheduler_for_new_primary() { restart_scheduler_for_new_primary() {
local before i local before i
before="$(wc -l < "$TOP/logs/scheduler.log" 2>/dev/null || echo 0)" before="$(wc -l < "$TOP/logs/scheduler.log" 2>/dev/null || echo 0)"
sched_rec_abandon
pkill -9 -f -- "$(sched_pattern)" 2>/dev/null pkill -9 -f -- "$(sched_pattern)" 2>/dev/null
sleep 0.5 sleep 0.5
setsid nohup bash "$TOP/scripts/start-scheduler.sh" -v \ # shellcheck disable=SC2046 # sched_extra_args is intentionally word-split
setsid nohup bash "$TOP/scripts/start-scheduler.sh" -v $(sched_extra_args) \
</dev/null >>"$TOP/logs/scheduler.stderr" 2>&1 & </dev/null >>"$TOP/logs/scheduler.stderr" 2>&1 &
for i in $(seq 1 20); do for i in $(seq 1 20); do
tail -n +"$((before + 1))" "$TOP/logs/scheduler.log" 2>/dev/null \ if tail -n +"$((before + 1))" "$TOP/logs/scheduler.log" 2>/dev/null \
| grep -q "sched_init: joined cluster" && return 0 | grep -q "sched_init: joined cluster"; then
sched_rec_start
return 0
fi
sleep 1 sleep 1
done done
log "worker-resync: scheduler restart did not confirm join within 20s (bug-1760 workaround) -- worker-resync coverage may fail this round" log "worker-resync: scheduler restart did not confirm join within 20s (bug-1760 workaround) -- worker-resync coverage may fail this round"
@ -584,7 +614,8 @@ start_worker_and_scheduler() {
log "worker-resync: starting worker ($WORKER_NAME) + scheduler" log "worker-resync: starting worker ($WORKER_NAME) + scheduler"
setsid nohup bash "$TOP/scripts/start-worker.sh" "$WORKER_NAME" -vvv \ setsid nohup bash "$TOP/scripts/start-worker.sh" "$WORKER_NAME" -vvv \
</dev/null >>"$TOP/logs/$WORKER_NAME.stderr" 2>&1 & </dev/null >>"$TOP/logs/$WORKER_NAME.stderr" 2>&1 &
setsid nohup bash "$TOP/scripts/start-scheduler.sh" -v \ # shellcheck disable=SC2046 # sched_extra_args is intentionally word-split
setsid nohup bash "$TOP/scripts/start-scheduler.sh" -v $(sched_extra_args) \
</dev/null >>"$TOP/logs/scheduler.stderr" 2>&1 & </dev/null >>"$TOP/logs/scheduler.stderr" 2>&1 &
# Real xcecd started without systemd/dbus present still joins the cluster # Real xcecd started without systemd/dbus present still joins the cluster
@ -611,6 +642,114 @@ start_worker_and_scheduler() {
WORKER_ENABLED=1 WORKER_ENABLED=1
log "worker-resync: worker + scheduler joined -- rejoin-resync coverage enabled for this run" log "worker-resync: worker + scheduler joined -- rejoin-resync coverage enabled for this run"
sched_rec_start
}
# ── Scheduler replay-parity gate helpers ─────────────────────────────────────
# See the header's "Scheduler replay-parity gate". Every helper is a no-op
# when the gate is disabled, so call sites need no guards of their own.
# Extra xce_scheduler argv for start-scheduler.sh (whose `$*` passes it on).
sched_extra_args() {
[ "$SCHED_REPLAY_VERIFY" = "1" ] || return 0
mkdir -p "$SCHED_REPLAY_DIR/complete"
echo "--record-dir $SCHED_REPLAY_DIR"
}
# Runs one `xceadmin scheduler record <action>` against the whole cluster
# (xceadmin fails over across the comma list and follows redirects).
sched_rec_admin() {
local xceadmin
xceadmin="$(find_xceadmin)" || return 2
timeout 20 "$xceadmin" scheduler record "$1" --controller "$MASTERS" 2>&1
}
sched_rec_start() {
[ "$SCHED_REPLAY_VERIFY" = "1" ] || return 0
local out
if ! find_xceadmin >/dev/null; then
log "sched-replay: xceadmin not built -- disabling replay-parity gate (run /xce-build xceadmin)"
SCHED_REPLAY_VERIFY=0
return 0
fi
if out="$(sched_rec_admin start)"; then
SCHED_REC_FILE="$(echo "$out" | awk '$1 == "file:" { print $2 }')"
SCHED_REC_FILE="$(basename "$SCHED_REC_FILE")"
SCHED_REC_PID="$(pgrep -f -- "$(sched_pattern)" | head -1)"
log "sched-replay: recording started ($SCHED_REC_FILE)"
else
SCHED_REC_FILE=""
log "sched-replay: record start failed -- this window goes unrecorded: $(echo "$out" | tail -1)"
fi
}
# Cleanly stops the in-progress recording (scheduler + its primary must still
# be alive) and moves the flushed file into complete/ for verification.
sched_rec_stop() {
[ "$SCHED_REPLAY_VERIFY" = "1" ] && [ -n "$SCHED_REC_FILE" ] || return 0
local out
if out="$(sched_rec_admin stop)" \
&& [ -f "$SCHED_REPLAY_DIR/$SCHED_REC_FILE" ]; then
mv "$SCHED_REPLAY_DIR/$SCHED_REC_FILE" "$SCHED_REPLAY_DIR/complete/"
log "sched-replay: recording stopped cleanly ($SCHED_REC_FILE, $(echo "$out" | awk '$1 == "events:" { print $2 }') events)"
elif echo "$out" | grep -q 'not recording' \
&& [ -f "$SCHED_REPLAY_DIR/$SCHED_REC_FILE" ] \
&& [ -n "$SCHED_REC_PID" ] \
&& [ "$(pgrep -f -- "$(sched_pattern)" | head -1)" = "$SCHED_REC_PID" ] \
&& ! grep -q "recording write to .*$SCHED_REC_FILE failed" \
"$TOP/logs/scheduler.log" 2>/dev/null; then
# The SAME scheduler process says it is no longer recording, and it
# never logged sched_record_abort_on_error() for this file -- the
# only other way a recording ends is a clean stop. That happens when
# our stop landed but its reply was lost mid-failover and xceadmin
# retried it (live: the file's last write matched the first stop;
# the file replayed with 0 mismatches). A restarted scheduler (pid
# changed) or an abort still counts as unclean below.
mv "$SCHED_REPLAY_DIR/$SCHED_REC_FILE" "$SCHED_REPLAY_DIR/complete/"
log "sched-replay: recording stopped (stop reply lost, xceadmin retry saw 'not recording'; same pid $SCHED_REC_PID, no abort logged) ($SCHED_REC_FILE)"
else
V_SIMVERIFY_UNCLEAN=$((V_SIMVERIFY_UNCLEAN + 1))
log "sched-replay: record stop failed -- $SCHED_REC_FILE left unclean, will not be verified: $(echo "$out" | tail -1)"
fi
SCHED_REC_FILE=""
}
# The scheduler is about to be killed while (possibly) still recording.
sched_rec_abandon() {
[ "$SCHED_REPLAY_VERIFY" = "1" ] && [ -n "$SCHED_REC_FILE" ] || return 0
V_SIMVERIFY_UNCLEAN=$((V_SIMVERIFY_UNCLEAN + 1))
log "sched-replay: scheduler restarted while still recording -- $SCHED_REC_FILE left unclean, will not be verified"
SCHED_REC_FILE=""
}
# Replays every clean recording through --sim-verify. Returns 0 only when at
# least one recording was verified and none had a mismatch or a failed run.
sched_replay_verify() {
[ "$SCHED_REPLAY_VERIFY" = "1" ] || return 0
local sched_bin f n=0 rc mm vlog
sched_rec_stop
sched_bin="$(awk '$1 == "exec" { print $2; exit }' "$TOP/scripts/start-scheduler.sh")"
[ -x "$sched_bin" ] || { log "sched-replay: scheduler binary not found ($sched_bin)"; V_SIMVERIFY_ERR=$((V_SIMVERIFY_ERR + 1)); return 1; }
for f in "$SCHED_REPLAY_DIR"/complete/*.replay; do
[ -f "$f" ] || continue
n=$((n + 1))
vlog="$TOP/logs/simverify-$n.log"
ASAN_OPTIONS=detect_leaks=0 timeout 900 "$sched_bin" --sim="$f" \
--sim-verify --sim-speed=0 --logfile "$vlog" \
>"$TOP/logs/simverify-$n.stderr" 2>&1
rc=$?
# The logger creates $vlog lazily (absent == nothing logged), so
# also count the stderr copy rather than trusting the file alone.
mm="$(cat "$vlog" "$TOP/logs/simverify-$n.stderr" 2>/dev/null \
| grep -c 'decision verification MISMATCH')"
mm="${mm:-0}"
V_SIMVERIFY_FILES=$((V_SIMVERIFY_FILES + 1))
V_SIMVERIFY_MISMATCH=$((V_SIMVERIFY_MISMATCH + mm))
[ "$rc" -eq 0 ] || V_SIMVERIFY_ERR=$((V_SIMVERIFY_ERR + 1))
log "sched-replay: $(basename "$f"): rc=$rc mismatches=$mm (log $vlog)"
done
log "SIMVERIFY files=$V_SIMVERIFY_FILES mismatches=$V_SIMVERIFY_MISMATCH errors=$V_SIMVERIFY_ERR unclean=$V_SIMVERIFY_UNCLEAN"
[ "$V_SIMVERIFY_FILES" -gt 0 ] && [ "$V_SIMVERIFY_MISMATCH" -eq 0 ] && [ "$V_SIMVERIFY_ERR" -eq 0 ]
} }
# Submits ONE real job, dispatched through the live scheduler onto the live # Submits ONE real job, dispatched through the live scheduler onto the live
@ -1416,6 +1555,10 @@ run_chaotic_rounds() {
# shortfall is NOT a loss (the job was never acked, so never tracked). # shortfall is NOT a loss (the job was never acked, so never tracked).
submit_jobs "$NJOBS" || log "round $round: submit shortfall (transient — not a loss)" submit_jobs "$NJOBS" || log "round $round: submit shortfall (transient — not a loss)"
# Replay-parity gate: flush this window's recording while the
# scheduler's primary is still alive to route the stop.
sched_rec_stop
# Kill the current primary, landing inside the next election window. # Kill the current primary, landing inside the next election window.
pid="$(pgrep -f -- "$(node_pattern "$PRIMARY")")" pid="$(pgrep -f -- "$(node_pattern "$PRIMARY")")"
if [ -n "$pid" ]; then if [ -n "$pid" ]; then
@ -3262,6 +3405,12 @@ if [ "$MODE" = "chaotic" ]; then
verdict_emit "chaotic" "$ROUNDS" "${#ALL_JOBIDS[@]}" \ verdict_emit "chaotic" "$ROUNDS" "${#ALL_JOBIDS[@]}" \
"$V_DIVERGENCE" "$V_JOBLOSS" "$V_BUG854" "$V_BUG924" "$V_DIVERGENCE" "$V_JOBLOSS" "$V_BUG854" "$V_BUG924"
VERDICT_RC=$? VERDICT_RC=$?
if ! sched_replay_verify; then
echo "[xce-test-ha] FAIL: chaotic scheduler replay-parity -- SIMVERIFY files=$V_SIMVERIFY_FILES mismatches=$V_SIMVERIFY_MISMATCH errors=$V_SIMVERIFY_ERR unclean=$V_SIMVERIFY_UNCLEAN (logs: $TOP/logs/simverify-*.log)" >&2
cleanup
trap - EXIT INT TERM
exit 1
fi
if [ "$VERDICT_RC" -eq 0 ]; then if [ "$VERDICT_RC" -eq 0 ]; then
log "PASS (chaotic): $ROUNDS rounds, ${#ALL_JOBIDS[@]} jobs, zero committed divergence, zero committed job loss (bug854=$V_BUG854 bug924=$V_BUG924 excluded)$([ "$WORKER_ENABLED" -eq 1 ] && echo ", ${#WORKER_RESYNC_JOBIDS[@]} worker-resync jobs reconciled")" log "PASS (chaotic): $ROUNDS rounds, ${#ALL_JOBIDS[@]} jobs, zero committed divergence, zero committed job loss (bug854=$V_BUG854 bug924=$V_BUG924 excluded)$([ "$WORKER_ENABLED" -eq 1 ] && echo ", ${#WORKER_RESYNC_JOBIDS[@]} worker-resync jobs reconciled")"
cleanup cleanup
@ -3339,6 +3488,10 @@ for round in $(seq 1 "$ROUNDS"); do
PREV_TERM="$(latest_primary_term)" PREV_TERM="$(latest_primary_term)"
PREV_TERM="${PREV_TERM:-0}" PREV_TERM="${PREV_TERM:-0}"
# Replay-parity gate: flush this window's recording while the
# scheduler's primary is still alive to route the stop.
sched_rec_stop
# Step 6: kill the current primary. Match on the BINARY + --myname + --workdir # Step 6: kill the current primary. Match on the BINARY + --myname + --workdir
# so the pattern cannot also hit this driver's own shell snapshot (which # so the pattern cannot also hit this driver's own shell snapshot (which
# carries the "--myname ctrl-N" substring in its argv and would otherwise be # carries the "--myname ctrl-N" substring in its argv and would otherwise be
@ -3381,6 +3534,12 @@ for round in $(seq 1 "$ROUNDS"); do
walcheck "${#ALL_JOBIDS[@]}" walcheck "${#ALL_JOBIDS[@]}"
done done
# Replay-parity gate: verify now, while the scheduler is still joined to the
# loop's last primary (the leadership maneuver below kills primaries without
# restarting the scheduler, so its last recording could not be stopped later).
sched_replay_verify \
|| fail "scheduler replay-parity: SIMVERIFY files=$V_SIMVERIFY_FILES mismatches=$V_SIMVERIFY_MISMATCH errors=$V_SIMVERIFY_ERR unclean=$V_SIMVERIFY_UNCLEAN (logs: $TOP/logs/simverify-*.log)"
# ── Leadership coverage: EVERY node must have served as primary ────────────── # ── Leadership coverage: EVERY node must have served as primary ──────────────
# The natural single-failover loop only ever elects the two highest-priority # The natural single-failover loop only ever elects the two highest-priority
# nodes (ctrl-1/ctrl-2) — the priority-staggered election timeout means ctrl-3 # nodes (ctrl-1/ctrl-2) — the priority-staggered election timeout means ctrl-3