diff --git a/.claude/skills/xce-test-ha/run-ha-soak.sh b/.claude/skills/xce-test-ha/run-ha-soak.sh index e127a195..3456af75 100755 --- a/.claude/skills/xce-test-ha/run-ha-soak.sh +++ b/.claude/skills/xce-test-ha/run-ha-soak.sh @@ -109,6 +109,36 @@ # --force-snapshot, hard-fails (not count-and-tolerate) on # any violated invariant, since these are the feature's core # correctness claims, not a chaotic/racy outcome class. +# worker-rejoin-resync live coverage (--sequential / --chaotic, task 8.x): +# when a real worker+scheduler binary pair exists alongside +# the controller binary (same build dir -- run /xce-build +# worker and /xce-build scheduler alongside /xce-build +# controller), sequential/chaotic modes ALSO start a real +# worker (start-worker.sh/start-scheduler.sh, same binaries +# and auto-detection deploy-ha.sh already uses -- real +# systemd present, or XCE_REAL_WORKER=1 forced, picks the +# real production xcecd; otherwise xcecd_virtual, which +# exercises byte-identical rejoin/reconciliation code with +# job execution simulated instead of a real systemd unit) +# and dispatch a REAL job onto it each round -- not +# xce_test's scripted jobsub/jstart/jfinish stand-in, which +# predates and cannot speak OPCode_jobStateQuery/Report at +# all. Sequential mode hard-fails per round if the job does +# not recover to a terminal state via a genuinely fresh +# rejoin after the kill (proven via the worker's own log, +# not just eventual re-delivery); chaotic mode tracks jobs +# through the overlapping-kill loop and hard-fails only in +# a final settled sweep after the loop, since "every lost +# job eventually reconciles" is this feature's own core +# correctness claim, not a chaotic/racy outcome class (same +# standard --array-soak/--array-chaos-retry hold themselves +# to). Soft-skipped with a warning, not fail(), when the +# worker/scheduler binaries or their generated start +# scripts are missing -- a controller-only build dir stays +# fully backward compatible. Live-verified against a real +# 3-node cluster + xcecd_virtual before being wired in here +# (real dispatch to RUN, kill-during-RUN, confirmed-fresh +# rejoin via the worker's own log, job recovered to DONE). # --array-chaos-retry job-array-single-wal-record task 6.2 (Req 8.2, 8.3): # submits a job ARRAY and kills the primary IMMEDIATELY # (before it is known whether the array's WAL_JOB_ARRAY_SUBMIT @@ -133,6 +163,19 @@ # --selftest run the verdict-parser self-test (soak-verdict-selftest.sh) # and exit — no cluster, no binaries needed. # +# Worker-rejoin-resync live coverage env overrides: +# XCE_REAL_WORKER 0|1 — forces xcecd_virtual/real xcecd choice, same +# variable deploy-ha.sh's own generated start-worker.sh +# already reads; unset auto-detects on /run/systemd/system +# exactly as it always has. Nothing new to configure here. +# XCE_HA_WORKER_RESYNC_SLEEP seconds the sequential loop's per-round +# worker-dispatched job sleeps for (default 20) — sized +# so the job's simulated finish lands strictly AFTER +# that round's kill, guaranteeing its fire-and-forget +# finish notify has nowhere live to land (a genuine +# loss, not a timing coincidence) before the worker's +# own reconnect logic rejoins the new primary. +# # Env overrides: # XCE_HA_TOP deploy dir (default /home/claude/tmp/xce-ha-deploy) # XCE_HA_MODE sequential | chaotic | force-snapshot (default sequential) @@ -341,6 +384,13 @@ V_BUG924=0 # overlayfs `fdatasync FAILED` log lines (environment defect) V_PHANTOM=0 # phantom fact reactions observed (see verify_factstream_no_phantom) FACTSTREAM_ALL_JOBIDS=() # every jobid ever driven through the fact stream, across rounds +# ── Worker-rejoin-resync live coverage (sequential/chaotic only) ──────────── +WORKER_NAME="soak-worker" +WORKER_ENABLED=0 # 1 once start_worker_and_scheduler() confirms both joined +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 + log() { echo "[xce-test-ha] $*"; } fail() { echo "[xce-test-ha] FAIL: $*" >&2; cleanup; exit 1; } @@ -370,7 +420,21 @@ fail() { echo "[xce-test-ha] FAIL: $*" >&2; cleanup; exit 1; } node_pattern() { echo "xce_controller --myname $1 .*--workdir $TOP/controller"; } run_pattern() { echo "xce_controller .*--workdir $TOP/controller"; } -cleanup() { pkill -9 -f -- "$(run_pattern)" 2>/dev/null; sleep 0.3; } +# Same TOP-scoping discipline as node_pattern/run_pattern above, applied to +# the worker-rejoin-resync worker/scheduler processes. `-l $TOP/logs` is +# passed verbatim by generated start-worker.sh regardless of which binary +# (xcecd_virtual or real xcecd) it targets, so one pattern covers both; +# xce_scheduler is a cluster singleton so `--logfile $TOP/logs/scheduler.log` +# alone is enough to scope it to this run. +worker_pattern() { echo "xcecd.*-l $TOP/logs"; } +sched_pattern() { echo "xce_scheduler .*--logfile $TOP/logs/scheduler.log"; } + +cleanup() { + pkill -9 -f -- "$(run_pattern)" 2>/dev/null + pkill -9 -f -- "$(worker_pattern)" 2>/dev/null + pkill -9 -f -- "$(sched_pattern)" 2>/dev/null + sleep 0.3 +} # Record that a node has acted as primary at least once (leadership-coverage # tracking — the run asserts all three nodes lead, see the verdict). @@ -387,6 +451,211 @@ kill_node() { return 0 } +# ── Worker-rejoin-resync live coverage (sequential/chaotic only) ──────────── +# +# Real xcecd's log ($TOP/logs/xcecd.log, hardcoded regardless of -n) comes out +# root-owned 640 (xce-deploy-ha SKILL.md, confirmed) -- a plain read as this +# script's own user fails. xcecd_virtual's log ($TOP/logs/xcecd-$WORKER_NAME.log) +# needs no such treatment. These three helpers are the single place that +# knows which applies, so no other worker-resync code needs to care. +worker_log_path() { + [ -f "$TOP/logs/xcecd.log" ] && { echo "$TOP/logs/xcecd.log"; return; } + echo "$TOP/logs/xcecd-$WORKER_NAME.log" +} +worker_log_grep() { + local pat="$1" path; path="$(worker_log_path)" + if [ "$path" = "$TOP/logs/xcecd.log" ]; then + sudo -n grep "$pat" "$path" 2>/dev/null + else + grep "$pat" "$path" 2>/dev/null + fi +} +worker_log_count() { + local pat="$1" path n; path="$(worker_log_path)" + if [ "$path" = "$TOP/logs/xcecd.log" ]; then + n="$(sudo -n grep -c "$pat" "$path" 2>/dev/null)" + else + n="$(grep -c "$pat" "$path" 2>/dev/null)" + fi + echo "${n:-0}" +} + +# Starts a real worker + scheduler alongside the controller cluster, using +# the SAME generated start-worker.sh/start-scheduler.sh (and therefore the +# SAME xcecd_virtual-vs-real-xcecd/XCE_REAL_WORKER auto-detection) deploy-ha.sh +# already produces for xce-deploy-ha -- no separate detection logic here. +# Soft-skips (log a warning, do not fail()) when the binaries/generated +# scripts are missing, or when either process does not confirm joining +# within budget, so a controller-only build dir stays fully backward +# compatible and a flaky join never turns an otherwise-healthy HA soak into +# a hard failure over an orthogonal feature's coverage. + +# Pragmatic soak-harness workaround for bug-1760 (logged, not fixed): the +# scheduler has NO periodic reconnect check analogous to the worker's +# checking_connection() -- its only rejoin path is REACTIVE, firing only as +# a side effect of its own next successful publish call +# (sched_publish_check_rejoin(), scheduler.c). After a real controller +# failover it has nothing queued to publish (no new job ever reaches its +# picker, since the controller-side registration of "where the scheduler +# is" does not appear to carry over to the newly-elected primary) -- a +# chicken-and-egg deadlock, live-confirmed (60s+ of zero scheduler.log +# activity, job stuck PEND). Restarting the scheduler process after each +# new-primary election, the same way this harness already restarts a +# downed CONTROLLER node, sidesteps it: a fresh process's sched_init() tries +# all 3 candidates in order and joins whichever is actually reachable. Test- +# infrastructure-only workaround -- does NOT fix the underlying gap. +restart_scheduler_for_new_primary() { + local before i + before="$(wc -l < "$TOP/logs/scheduler.log" 2>/dev/null || echo 0)" + pkill -9 -f -- "$(sched_pattern)" 2>/dev/null + sleep 0.5 + setsid nohup bash "$TOP/scripts/start-scheduler.sh" -v \ + >"$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 + sleep 1 + done + log "worker-resync: scheduler restart did not confirm join within 20s (bug-1760 workaround) -- worker-resync coverage may fail this round" + return 1 +} + +start_worker_and_scheduler() { + if [ ! -f "$TOP/scripts/start-worker.sh" ] || [ ! -f "$TOP/scripts/start-scheduler.sh" ]; then + log "worker-resync: start-worker.sh/start-scheduler.sh not generated (worker and/or scheduler binary missing from this build dir) -- skipping worker-rejoin-resync coverage this run. Run /xce-build worker and /xce-build scheduler alongside /xce-build controller to enable it." + return 0 + fi + + 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 \ + >"$TOP/logs/scheduler.stderr" 2>&1 & + + # Real xcecd started without systemd/dbus present still joins the cluster + # fine (only job DISPATCH later fails) -- this check confirms liveness/ + # join, not "can actually run a job"; the first submit_worker_job() call + # confirms that for real. + local i + for i in $(seq 1 20); do + worker_log_grep "Successfully sent .* load indices" >/dev/null && break + sleep 1 + done + if ! worker_log_grep "Successfully sent .* load indices" >/dev/null; then + log "worker-resync: worker did not confirm join within 20s ($(worker_log_path)) -- skipping worker-rejoin-resync coverage this run" + return 0 + fi + for i in $(seq 1 20); do + grep -q "sched_init: joined cluster" "$TOP/logs/scheduler.log" 2>/dev/null && break + sleep 1 + done + if ! grep -q "sched_init: joined cluster" "$TOP/logs/scheduler.log" 2>/dev/null; then + log "worker-resync: scheduler did not confirm join within 20s -- skipping worker-rejoin-resync coverage this run" + return 0 + fi + + WORKER_ENABLED=1 + log "worker-resync: worker + scheduler joined -- rejoin-resync coverage enabled for this run" +} + +# Submits ONE real job, dispatched through the live scheduler onto the live +# worker -- NOT xce_test's scripted jobsub/jstart/jfinish stand-in. The +# `sleep $1` command is what xcecd_worker_utils.c parses to drive the +# virtual worker's own timer-based simulated execution (confirmed live: a +# real xcecd_virtual genuinely reaches RUN via real scheduler dispatch, +# independent of systemd/dbus). Echoes the jobid and returns 0 once RUN is +# confirmed; returns 1 (echoing nothing) on a submit or RUN-timeout failure. +submit_worker_job() { + local sleep_secs="$1" out jid attempt st + out="$(printf 'set masters %s\nset myname soak\nclient\nwait-primary %s\njobsub -u root -q normal -c "sleep %s"\nquit\n' \ + "$MASTERS" "$WAITMS" "$sleep_secs" | xtest)" + jid="$(printf '%s\n' "$out" | sed -n 's/^jobsubmit ok: JobId: \(.*\)$/\1/p')" + if [ -z "$jid" ]; then + # log() writes to stdout, which this function's own callers capture + # via $(...) to get the jobid back -- a diagnostic here MUST go to + # stderr instead, or it silently becomes (part of) the "jobid". + log "worker-resync: jobsub itself failed -- raw output: $(printf '%s' "$out" | tr '\n' ' ')" >&2 + return 1 + fi + # The scheduler's own rejoin with a NEW primary is reactive, not + # periodically polled like a worker's checking_connection() -- it only + # re-issues xcecli_join() as a side effect of its NEXT successful + # publish call (scheduler.c's sched_publish_check_rejoin(), fired from + # sched_publish_retry_loop() only after that same call already + # succeeded). Right after a controller failover, THIS job may be the + # scheduler's first real activity since the kill, so give it a much + # longer, generously-diagnosed budget than an ordinary RUN-wait -- + # confirmed necessary live (a 10s budget was not enough in testing). + for attempt in $(seq 1 60); do + st="$(jobinfo_of "$jid" 2000 | sed -n 's/^state: //p')" + if [ "$st" = "RUN" ]; then + echo "$jid" + return 0 + fi + sleep 1 + done + log "worker-resync: job $jid never reached RUN after 60s (last state: ${st:-unknown})" >&2 + return 1 +} + +# Sequential-mode, per-round hard gate: verifies ONE worker-dispatched job +# survived a real controller failover via genuine rejoin-reconciliation, not +# eventual re-delivery or a lucky timing coincidence -- +# (a) the worker's OWN log shows a FRESH "rejoin after transparent +# reconnect succeeded" line (count strictly greater than the baseline +# captured before the kill) -- proof an actual disconnect+rejoin cycle +# happened; +# (b) the job ends up DONE on the new primary, never left stuck RUN. +# fail()s (hard) on either miss -- this is the feature's own core +# correctness claim (bug-1741's original motivating scenario), not a +# chaotic/racy outcome class. +verify_worker_rejoin_resync() { + local jid="$1" pre_count="$2" round="$3" i post_count st + for i in $(seq 1 30); do + post_count="$(worker_log_count "rejoin after transparent reconnect succeeded")" + [ "${post_count:-0}" -gt "${pre_count:-0}" ] && break + sleep 1 + done + [ "${post_count:-0}" -gt "${pre_count:-0}" ] \ + || fail "round $round: worker-resync job $jid: worker never logged a fresh rejoin after the failover (pre=$pre_count post=$post_count)" + + for i in $(seq 1 30); do + st="$(jobinfo_of "$jid" 2000 | sed -n 's/^state: //p')" + [ "$st" = "DONE" ] && { log "round $round: worker-resync job $jid recovered to DONE via real rejoin-reconciliation"; return 0; } + sleep 1 + done + fail "round $round: worker-resync job $jid never reached DONE after rejoin (last state: ${st:-unknown}) -- stuck job, reconciliation did not recover it" +} + +# Chaotic-mode final sweep: unlike the sequential per-round gate, chaotic +# mode deliberately never blocks mid-loop for a specific job's outcome (that +# would contradict its whole overlapping-kill design). Every worker-resync +# job submitted during the loop (WORKER_RESYNC_JOBIDS) is instead checked +# ONCE, here, after the loop's own final "restore 3-of-3 and settle" step -- +# still a hard fail() on a genuinely stuck job, since "every lost job +# eventually reconciles" is this feature's own core correctness claim, not a +# chaotic/racy outcome class (same standard --array-soak/--array-chaos-retry +# hold themselves to), just checked in one batched pass instead of per round. +verify_worker_resync_jobs_final() { + local jid i st stuck=() + for jid in "${WORKER_RESYNC_JOBIDS[@]}"; do + st="" + for i in $(seq 1 30); do + st="$(jobinfo_of "$jid" 2000 | sed -n 's/^state: //p')" + [ "$st" = "DONE" ] && break + sleep 1 + done + if [ "$st" != "DONE" ]; then + stuck+=("$jid(last=${st:-unknown})") + V_RESYNC_STUCK=$((V_RESYNC_STUCK + 1)) + fi + done + [ "${#stuck[@]}" -eq 0 ] \ + || fail "chaotic: ${#stuck[@]}/${#WORKER_RESYNC_JOBIDS[@]} worker-resync job(s) never reconciled after the loop settled: ${stuck[*]}" + [ "${#WORKER_RESYNC_JOBIDS[@]}" -gt 0 ] \ + && log "chaotic: all ${#WORKER_RESYNC_JOBIDS[@]} worker-resync job(s) reconciled to DONE" +} + # ── Preconditions ──────────────────────────────────────────────────────────── [ -x "$BIN" ] || { echo "[xce-test-ha] FAIL: controller binary missing: $BIN (run /xce-build controller)" >&2; exit 2; } [ -x "$XT" ] || { echo "[xce-test-ha] FAIL: xce_test missing: $XT (run /xce-build controller)" >&2; exit 2; } @@ -1018,7 +1287,7 @@ scan_bug924() { # the prior node is restarted, so at most one node is down at a kill instant. # Every data outcome is COUNTED into the verdict, never hard-failed. run_chaotic_rounds() { - local round PRIMARY PREV_TERM NEWP pid DOWN="" + local round PRIMARY PREV_TERM NEWP pid DOWN="" resync_jid for round in $(seq 1 "$ROUNDS"); do log "=== chaotic round $round/$ROUNDS ===" @@ -1068,9 +1337,38 @@ run_chaotic_rounds() { log "round $round: NO new primary within window (possible election stall)" fi - # Count loss/divergence for this round (verdict, not a hard fail). + # Count loss/divergence for this round (verdict, not a hard fail). Runs + # BEFORE any worker-resync activity below on purpose -- this is the + # EXISTING, already-validated check, timed exactly as it always has + # been; worker-resync's own (much slower, up to ~80s combined) + # scheduler-restart + job-submit-and-RUN-wait must never shift ITS + # comparison window (confirmed live: doing this in the other order + # produced spurious mid-run "committed divergence" hits that a + # post-hoc walcompare on the SAME data proved were transient + # replication-lag artifacts, not real loss -- the exact false- + # positive class live_committed_boundary()'s own header comment + # already documents, just newly exposed by worker-resync's added + # per-round wall-clock time). verify_classify walcheck_count "${#ALL_JOBIDS[@]}" + + # worker-rejoin-resync: best-effort, same tolerance as submit_jobs + # above — chaotic mode never blocks mid-loop for one job's outcome + # (that would contradict its whole overlapping-kill design). Every + # job that DOES reach RUN is tracked and checked once, in a single + # final sweep after the whole loop settles (verify_worker_resync_ + # jobs_final, called by the chaotic MODE dispatch below). Placed + # AFTER this round's own divergence check (see comment above) so + # its slower pace never perturbs that check's timing; which + # specific round's kill a tracked job ends up surviving does not + # matter, since every tracked job is checked only once, at the end, + # after every round's chaos (including this one) has already run. + if [ "$WORKER_ENABLED" -eq 1 ]; then + restart_scheduler_for_new_primary + resync_jid="$(submit_worker_job "$WORKER_RESYNC_SLEEP")" \ + && WORKER_RESYNC_JOBIDS+=("$resync_jid") \ + || log "round $round: worker-resync job did not reach RUN (transient — not a loss, not tracked)" + fi done # Restore 3-of-3 and let it settle so the FINAL sweep sees every member's @@ -2447,6 +2745,15 @@ PRIMARY="$(discover_primary)" record_primary "$PRIMARY" log "primary is $PRIMARY" +# worker-rejoin-resync live coverage: only sequential/chaotic drive it (see +# this file's own header comment) -- the other dedicated single-round modes +# have their own separate, already-established scenarios and env knobs; +# starting an unrelated worker+scheduler alongside them would only add +# noise, not coverage. +if [ "$MODE" = "sequential" ] || [ "$MODE" = "chaotic" ]; then + start_worker_and_scheduler +fi + # ── Step 5: initial submit + verify + waldump ──────────────────────────────── submit_jobs "$NJOBS" || fail "initial job submission did not get $NJOBS clean acks" verify_no_loss || fail "initial joblist verification failed" @@ -2640,6 +2947,14 @@ fi if [ "$MODE" = "chaotic" ]; then log "MODE=chaotic — overlapping-kill soak ($ROUNDS rounds)" run_chaotic_rounds + # worker-rejoin-resync: hard sweep over every job tracked during the loop + # (see run_chaotic_rounds' own submit call and this file's header + # comment) -- run AFTER run_chaotic_rounds' own final settle step so the + # cluster is stable before judging "stuck". fail()s (exits) on its own if + # any job never reconciled; falls through here only on full success. + if [ "$WORKER_ENABLED" -eq 1 ]; then + verify_worker_resync_jobs_final + fi # Final divergence + loss sweep on the settled cluster, then bug-924 tally. walcheck_count "${#ALL_JOBIDS[@]}" verify_classify @@ -2648,7 +2963,7 @@ if [ "$MODE" = "chaotic" ]; then "$V_DIVERGENCE" "$V_JOBLOSS" "$V_BUG854" "$V_BUG924" VERDICT_RC=$? 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)" + 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 trap - EXIT INT TERM exit 0 @@ -2705,6 +3020,20 @@ for round in $(seq 1 "$ROUNDS"); do [ -n "$PRIMARY" ] || fail "round $round: no serving primary before kill" log "round $round: current primary $PRIMARY" + # worker-rejoin-resync: dispatch one real job onto the live worker BEFORE + # this round's kill, sized (WORKER_RESYNC_SLEEP) so its simulated finish + # lands strictly AFTER the kill -- guaranteeing its fire-and-forget + # finish notify has nowhere live to land (a genuine loss, not a timing + # coincidence) until the worker's own reconnect logic rejoins the new + # primary. Skipped entirely when WORKER_ENABLED=0. + RESYNC_JID="" + if [ "$WORKER_ENABLED" -eq 1 ]; then + RESYNC_JID="$(submit_worker_job "$WORKER_RESYNC_SLEEP")" \ + || fail "round $round: worker-resync job never reached RUN before the kill" + RESYNC_PRE_COUNT="$(worker_log_count "rejoin after transparent reconnect succeeded")" + log "round $round: worker-resync job $RESYNC_JID dispatched and RUN, will finish in ${WORKER_RESYNC_SLEEP}s" + fi + # Record the election term BEFORE the kill so we can detect a STRICTLY-newer # CTRL_PRIMARY announcement (a genuine new election) afterwards. PREV_TERM="$(latest_primary_term)" @@ -2722,6 +3051,12 @@ for round in $(seq 1 "$ROUNDS"); do DOWN="$PRIMARY" sleep 2 + # worker-rejoin-resync: let the job's simulated execution finish while + # the old primary is confirmed dead, before we even look for a new one. + if [ "$WORKER_ENABLED" -eq 1 ] && [ -n "$RESYNC_JID" ]; then + sleep "$WORKER_RESYNC_SLEEP" + fi + # Step 7: a NEW primary must be elected (client probe reports a SERVING # primary at a higher term) AND be reachable; then joblist must show no loss. log "round $round: waiting for new primary (term > $PREV_TERM)" @@ -2731,8 +3066,13 @@ for round in $(seq 1 "$ROUNDS"); do record_primary "$NEWP" PRIMARY="$(discover_primary)" [ -n "$PRIMARY" ] || fail "round $round: new primary $NEWP elected but client cannot reach it (bug-854 class)" + [ "$WORKER_ENABLED" -eq 1 ] && restart_scheduler_for_new_primary verify_no_loss || fail "round $round: a committed job was LOST after failover" + if [ "$WORKER_ENABLED" -eq 1 ] && [ -n "$RESYNC_JID" ]; then + verify_worker_rejoin_resync "$RESYNC_JID" "$RESYNC_PRE_COUNT" "$round" + fi + # Step 8: submit another batch on the new primary. submit_jobs "$NJOBS" || fail "round $round: post-failover submit did not get $NJOBS acks" @@ -2769,7 +3109,7 @@ done [ -z "$MISSING" ] || fail "not all nodes acted as primary — never led:$MISSING" LED="$(printf '%s\n' "${!SEEN_PRIMARY[@]}" | sort | tr '\n' ',' | sed 's/,$//')" -log "PASS: $ROUNDS rounds, ${#ALL_JOBIDS[@]} jobs submitted, zero job loss; all 3 nodes led ($LED)" +log "PASS: $ROUNDS rounds, ${#ALL_JOBIDS[@]} jobs submitted, zero job loss; all 3 nodes led ($LED)$([ "$WORKER_ENABLED" -eq 1 ] && echo "; $ROUNDS worker-resync jobs reconciled")" cleanup trap - EXIT INT TERM exit 0 diff --git a/.wolf/buglog.json b/.wolf/buglog.json index d1651eac..2bfebc09 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -20662,6 +20662,82 @@ ], "occurrences": 1, "last_seen": "2026-09-02T02:45:00Z" + }, + { + "id": "bug-1758", + "timestamp": "2026-09-02T03:23:00Z", + "error_message": "scheduler suite (meson test --suite scheduler): sched_core_events_test FAILs deterministically -- test_core_events.c:1364:test_job_rusage_reconciles_mem_reservation_against_usage:FAIL: Expected 4 Was 0. Discovered as one of 2 failures (the other is a pre-existing, unrelated libxce/meson.build ASAN-flag gap) during worker-rejoin-resync feature-level /kiro-validate-impl full-suite run; confirmed NOT caused by worker-rejoin-resync.", + "file": "src/scheduler/testsuite/test_core_events.c", + "root_cause": "NOT YET ROOT-CAUSED (logged, not investigated -- out of scope for the session that found it). Confirmed via git blame that the ENTIRE failing test function, including the failing sanity assertion at line 1364 itself, was newly added by commit eb06f16d (\"fix(scheduler): wire mem reservation reconciliation into live rusage event path\", .kiro/specs/scheduler-dispatch-commit/), not by worker-rejoin-resync or any earlier commit -- this is that commit's own new test failing against its own new code, not a regression it caused in pre-existing coverage. The failure is at the test's OWN pre-condition sanity check (line 1364, before the rusage/reconciliation event the test is actually about is even pushed): a JOBS_PUSH-dispatched job with a real 4.0 \"mem\" xce_alloc_t is asserted to have already charged 4.0 into w->resInUse (\"matching sched_charge_account()'s existing behavior\", per the test's own comment) -- but val[0] reads back 0. Two live hypotheses, neither yet confirmed: (a) core_events.c's XCE_CORE_EVENT_JOBS_PUSH handler (used here to simulate a dispatch by directly attaching job1->allocs) never actually calls sched_charge_account()/an equivalent resInUse-charging step for a pushed RUN job carrying allocs -- JOBS_PUSH may be resync-shaped (report already-existing state) rather than dispatch-shaped (perform a fresh charge) by design, making the test's own sanity-check premise wrong; or (b) charging happens but keyed off a different resource-index/worker-pointer path than this test's fixture reads back from. Needs an actual debugging pass (e.g. kiro-debug) to distinguish; not attempted here.", + "fix": "NOT FIXED. Out of scope for the worker-rejoin-resync feature that discovered it (confirmed via git blame this belongs entirely to eb06f16d/.kiro/specs/scheduler-dispatch-commit/, a separate, currently in-flight spec on this shared branch). Logged per this project's bug-tracking convention instead of silently ignoring a real, currently-red test on the shared branch. Needs a dedicated debugging/fix pass scoped to scheduler-dispatch-commit before that spec can be considered complete -- do not patch around it from an unrelated feature.", + "tags": [ + "scheduler-dispatch-commit", + "core_events-c", + "test_core_events-c", + "sched_reconcile_job_resource_usage", + "mem-reservation", + "resInUse", + "unrelated-branch-breakage", + "discovered-by-worker-rejoin-resync-validation", + "not-fixed" + ], + "related_bugs": [], + "occurrences": 1, + "last_seen": "2026-09-02T03:23:00Z" + }, + { + "id": "bug-1759", + "timestamp": "2026-09-02T03:47:00Z", + "error_message": "Live simulation run (xce_scheduler --sim, user-observed, not reproduced by me in this session) shows a JOBS_PUSH batch of 50 jobs where the first 22 (indices [0]-[21]) receive [sim] DISPATCH decisions, immediately followed by [sim] PEND decisions for ALL 50 jobs (indices [0]-[49]) -- including the 22 that had JUST been dispatched. Design expectation (confirmed correct, see root_cause): a job that has received a DISPATCH decision must be treated as RUN immediately, without waiting for any downstream job-start acknowledgment, and must never be reconsidered as a fresh scheduling candidate afterward -- in BOTH the live scheduler and simulation/replay mode.", + "file": "src/scheduler/src/sim_loop.c, src/scheduler/src/plugins/builtin_fcfs.c, src/scheduler/src/scheduler.c", + "root_cause": "NOT YET ROOT-CAUSED -- logged from a live-observed symptom, investigated only via static code reading this session (no live repro attempted), per explicit instruction to log and defer rather than context-switch into a full debug pass. Confirmed via source read: sched_commit_decision() (scheduler.c:1435-1455) DOES set job->state = JOB_STAT_RUN synchronously at the moment a DISPATCH decision is committed, with no wait for any job-start ack -- this is shared code (sched_allocator()/sched_commit_decision()) used by BOTH the normal-mode driver and the sim driver alike (scheduler/CLAUDE.md: \"Both drive the identical core session/decision-callback protocol\"), so the intended \"dispatch implies RUN, immediately\" design IS mechanically implemented at this layer already -- this is not a missing feature. builtin_fcfs.c's on_dispatch() carries its own documented, pre-existing concurrency-hazard comment (\"this runs in the allocator thread and can race the picker thread's next_job() -- jbuf's capacity-1 handoff unblocks the picker for job N+1 before this call for job N returns\"), guarded by fcfs_plugin_data_t.lock for candidate-list mutations, but reading the code alone does not confirm whether that race (or something else -- e.g. two back-to-back sim sessions/rounds failing to preserve job->state or the picker's candidate set between them) is what produces ALL 50 jobs reappearing in one PEND batch, including the 22 already-dispatched ones. Related prior findings: bug-1567 (fixed 2026-08-17) documented that simulation mode ONCE unconditionally PENDed every candidate with no real dispatch at all, deliberately deferred to a then-not-yet-designed scheduler-allocation spec -- the pasted live log now shows genuine DISPATCH decisions in sim mode, meaning that gap has since been closed (scheduler-sim-decision-parity, referenced by bug-1623, 2026-08-22, looks like the likely spec, not yet confirmed which task/commit). bug-1623 also documents sim_loop.c's sim_reconcile_unaccounted_jobs() logic (per-round decoded-decision matching for RUN-state unaccounted jobs) as a separate, related mechanism in the same file worth checking during a real debug pass.", + "fix": "NOT FIXED -- deliberately deferred per explicit instruction (log and continue other work, do not context-switch into a full debug pass now). Needs a dedicated investigation (e.g. /kiro-debug) scoped to sim_loop.c's session/round-driving loop to determine: (a) whether this is one scheduling session emitting a genuine duplicate/second decision for already-dispatched jobs (a real bug in the shared allocator/picker pipeline or in sim_loop.c's own session driving), or two distinct back-to-back sessions where job->state / the picker's candidate set was not correctly carried over between them; (b) whether the identical scenario is reproducible against the NORMAL-mode driver (scheduler.c/driver.c), which would point at the shared sched_allocator/builtin_fcfs code rather than anything sim-specific, or whether it only reproduces in --sim, which would point at sim_loop.c's own session/round handling (possibly interacting with bug-1623's sim_reconcile_unaccounted_jobs()). A live, controlled repro (fixed job count, fixed resource limits, single JOBS_PUSH batch, --sim-verify or a new targeted unit test) should be built first rather than relying on the user's own live-run log.", + "tags": [ + "scheduler", + "sim-mode", + "sim_loop-c", + "builtin_fcfs", + "dispatch", + "pend", + "job-state", + "dispatch-implies-run", + "race-condition-suspected", + "needs-debug", + "discovered-live", + "user-reported", + "not-fixed" + ], + "related_bugs": [ + "bug-1567", + "bug-1623" + ], + "occurrences": 1, + "last_seen": "2026-09-02T03:47:00Z" + }, + { + "id": "bug-1760", + "timestamp": "2026-09-02T04:10:00Z", + "error_message": "Live-tested against a real 3-node HA cluster + xcecd_virtual worker + xce_scheduler (worker-rejoin-resync soak-harness development): after the CURRENT primary is killed and a NEW primary is elected+reconverged, a job submitted through the new primary stays PEND for 60+ seconds with ZERO scheduler.log activity of any kind (no WARN/INFO/ERROR, no reconnect attempt) -- not a slow recovery, a genuinely stuck one. Reproduced twice in a row with the same shape.", + "file": "src/scheduler/src/scheduler.c (sched_needs_rejoin:487, sched_on_reconnect:507, sched_publish_check_rejoin:1474), src/scheduler/src/main.c", + "root_cause": "CONFIRMED via source read (not yet live-instrumented/gdb-confirmed): the scheduler has NO periodic connection-liveness/reconnect check analogous to the worker daemon's checking_connection() (src/worker/src/controller_connector.c:505, called every xcecd_ctx.update_interval seconds from xcecd.c's main loop via xcecli_hello()). The scheduler's ONLY rejoin mechanism is sched_publish_check_rejoin() (scheduler.c:1474), which re-issues xcecli_join() ONLY as a side effect of its own NEXT SUCCESSFUL publish call (sched_publish_dispatch()/sched_publish_pend_reason() via sched_publish_retry_loop(), which calls sched_publish_check_rejoin() only after attempt_fn() already returned >=0). sched_needs_rejoin itself is set correctly by sched_on_reconnect() (the client library's own transparent-reconnect callback), so the SCHEDULER's own underlying connection to the cluster likely IS aware it reconnected somewhere -- but nothing forces a FRESH xcecli_join() against the actual NEW primary until the scheduler has something to publish. After a real controller failover, the scheduler has nothing queued to publish (no job ever reaches its picker/allocator, since the CONTROLLER-side registration of \"where the scheduler is\" is presumed to be live-connection-scoped state on whichever controller instance the scheduler last explicitly joined -- i.e. the dead primary -- and does not appear to carry over to the newly-elected primary), so the scheduler can never publish anything to trigger its own rejoin: a chicken-and-egg deadlock. NOT YET independently confirmed via gdb/live instrumentation which exact half of this loop is stuck (client-library-level reconnect vs. controller-side scheduler-registration loss) -- this is a plausible, evidence-consistent hypothesis from static reading + the observed symptom, not a fully root-caused finding.", + "fix": "NOT FIXED -- discovered as a side effect of unrelated worker-rejoin-resync soak-harness development; deliberately not investigated further or fixed in that session (explicit instruction: log and continue). This is a potentially serious standing HA-availability gap (every job submitted after ANY controller failover could stay PEND forever until the scheduler process is manually restarted) that deserves its own dedicated debugging investigation (e.g. /kiro-debug) scoped to component-failover-adoption's scheduler-rejoin design, ideally with live gdb/log instrumentation to confirm which half of the chicken-and-egg loop is actually broken. Pragmatic workaround adopted ONLY in the worker-rejoin-resync soak harness (.claude/skills/xce-test-ha/run-ha-soak.sh): restart the scheduler process after each round's controller failover, the same way the harness already restarts the downed CONTROLLER node -- a fresh scheduler process calls sched_init(), which tries all 3 candidates in order and joins whichever is actually reachable, sidestepping the stuck reactive-rejoin path entirely. This workaround is scoped to test infrastructure only and does NOT fix the underlying production behavior.", + "tags": [ + "scheduler", + "ha", + "failover", + "rejoin", + "availability", + "component-failover-adoption", + "sched_publish_check_rejoin", + "chicken-and-egg", + "discovered-live", + "needs-debug", + "not-fixed", + "severity-high-suspected" + ], + "related_bugs": [], + "occurrences": 2, + "last_seen": "2026-09-02T04:10:00Z" } ] }