diff --git a/.claude/skills/xce-test-ha/SKILL.md b/.claude/skills/xce-test-ha/SKILL.md index 97eac085..a1d3e7cf 100644 --- a/.claude/skills/xce-test-ha/SKILL.md +++ b/.claude/skills/xce-test-ha/SKILL.md @@ -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 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= mismatches= errors= unclean= +``` + +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-.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) The verdict parser has a deterministic, pure-bash self-test that feeds fixture diff --git a/.claude/skills/xce-test-ha/run-ha-soak.sh b/.claude/skills/xce-test-ha/run-ha-soak.sh old mode 100755 new mode 100644 index 1d843c1b..191364eb --- a/.claude/skills/xce-test-ha/run-ha-soak.sh +++ b/.claude/skills/xce-test-ha/run-ha-soak.sh @@ -206,6 +206,20 @@ # loss, not a timing coincidence) before the worker's # 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: # XCE_HA_TOP deploy dir (default /home/claude/tmp/xce-ha-deploy) # 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 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] $*"; } fail() { echo "[xce-test-ha] FAIL: $*" >&2; cleanup; exit 1; } @@ -562,13 +587,18 @@ worker_log_count() { restart_scheduler_for_new_primary() { local before i before="$(wc -l < "$TOP/logs/scheduler.log" 2>/dev/null || echo 0)" + sched_rec_abandon pkill -9 -f -- "$(sched_pattern)" 2>/dev/null 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) \ >"$TOP/logs/scheduler.stderr" 2>&1 & for i in $(seq 1 20); do - tail -n +"$((before + 1))" "$TOP/logs/scheduler.log" 2>/dev/null \ - | grep -q "sched_init: joined cluster" && return 0 + if tail -n +"$((before + 1))" "$TOP/logs/scheduler.log" 2>/dev/null \ + | grep -q "sched_init: joined cluster"; then + sched_rec_start + return 0 + fi sleep 1 done 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" setsid nohup bash "$TOP/scripts/start-worker.sh" "$WORKER_NAME" -vvv \ >"$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) \ >"$TOP/logs/scheduler.stderr" 2>&1 & # Real xcecd started without systemd/dbus present still joins the cluster @@ -611,6 +642,114 @@ start_worker_and_scheduler() { WORKER_ENABLED=1 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 ` 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 @@ -1416,6 +1555,10 @@ run_chaotic_rounds() { # 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)" + # 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. pid="$(pgrep -f -- "$(node_pattern "$PRIMARY")")" if [ -n "$pid" ]; then @@ -3262,6 +3405,12 @@ if [ "$MODE" = "chaotic" ]; then verdict_emit "chaotic" "$ROUNDS" "${#ALL_JOBIDS[@]}" \ "$V_DIVERGENCE" "$V_JOBLOSS" "$V_BUG854" "$V_BUG924" 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 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 @@ -3339,6 +3488,10 @@ for round in $(seq 1 "$ROUNDS"); do PREV_TERM="$(latest_primary_term)" 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 # 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 @@ -3381,6 +3534,12 @@ for round in $(seq 1 "$ROUNDS"); do walcheck "${#ALL_JOBIDS[@]}" 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 ────────────── # 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