diff --git a/.kiro/specs/ha-commit-durability/tasks.md b/.kiro/specs/ha-commit-durability/tasks.md index 2936a607..72a71336 100644 --- a/.kiro/specs/ha-commit-durability/tasks.md +++ b/.kiro/specs/ha-commit-durability/tasks.md @@ -17,7 +17,7 @@ - _Requirements: 3.2, 3.3_ - _Boundary: DurabilityTestSeam_ -- [ ] 1.3 Drive a deterministic durability reproduction from the soak harness +- [x] 1.3 Drive a deterministic durability reproduction from the soak harness - Extend `test-commit-durability.sh` with a deterministic mode that widens the batching window / uses the seam and kills a durable contributor in-window. - Observable: on the current (unfixed) build the deterministic mode reports DATA LOSS (RED), proving bug-661 without relying on race timing. - _Requirements: 3.1, 3.2_ @@ -122,3 +122,4 @@ ## Implementation Notes - 1.1: Config plumbing routes through `myconf_t.wal_sync_ms` + `persist_config_set_wal_sync_ms()` (0-sentinel = keep `DEFAULT_WAL_SYNC_MS`), NOT a new config.h constant (design File Structure Plan keeps `DEFAULT_WAL_SYNC_MS`). The override is applied at BOTH `persist_init` sites — `myapp_run` step-6 (production path) and `cluster_init_phase2` (guarded by `wal_path[0]=='\0'`, skipped in production). They are mutually exclusive; apply any new persist_config override at both sites or it is silently dropped. Pre-existing latent bug (do NOT fix here): `--sync-timeout-ms` is applied only in phase2, so it is ignored on the production startup path — relevant if a later task relies on `sync_timeout_ms`. - 1.2: Test seam = `persist_test_durable_lsn_on_disk(persist_t*)` (decl `persist.h`, impl `persist.c`, all `#ifdef XCE_TESTING`) — re-opens WAL segment files from disk and CRC-validates the chain (read-only, state-free) to return the highest fully-persisted LSN; new test `testsuite/test_commit_durability.c` (registered in `meson.build` + `controller_test.c`). Production `xce_controller` links without it (proven via `nm`). DRY NOTE: ~115 lines of segment-scan/CRC-chain logic are duplicated from the static `replay_wal`; tasks 3.1 (recovery verdict) and 3.4 (durable floor from WAL tip) touch the SAME scan/CRC logic — consider extracting a shared read-only `wal_scan_durable_lsn`-style helper there and routing this seam through it (avoid a third copy). `XCE_TESTING` is defined only for `controller_unit_test` (`src/controller/meson.build:167`). +- 1.3: Deterministic mode = `bash src/tools/test-commit-durability.sh --deterministic` proves the durability GAP via strace, NOT joblist data-loss. SCOPE CLARIFICATION (review-ratified): single-host SIGKILL committed-job loss is physically NON-deterministic — `persist_wal_async` pwrites inline (page cache survives process death) and standbys fdatasync-before-WalAck (persist.c:515), so a committed job is always durable off the primary; a data-loss run flips GREEN/RED/RED. The deterministic slice: with `--wal-sync-ms 30000` the primary acks "jobsubmit ok" with ZERO primary fdatasync in the submit→ack window (exec-wrap `strace -f -tt -e trace=fdatasync,fsync`; PTRACE_ATTACH `-p` is yama-blocked). RED = in-window primary syncs==0 (15/15 across 5 runs; primary=0 vs standby=2). This is a valid RED→GREEN gate: the task-2.x fsync-before-ack fix makes the primary count ≥1 ⇒ GREEN. Original racy soak retained as the default mode. Boundary: only `src/tools/test-commit-durability.sh` (flag plumbed via deploy-ha.sh start.sh `$*` passthrough — no C edits). For task 5.2's E2E, prefer this strace gap-proof over joblist-loss for a deterministic durability assertion. diff --git a/src/tools/test-commit-durability.sh b/src/tools/test-commit-durability.sh new file mode 100755 index 00000000..c01a9b22 --- /dev/null +++ b/src/tools/test-commit-durability.sh @@ -0,0 +1,525 @@ +#!/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