diff --git a/.claude/skills/xce-test-ha/SKILL.md b/.claude/skills/xce-test-ha/SKILL.md index a1d3e7cf..75561361 100644 --- a/.claude/skills/xce-test-ha/SKILL.md +++ b/.claude/skills/xce-test-ha/SKILL.md @@ -85,7 +85,13 @@ single machine-parseable verdict line (`soak-verdict.sh`): - **`committed_divergence`** — committed-prefix `walcompare` divergences, counted from task 1.1's `WALCMP_DIVERGENCE … class=committed` machine line (`walcompare --report`). Uncommitted-tail divergences are non-fatal and not - counted. + counted. The per-round (mid-chaos) check only compares members guaranteed + to hold the committed prefix: the live primary plus live standbys whose + `appliedLsn` has reached the boundary. A just-killed ex-primary or a + still-catching-up node can legitimately keep an unreplicated tail (bug-1853: + a NACKed term-4 `lsn=58` vs the new leader's term-5 no-op was a false + "committed" hit). The settled final sweep still compares all three members. + Each `walcompare:` log line names the `members=` it compared. - **`committed_job_loss`** — a tracked, acked job reported `not found` on a **reachable** primary (a real server-side loss, bug-828 class). - **`excluded_bug854_discovery`** — the client could not LOCATE the primary diff --git a/.claude/skills/xce-test-ha/run-ha-soak.sh b/.claude/skills/xce-test-ha/run-ha-soak.sh old mode 100644 new mode 100755 index 191364eb..8dd55921 --- a/.claude/skills/xce-test-ha/run-ha-soak.sh +++ b/.claude/skills/xce-test-ha/run-ha-soak.sh @@ -1402,23 +1402,71 @@ walcheck_count() { # bug-795/828/851/1060 family this spec exists to prevent), and why a # static njobs-derived guess is the wrong fix (it overshoots the real WAL # tip once per-term NOOP entries are counted). - local njobs="$1" d1 d2 d3 out n clsn - d1="$TOP/controller/ctrl-1/data" - d2="$TOP/controller/ctrl-2/data" - d3="$TOP/controller/ctrl-3/data" - if clsn="$(live_committed_boundary)"; then - out="$(printf 'walcompare --report --committed %s %s %s %s\nquit\n' "$clsn" "$d1" "$d2" "$d3" | xtest)" + # + # bug-1853: pass "midloop" as $2 from a mid-chaos check (the cluster is + # NOT settled). A member that is down -- typically the ex-primary this + # round just killed -- or that is alive but has not yet applied up to + # the boundary may legitimately still hold an UNCOMMITTED tail it has + # not truncated yet. Live repro: the killed term-4 primary's NACKed, + # never-committed lsn=58 vs the new term-5 leader's own-term noop at + # lsn=58, counted as class=committed under boundary=auto. So midloop + # (1) takes the serving primary's own committedLsn as the boundary -- + # live_committed_boundary() requires 3-of-3 convergence, which a chaotic + # round (one member always down) never reaches -- and (2) + # compares only live members guaranteed to hold the committed prefix: + # the serving primary, plus standbys whose appliedLsn has reached the + # boundary (every live member under auto). Nothing is hidden for good: + # the settled final sweep calls this WITHOUT "midloop" and compares all + # three members, after the excluded ones have caught up. + local njobs="$1" mode="${2:-full}" out n clsn i nd info role alsn + local dirs=() names=() + clsn="" + if [ "$mode" = "midloop" ]; then + for i in 1 2 3; do + info="$(probe_primary)" && clsn="$(echo "$info" | awk '{print $3}')" + # probe_primary's own ${clsn:-0} default: 0 is untrustworthy + # (see live_committed_boundary()). + [ -n "$clsn" ] && [ "$clsn" != "0" ] && break + clsn="" + sleep 1 + done + else + clsn="$(live_committed_boundary)" || clsn="" + fi + if [ "$mode" = "midloop" ]; then + for nd in "${NODES[@]}"; do + pgrep -f -- "$(node_pattern "$nd")" >/dev/null || continue + info="$(node_probe "$nd")" || continue + role="$(echo "$info" | awk '{print $1}')" + alsn="$(echo "$info" | awk '{print $4}')" + if [ "$role" != "primary" ] && [ -n "$clsn" ] \ + && [ "${alsn:-0}" -lt "$clsn" ]; then + continue + fi + dirs+=("$TOP/controller/$nd/data") + names+=("$nd") + done + if [ "${#dirs[@]}" -lt 2 ]; then + log "walcompare: skipped mid-loop (only ${#dirs[@]} caught-up live member(s): ${names[*]:-none}) — the settled final sweep still compares all 3" + return 0 + fi + else + dirs=("$TOP/controller/ctrl-1/data" "$TOP/controller/ctrl-2/data" "$TOP/controller/ctrl-3/data") + names=("${NODES[@]}") + fi + if [ -n "$clsn" ]; then + out="$(printf 'walcompare --report --committed %s %s\nquit\n' "$clsn" "${dirs[*]}" | xtest)" else clsn="auto" - out="$(printf 'walcompare --report %s %s %s\nquit\n' "$d1" "$d2" "$d3" | xtest)" + out="$(printf 'walcompare --report %s\nquit\n' "${dirs[*]}" | xtest)" fi n="$(printf '%s' "$out" | verdict_count_committed_divergence)" if [ "${n:-0}" -gt 0 ]; then V_DIVERGENCE=$((V_DIVERGENCE + n)) - log "walcompare: COMMITTED DIVERGENCE x$n (jobs so far=$njobs, boundary=$clsn) — COUNTED" + log "walcompare: COMMITTED DIVERGENCE x$n (jobs so far=$njobs, boundary=$clsn, members=${names[*]}) — COUNTED" printf '%s\n' "$out" | grep 'WALCMP_DIVERGENCE' >&2 else - log "walcompare: committed prefix consistent (jobs so far=$njobs, boundary=$clsn)" + log "walcompare: committed prefix consistent (jobs so far=$njobs, boundary=$clsn, members=${names[*]})" fi } @@ -1592,7 +1640,7 @@ run_chaotic_rounds() { # already documents, just newly exposed by worker-resync's added # per-round wall-clock time). verify_classify - walcheck_count "${#ALL_JOBIDS[@]}" + walcheck_count "${#ALL_JOBIDS[@]}" midloop # worker-rejoin-resync: best-effort, same tolerance as submit_jobs # above — chaotic mode never blocks mid-loop for one job's outcome diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 53bfedab..07ccb870 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -25204,6 +25204,36 @@ "MOVE_PTR", "driver" ] + }, + { + "id": "bug-1853", + "timestamp": "2026-09-24T08:20:00Z", + "error_message": "Test-harness false positive, not a controller safety bug. 10-round chaotic soak (run-ha-soak.sh --chaotic 10): VERDICT committed_divergence=1 committed_job_loss=0 result=FAIL. Single hit, round 3, mid-loop walcompare with boundary=auto: 'WALCMP_DIVERGENCE lsn=58 class=committed compared=3 present=3'. Final settled sweep: committed prefix consistent, all 33 jobs present.", + "file": ".claude/skills/xce-test-ha/run-ha-soak.sh", + "root_cause": "LSN 58 was never committed. ctrl-3 (term-4 primary) appended lsn=58 at 08:06:22, its only standby NACKed it ('WAL NACK from standby lsn=58 success=0'), acks never passed acked_lsn=57; the soak then killed ctrl-3. New primary ctrl-1 (term 5) correctly appended its own-term noop at lsn=58 (08:06:35). The round-3 walcheck fell back to boundary=auto (live_committed_boundary unavailable right after the election) and auto-derive (min CRC-intact tip across ALL members' on-disk WALs, including the just-killed ex-primary's) put lsn 58 inside the 'committed' window, so the dead ex-primary's uncommitted term-4 tail vs the new term-5 entry was classified as class=committed. ctrl-3 truncated/overwrote it on rejoin; settled sweep consistent. Same family as the transient-artifact false positives documented at live_committed_boundary()/bug-1487.", + "fix": "FIXED (2026-09-24, harness only). walcheck_count() takes an optional 2nd arg 'midloop', passed only by run_chaotic_rounds' per-round check: it takes the serving primary's own committedLsn (probe_primary, up to 3 tries; live_committed_boundary() needs 3-of-3 convergence, which a chaotic round never reaches -- first cut retried it and always fell back to auto) before falling back to auto, and compares only live members guaranteed to hold the committed prefix -- the serving primary plus live standbys whose node_probe appliedLsn >= boundary (all live members under auto); with fewer than 2 such members the mid-loop check is logged as skipped. Every other caller, including the settled final sweep, keeps the unchanged full 3-member comparison, so an excluded member is still checked once it has caught up. Log lines now name members=. SKILL.md chaotic-verdict section updated. Candidate (c), re-check-after-settle, rejected: a real divergence can 'heal' onto wrong content. Validated: 10-round chaotic soak PASS (committed_divergence=0, job_loss=0).", + "tags": [ + "ha-soak", + "chaotic", + "walcompare", + "false-positive", + "test-harness" + ] + }, + { + "id": "bug-1854", + "timestamp": "2026-09-24T08:35:00Z", + "error_message": "OPEN, NOT FIXED, low priority. Every HA soak run logs 'ERROR [sched_init_resources] sched_init_resources add resource failed' for EVERY configured resource (~33 lines), once per scheduler process, ~30s after it joined -- i.e. when a primary failover makes the scheduler re-join and the controller re-pushes its config (231/264/429 lines in 3 soak runs today). Scheduling is unaffected in those runs (all soaks PASS, replay parity 0 mismatches).", + "file": "src/scheduler/src/scheduler.c", + "root_cause": "sched_init_config() is written as a first-time initializer but runs on every config push (sched_apply_pending_config, including each rejoin's push). sched_init_resources() calls makeResource() for each config->resources[i], which fails when the name is already registered in core.resmgr (key_add of an existing key) and only logs. Consequences: (1) ERROR log noise on every rejoin; (2) latent: a rejoin/upgrade config push that CHANGES a resource definition (flags, valtype, order) never updates the scheduler's copy. Pre-existing -- the same call ran on the handler thread before bug-1846's deferral; not introduced by it. sched_init_queues() re-adding queues on each push is worth checking under the same lens.", + "fix": "NOT FIXED. Candidate: on an existing name, update the registered xce_resource_t in place (or treat identical definitions as a no-op and log at DEBUG), mirroring core_events.c's core_upsert_* upsert posture for RESOURCES_PUSH; decide separately whether a changed definition needs picker/accounting refresh.", + "tags": [ + "scheduler", + "config-push", + "rejoin", + "resources", + "log-noise" + ] } ] }