fix(xce-test-ha): chaotic mid-round walcompare false committed divergence (bug-1853)
A chaotic round's walcheck compared all three members' on-disk WALs with boundary=auto. The just-killed term-4 primary still held its NACKed, never-committed lsn=58, which differed from the new term-5 leader's own-term noop at lsn=58, and was counted as class=committed. walcheck_count now takes an optional "midloop" mode, used only by the per-round chaotic check: the boundary is the serving primary's own committedLsn (live_committed_boundary() needs 3-of-3 convergence, which a chaotic round never reaches), and only members guaranteed to hold the committed prefix are compared -- the primary plus live standbys whose appliedLsn has reached the boundary. Every other caller, including the settled final sweep, still compares all three. Log lines name members=. Also logs bug-1854 (scheduler re-adds every configured resource on each rejoin config push; ERROR noise, changed definitions ignored) for follow-up. 10-round chaotic soak: PASS (divergence 0, job loss 0, SIMVERIFY 9 files, 0 mismatches). Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
d9ff02cdc1
commit
5b891b50c2
3 changed files with 95 additions and 11 deletions
|
|
@ -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
|
||||
|
|
|
|||
68
.claude/skills/xce-test-ha/run-ha-soak.sh
Normal file → Executable file
68
.claude/skills/xce-test-ha/run-ha-soak.sh
Normal file → Executable file
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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 <name> 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"
|
||||
]
|
||||
}
|
||||
]
|
||||
}
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue