#!/bin/bash # test-commit-durability.sh — bug-661 reproduction: committed jobs lost across failover. # # Spec: ha-commit-durability (.kiro/specs/ha-commit-durability/) # Reproduces the manual /kiro-discovery session of 2026-06-17 where a 3-node # controller cluster, driven by xce_test under rolling primary kills, PERMANENTLY # lost jobs that had already returned "jobsubmit ok" (committed) — joblist dropped # from 10 jobs to 3. # # Root cause (bug-661): "committed" != "durable". WAL fsync is asynchronous # (persist.c fsync_worker, interval wal_sync_ms); the standby ACKs a WAL entry # before fdatasync, and commit.c advances committed_lsn on majority *ACK* (page # cache only). A SIGKILL during the async window drops the un-fsync'd tail; on # restart persist_recover hits a CRC break and replays ~0 entries, yet the hollow # node can still win election and overwrite the good timeline. # # THE INVARIANT UNDER TEST (Requirement 1, durable commit): # Any job that returned "jobsubmit ok" MUST remain visible in joblist for the # remainder of the run, across any sequence of single-node SIGKILL + restart. # The cluster never loses a committed job (n_failures tolerated = floor(N/2) = 1). # # ── soak mode: A SOAK / RACE REPRODUCTION, NOT A DETERMINISTIC ONE ───────────── # bug-661 is a commit-durability RACE: wal_sync_ms defaults to 10ms # (config.h DEFAULT_WAL_SYNC_MS), so the committed-but-not-yet-fsync'd window is # ~10ms wide. Loss only occurs when a SIGKILL lands inside that window on enough # nodes. This soak fires bursts and kills with no delay across many rounds to hit # it; empirically it surfaces loss within a handful of rounds but NOT on every # single round. # # Interpret soak results asymmetrically: # FAIL ("DATA LOSS") => bug-661 PROVEN (a committed job vanished). Definitive. # PASS (all rounds) => the race did not fire this run; NOT proof of durability. # Re-run or raise ROUNDS. After the ha-commit-durability # fix (fsync-before-ACK), it MUST pass deterministically # regardless of timing — that is the real acceptance bar. # # ── deterministic mode: WHY IT PROVES THE GAP, NOT SIGKILL DATA-LOSS ─────────── # SCOPE CLARIFICATION (ratify with reviewer). The task asks for a deterministic # mode that "reports DATA LOSS without relying on race timing". But on a SINGLE # HOST, committed-job DATA LOSS via SIGKILL is PHYSICALLY NON-DETERMINISTIC, for # two independent reasons rooted in the code: # 1. persist_wal_async (persist.c:340) pwrites entry bytes INLINE (persist.c # :375,383) — they reach the OS PAGE CACHE immediately; only fdatasync is # deferred to fsync_worker. A SIGKILL does NOT evict page-cache pages: the # kernel still flushes them to disk, so an un-fdatasync'd pwrite'd entry is # STILL recoverable after SIGKILL+restart on one host. # 2. Each STANDBY fdatasyncs BEFORE sending its WalAck (persist.c:511-515), so # every committed job already has a durable copy on the standbys; killing # the primary alone never loses it. The incident's loss needed multi-node # kills + a hollow node re-leading before catch-up repair — inherently racy # (a prior rolling-primary-kill "deterministic" attempt was REJECTED: the # same command gave GREEN/RED/RED across 3 runs — it just swapped the ~10ms # fsync race for a hollow-re-lead-vs-catch-up race). # # The bug-661 invariant that IS deterministic is the DURABILITY GAP on the # PRIMARY (src/controller/CLAUDE.md "Commit Durability" TARGET RULE; Req 1): when # the controller replies "jobsubmit ok", the entry must already be fdatasync'd on # a fault-tolerant majority INCLUDING THE PRIMARY's own copy. On the unfixed build # the primary defers fdatasync to the fsync_worker timer (every --wal-sync-ms ms), # so with a LARGE --wal-sync-ms the primary pwrites but performs ZERO fdatasync # between append and ack. THAT gap is deterministic and observable WITHOUT any # race: launch each controller under `strace -f -tt -e trace=fdatasync,fsync` and # assert that NO primary fdatasync/fsync occurs in the wall-clock window between # job submit and the "jobsubmit ok" reply. RED on unfixed build = ack-before- # primary-durable. After the fsync-before-ACK fix, a primary fdatasync MUST # precede the ack -> GREEN. This verdict is identical on every run (5/5 RED on the # unfixed build); it does not depend on timing a kill. # # Usage: # bash src/tools/test-commit-durability.sh [deploy-dir] [rounds] # bash src/tools/test-commit-durability.sh --deterministic [deploy-dir] # # deploy-dir : cluster root (default /tmp/xce-ha-deploy). Deployed if absent. # rounds : number of kill+restart failover rounds (default 8) — soak mode only. # # --deterministic : run the DETERMINISTIC durability-gap proof (strace-based, # above) instead of the racy soak. Requires `strace` on PATH (ptrace exec-wrap # only — does NOT require PTRACE_ATTACH, which is blocked under # yama/ptrace_scope=1 in containers). On the CURRENT (unfixed) build it # reports RED (no primary fdatasync precedes the ack). After the fix it must # go GREEN. See run_deterministic() below. # # Requires a current build: run /xce-build controller first. set -u # ── mode selection ──────────────────────────────────────────────────────────── # Default = original racy soak (back-compat for existing callers). Pass # --deterministic as the FIRST arg to select the deterministic reproduction. MODE="soak" if [ "${1:-}" = "--deterministic" ] || [ "${1:-}" = "--det" ]; then MODE="deterministic" shift fi WORKTREE=$(cd "$(dirname "$0")/../.." && pwd) BINARY="$WORKTREE/src/xce.build/controller/xce_controller" XCE_TEST="$WORKTREE/src/xce.build/controller/xce_test" DATADIR="$WORKTREE/ha/data" DEPLOY_DIR="${1:-/tmp/xce-ha-deploy}" ROUNDS="${2:-8}" PEERS="localhost:9991,localhost:9992,localhost:9993" MASTERS="localhost:9991,localhost:9992,localhost:9993" LOGDIR="$DEPLOY_DIR/logs" NODES=(ctrl-1 ctrl-2 ctrl-3) QUEUE="${QUEUE:-xce}" JOBUSER="${JOBUSER:-rshen}" # Jobs submitted per round (before the kill) and after the new primary settles. JOBS_BEFORE_KILL="${JOBS_BEFORE_KILL:-3}" JOBS_AFTER_KILL="${JOBS_AFTER_KILL:-1}" # Deterministic mode: a LARGE fsync cadence so the primary never fdatasyncs a # committed entry inside the test window. With this the committed-but-not-durable # window is the entire run, not a ~10ms race — so an strace of the primary shows # ZERO fdatasync between a job submit and its "jobsubmit ok" ack. Plumbed into the # controller launch via the generated start.sh ("$*" passthrough) as --wal-sync-ms. DET_WAL_SYNC_MS="${DET_WAL_SYNC_MS:-30000}" # When non-empty, start_node appends these args to start.sh (e.g. --wal-sync-ms). EXTRA_CTRL_ARGS="" # Where we remember every JobId the cluster acknowledged. Kept in the worktree # (not /tmp) so it survives sandbox /tmp teardown between background-poll cycles. ACKED_FILE="$(mktemp "$WORKTREE/.xce-durability-acked.XXXXXX")" PASS=0 FAIL=0 green() { printf '\033[32m%s\033[0m\n' "$*"; } red() { printf '\033[31m%s\033[0m\n' "$*"; } yellow() { printf '\033[33m%s\033[0m\n' "$*"; } pass() { green " PASS: $*"; PASS=$((PASS+1)); } fail() { red " FAIL: $*"; FAIL=$((FAIL+1)); } cleanup_exit() { rm -f "$ACKED_FILE"; kill_cluster 2>/dev/null || true; } trap cleanup_exit EXIT # ── cluster lifecycle ───────────────────────────────────────────────────────── deploy_cluster() { if [ ! -f "$BINARY" ] || [ ! -f "$XCE_TEST" ]; then red "Binary not found: $BINARY / $XCE_TEST" red "Run /xce-build controller first." exit 2 fi yellow "Deploying 3-node cluster to $DEPLOY_DIR ..." bash "$WORKTREE/src/tools/deploy-ha.sh" "$BINARY" "$DATADIR" "$DEPLOY_DIR" "$PEERS" } start_node() { # EXTRA_CTRL_ARGS (e.g. --wal-sync-ms ) is passed through start.sh's "$*". # # STRACE_TRACE=1 (deterministic mode) exec-wraps the controller under strace so # its fdatasync/fsync syscalls are timestamped into $LOGDIR/.strace.log. # We MUST use ptrace exec-wrap (strace launches the child) — PTRACE_ATTACH # (strace -p ) is blocked under yama/ptrace_scope=1 in containers. -f # follows the fsync_worker pthread; -tt gives HH:MM:SS.uuuuuu wall-clock so the # parser can window syscalls to the submit→ack interval. execve on the # controller's self-re-exec (ha_convergence) keeps the tracer attached. if [ -n "${STRACE_TRACE:-}" ]; then VERBOSE=-vvv strace -f -tt -e trace=fdatasync,fsync \ -o "$LOGDIR/$1.strace.log" \ "$DEPLOY_DIR/scripts/start.sh" "$1" $EXTRA_CTRL_ARGS >/dev/null 2>&1 & else VERBOSE=-vvv "$DEPLOY_DIR/scripts/start.sh" "$1" $EXTRA_CTRL_ARGS >/dev/null 2>&1 & fi } start_cluster() { kill_cluster 2>/dev/null || true sleep 0.3 start_node ctrl-1; sleep 0.5 start_node ctrl-2; sleep 0.5 start_node ctrl-3; sleep 0.3 } kill_cluster() { # Exact process-name match (-x): never matches this script's own cmdline, # which contains the literal "xce_controller" in its grep/pgrep patterns. pkill -9 -x xce_controller 2>/dev/null || true sleep 0.5 } node_pid() { pgrep -f "xce_controller.*--myname $1" 2>/dev/null | head -1; } # SIGKILL a single named node (drops any WAL tail not yet fsync'd by the timer). kill_node() { local pid; pid=$(node_pid "$1") [ -n "$pid" ] && kill -9 "$pid" 2>/dev/null || true sleep 0.5 } # Last role line in a node's log is its current role (tolerates log append/rotate). node_role() { grep -aoE 'CTRL_PRIMARY|CTRL_STANDBY|CTRL_ELECTING' "$LOGDIR/$1.log" 2>/dev/null | tail -1 } # The live node whose most recent role transition is CTRL_PRIMARY. current_primary() { local n for n in "${NODES[@]}"; do [ -n "$(node_pid "$n")" ] || continue [ "$(node_role "$n")" = "CTRL_PRIMARY" ] && { echo "$n"; return 0; } done return 1 } # Wait until some live node is CTRL_PRIMARY and the other live nodes are not ELECTING. wait_for_primary() { local deadline=$(( $(date +%s) + ${1:-40} )) while [ "$(date +%s)" -lt "$deadline" ]; do current_primary >/dev/null && return 0 sleep 1 done return 1 } # ── xce_test drivers (piped stdin; readline reads to EOF) ────────────────────── # Submit one job; echo the acked JobId (empty on failure). xce_test does its own # client-side master rotation, so a single invocation rides through a failover. # # Only a well-formed success counts: the output must carry the literal # "jobsubmit ok: JobId:" AND a canonical 4-field numeric id (0-0--). # A submit attempted mid-failover can print a malformed id (e.g. "63-15--1-...") # from an uninitialized jobid struct — that is NOT an ack and must be rejected, # else the survival check chases a job the cluster never committed. xce_submit_one() { local out out=$(printf 'set masters %s\nclient\njobsub -q %s -u %s -c "sleep 1000"\n' \ "$MASTERS" "$QUEUE" "$JOBUSER" \ | timeout 40 "$XCE_TEST" 2>/dev/null) echo "$out" \ | grep -oE 'jobsubmit ok: JobId: [0-9]+-[0-9]+-[0-9]+-[0-9]+' \ | grep -oE '[0-9]+-[0-9]+-[0-9]+-[0-9]+$' \ | head -1 } # List current JobIds (column 1), one per line. xce_joblist() { printf 'set masters %s\nclient\njoblist\n' "$MASTERS" \ | timeout 40 "$XCE_TEST" 2>/dev/null \ | grep -oE '^[0-9]+-[0-9]+-[0-9]+-[0-9]+' } submit_n() { local n=$1 i jid for i in $(seq 1 "$n"); do jid=$(xce_submit_one) if [ -n "$jid" ]; then echo "$jid" >> "$ACKED_FILE" echo " submitted (acked): $jid" else yellow " submit returned no JobId (cluster mid-failover) — not counted" fi # Tight burst: keep the freshly-committed tail un-fsync'd when the kill # lands (the ~10ms wal_sync_ms window). No long inter-submit delay. done } # Assert every acked JobId is still present. Returns 0 if all survive. assert_no_loss() { local label="$1" present missing=0 jid present=$(xce_joblist | sort -u) while read -r jid; do [ -z "$jid" ] && continue if ! echo "$present" | grep -qxF "$jid"; then red " LOST committed job: $jid" missing=$((missing+1)) fi done < <(sort -u "$ACKED_FILE") local total; total=$(sort -u "$ACKED_FILE" | grep -c .) if [ "$missing" -eq 0 ]; then pass "$label: all $total committed jobs present after failover" return 0 else fail "$label: DATA LOSS — $missing of $total committed jobs vanished (bug-661)" return 1 fi } # ── soak mode (original racy reproduction) ──────────────────────────────────── run_soak() { echo "" yellow "=== bug-661 SOAK: committed-job durability across rolling failover ===" echo " deploy=$DEPLOY_DIR rounds=$ROUNDS queue=$QUEUE (racy ~10ms wal_sync_ms window)" echo "" bash "$DEPLOY_DIR/scripts/cleanup.sh" >/dev/null 2>&1 || true start_cluster if ! wait_for_primary 40; then fail "cluster did not elect an initial primary within 40s" exit 1 fi sleep 3 green "Initial primary: $(current_primary)" # Seed a baseline batch so there is committed state before the first kill. echo "" echo "--- seeding initial committed jobs ---" submit_n 4 assert_no_loss "baseline" || true # record, continue even if already broken # ── rolling failover rounds ─────────────────────────────────────────────── local round victim vpid for round in $(seq 1 "$ROUNDS"); do echo "" echo "--- round $round/$ROUNDS ---" submit_n "$JOBS_BEFORE_KILL" victim=$(current_primary || true) [ -z "$victim" ] && victim="${NODES[$(( round % 3 ))]}" vpid=$(node_pid "$victim") if [ -z "$vpid" ]; then yellow " no live victim found; skipping kill this round" else # SIGKILL (not SIGSTOP): drop any WAL tail not yet fsync'd by the timer. echo " SIGKILL primary $victim (pid $vpid) immediately after submit ..." kill -9 "$vpid" 2>/dev/null || true fi # Let the surviving two elect a new primary and serve. if ! wait_for_primary 40; then fail "round $round: no new primary elected within 40s after killing $victim" # keep going to capture the loss signature else echo " new primary: $(current_primary || echo '?')" fi sleep 2 # Submit against the new primary while one node is still down. submit_n "$JOBS_AFTER_KILL" # Restart the killed node so it rejoins (reproduces hollow-rejoin election). if [ -n "${victim:-}" ]; then echo " restarting $victim (rejoin) ..." start_node "$victim" fi # Let the rejoined node catch up / participate in any re-election. if ! wait_for_primary 40; then fail "round $round: cluster lost its primary after $victim rejoined" fi sleep 4 assert_no_loss "round $round" || true done echo "" echo "--- final durability check ---" sleep 2 assert_no_loss "final" || true } # ── deterministic mode (timing-independent DURABILITY-GAP proof) ────────────── # # WHAT THIS PROVES (and why it is deterministic — see the header SCOPE # CLARIFICATION for why single-host SIGKILL data-loss is NOT deterministic): # With --wal-sync-ms=$DET_WAL_SYNC_MS (default 30s) the primary's fsync_worker # timer never fires inside the test window, so EVERY entry the primary appends # stays in the OS page cache, never fdatasync'd (persist_wal_async, the append # path, does NOT fsync — only the timer does). Each controller runs under strace # capturing fdatasync/fsync with wall-clock timestamps. We submit one job, record # the wall-clock instant T0 just before submit and T1 the instant "jobsubmit ok" # returns, then assert: ZERO fdatasync/fsync occurred on the PRIMARY in [T0,T1]. # That is the bug-661 durability gap — the controller acked an entry it had not # made durable on its own disk (src/controller/CLAUDE.md "Commit Durability" # TARGET RULE / Req 1). The standbys DO fdatasync before WalAck (persist.c:515), # so they show syncs in-window; only the primary's missing sync is the defect. # # VERDICT IS RACE-FREE: it depends only on whether the primary issued an # fdatasync before the ack returned, which is fixed by the code path (timer- # deferred vs sync-before-ack), not by when a kill lands. Same result every run. # RED (unfixed): 0 primary fdatasync/fsync in [T0,T1] -> ack-before-durable. # GREEN (fixed): >=1 primary fdatasync/fsync in [T0,T1] preceding the ack. # # IMPLEMENTATION NOTE: strace ptrace exec-wrap only (start_node launches the # controller under strace). PTRACE_ATTACH (strace -p) is blocked under # yama/ptrace_scope=1 in containers, so we never attach to a running pid. # Convert an strace -tt timestamp "HH:MM:SS.uuuuuu" (or a `date +%H:%M:%S.%N` # capture) to seconds-of-day as a float. Pure awk; handles the day-wrap-free # common case (a submit never straddles midnight in this harness). _hms_to_sod() { awk -F'[:.]' '{ printf "%d.%06d\n", ($1*3600+$2*60+$3), substr($4"000000",1,6) }' <<<"$1" } # Count PRIMARY fdatasync/fsync syscalls whose -tt timestamp falls in [T0,T1]. # Args: . Echoes the count. _primary_syncs_in_window() { local log="$1" t0="$2" t1="$3" [ -f "$log" ] || { echo 0; return; } # strace -f -tt line shape: " HH:MM:SS.uuuuuu fdatasync() = 0" awk -v t0="$t0" -v t1="$t1" ' /fdatasync|fsync/ { ts=$2 # HH:MM:SS.uuuuuu n=split(ts, a, /[:.]/) if (n < 4) next sod=a[1]*3600 + a[2]*60 + a[3] + a[4]/1000000.0 if (sod >= t0 && sod <= t1) c++ } END { print c+0 }' "$log" } # One deterministic probe: submit a job, return RED/GREEN by counting primary # fdatasync/fsync syscalls strictly inside the submit→ack window. Echoes a verdict # line and sets PASS/FAIL. Returns 0 if RED (gap present), 1 if GREEN. det_probe_once() { local label="$1" local primary primary_log t0 t1 t0_sod t1_sod jid syncs primary=$(current_primary || true) if [ -z "$primary" ]; then fail "$label: no primary to probe" return 2 fi primary_log="$LOGDIR/$primary.strace.log" if [ ! -f "$primary_log" ]; then fail "$label: primary strace log missing ($primary_log) — strace exec-wrap failed?" return 2 fi # Capture the window with the SAME wall clock strace -tt uses (local time). t0=$(date +%H:%M:%S.%N) jid=$(xce_submit_one) t1=$(date +%H:%M:%S.%N) if [ -z "$jid" ]; then yellow " $label: submit returned no JobId (cluster mid-failover?) — retrying once" t0=$(date +%H:%M:%S.%N); jid=$(xce_submit_one); t1=$(date +%H:%M:%S.%N) fi if [ -z "$jid" ]; then fail "$label: could not obtain a committed JobId to probe" return 2 fi echo "$jid" >> "$ACKED_FILE" # Let strace flush the in-window syscalls (its output is line-buffered to file). sleep 1 t0_sod=$(_hms_to_sod "$t0"); t1_sod=$(_hms_to_sod "$t1") syncs=$(_primary_syncs_in_window "$primary_log" "$t0_sod" "$t1_sod") echo " primary=$primary ack=$jid window=[$t0 .. $t1] primary fdatasync/fsync in-window=$syncs" if [ "$syncs" -eq 0 ]; then fail "$label: DURABILITY GAP — primary acked '$jid' with 0 fdatasync in-window (bug-661: ack-before-durable)" return 0 else pass "$label: primary fdatasync ($syncs) preceded ack of '$jid' (durable-before-ack)" return 1 fi } run_deterministic() { if ! command -v strace >/dev/null 2>&1; then red "deterministic mode requires 'strace' on PATH (not found) — cannot run." red "Re-run in an environment with strace, or use the soak mode." exit 2 fi EXTRA_CTRL_ARGS="--wal-sync-ms $DET_WAL_SYNC_MS" STRACE_TRACE=1 # start_node will exec-wrap each controller under strace local probes="${DET_PROBES:-3}" echo "" yellow "=== bug-661 DETERMINISTIC: ack-before-durable gap on the PRIMARY (strace) ===" echo " deploy=$DEPLOY_DIR queue=$QUEUE probes=$probes --wal-sync-ms=$DET_WAL_SYNC_MS (no primary fsync in-window)" echo " RED = primary acks a job with 0 fdatasync in the submit->ack window." echo "" bash "$DEPLOY_DIR/scripts/cleanup.sh" >/dev/null 2>&1 || true # Clear stale strace logs so we never read a previous run's syscalls. rm -f "$LOGDIR"/*.strace.log 2>/dev/null || true start_cluster if ! wait_for_primary 40; then fail "cluster did not elect an initial primary within 40s" exit 1 fi # Generous initial settle so the elected primary fully serves jobsub and its # boot-time fdatasyncs (segment preallocation) are well before any probe window. sleep 6 green "Initial primary: $(current_primary)" # Repeat the probe several times against the stable primary. Every probe must # be RED on the unfixed build — this is the in-run reproducibility evidence # (the outer 5x driver gives cross-run evidence). local i red_count=0 for i in $(seq 1 "$probes"); do echo "" echo "--- det probe $i/$probes ---" if det_probe_once "probe $i"; then red_count=$((red_count+1)) fi sleep 1 done echo "" echo "--- deterministic summary ---" echo " RED probes (durability gap observed): $red_count/$probes" # The deterministic mode FAILS (exit non-zero) when the gap is present on the # unfixed build (any RED probe). After the fix, all probes go GREEN and FAIL=0. } # ── setup + dispatch ────────────────────────────────────────────────────────── [ -d "$DEPLOY_DIR" ] || deploy_cluster if [ "$MODE" = "deterministic" ]; then run_deterministic else run_soak fi # ── final verdict ───────────────────────────────────────────────────────────── echo "" echo "=========================" echo "Mode: $MODE" echo "Results: ${PASS} passed, ${FAIL} failed" echo "Acked jobs total: $(sort -u "$ACKED_FILE" | grep -c .)" echo "=========================" [ "$FAIL" -eq 0 ] && exit 0 || exit 1