diff --git a/.claude/skills/xce-test-ha/run-ha-soak.sh b/.claude/skills/xce-test-ha/run-ha-soak.sh index 643f7f4..fc5d768 100755 --- a/.claude/skills/xce-test-ha/run-ha-soak.sh +++ b/.claude/skills/xce-test-ha/run-ha-soak.sh @@ -919,8 +919,44 @@ walcheck_count() { # the expect-job result via the verdict parser. Increments V_JOBLOSS on a REAL # loss (reachable primary, tracked job "not found") and V_BUG854 when the client # cannot locate the primary (discovery fault — EXCLUDED). Never hard-fails. +# +# Retries a LOSS classification up to 5 times (2s settle between attempts) before +# counting it, mirroring verify_no_loss's bug-1422 "whole check" retry — same +# rationale, sharpened by a real bug-1487 live-repro measurement specific to +# chaotic mode: unlike wait_for_new_primary (which only waits for the new +# primary to be SERVING at a higher term) and unlike the sequential loop's +# wait_for_full_convergence (which waits for 2 consecutive fully-converged +# probes before the NEXT kill), this function runs immediately once a new +# primary is detected, with no settle window of its own. +# +# A newly-elected primary cannot advance its OWN committed_lsn past entries +# inherited from a PRIOR term merely because it holds them durably (Raft +# Figure-8 safety, `ha_arm_own_term_gate` in ha.c: "the universal commit +# barrier still requires per-entry majority of a new-term entry"). It appends +# an own-term WAL_NOOP on promotion and only folds in the earlier, already- +# majority-committed prefix once THAT noop itself gets a fresh majority ack +# under the new term. In steady state this closes in well under 200ms (round +# 24 of this same run: safe_committed_lsn -> committed_lsn advance in 167ms). +# But chaotic mode deliberately restarts the PREVIOUS round's downed node +# without waiting for it to reconverge before landing the NEXT kill (the +# "overlapping" design) -- so if that still-catching-up node is the one whose +# ack the new leader needs for its own-term barrier, the window stretches to +# however long that node's WAL catch-up stream takes. Live-repro evidence +# (bug-1487, this exact run): round 25 killed ctrl-1 while ctrl-3 was still +# reconnecting from round 25's own overlapping restart; ctrl-2 was elected at +# 04:47:52.470 with safe_committed_lsn=99 "(from 2 granted voters)" while its +# OWN committed_lsn (last known as a standby) stayed at 100 -- excluding the 3 +# jobs (lsn 101-103) ctrl-1 had already majority-committed (self + ctrl-2's +# own ack) moments before dying. committed_lsn did not jump to 104 (folding in +# 101-103) until ctrl-3's catch-up stream let it ack the new leader's own-term +# noop at 04:47:58.702 -- 6.232s later. verify_classify's single, immediate +# expect-job query landed inside that window and counted a false LOSS for a +# job that was genuinely durable/majority-committed the whole time and was +# confirmed present on every later verify (rounds 26-30 and the final sweep). +# 5 attempts x 2s settle gives ~8s of margin above the measured 6.232s gap +# while staying bounded -- a job still missing after that is a REAL loss. verify_classify() { - local primary out cls want="${#ALL_JOBIDS[@]}" + local primary out cls want="${#ALL_JOBIDS[@]}" attempt [ "$want" -eq 0 ] && return 0 primary="$(discover_primary)" if [ -z "$primary" ]; then @@ -939,8 +975,15 @@ expect-job $jid" done script+=" quit" - out="$(printf '%s\n' "$script" | xtest)" - cls="$(printf '%s' "$out" | verdict_classify_verify 1)" + for attempt in 1 2 3 4 5; do + out="$(printf '%s\n' "$script" | xtest)" + cls="$(printf '%s' "$out" | verdict_classify_verify 1)" + [ "$cls" = "LOSS" ] || break + if [ "$attempt" -lt 5 ]; then + log "verify_classify attempt $attempt/5: reachable primary $primary reports a tracked job missing (likely post-election own-term commit-barrier lag while a peer is still catching up, bug-1487 class) — settling 2s and rechecking before counting a loss" + sleep 2 + fi + done case "$cls" in LOSS) V_JOBLOSS=$((V_JOBLOSS + 1)) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 83c4625..8fb1351 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -13795,9 +13795,11 @@ "ha-soak", "workflow" ], - "related_bugs": [], - "occurrences": 1, - "last_seen": "2026-07-23T09:50:00Z" + "related_bugs": [ + "bug-1486" + ], + "occurrences": 2, + "last_seen": "2026-07-31T03:48:00Z" }, { "id": "bug-1465", @@ -14412,5 +14414,78 @@ ], "occurrences": 1, "last_seen": "2026-07-29T21:10:00Z" + }, + { + "id": "bug-1485", + "timestamp": "2026-07-30T14:35:00Z", + "error_message": "test_e2e_live_ha_push.py::test_live_config_push_against_primary_reaches_success_path flaky (near-100% fail rate across ~25 live runs during admin-config-tool task 6.3 round-2 remediation): TimeoutError: controller never opened localhost:: [Errno 111] Connection refused, raised from a fresh wait_for_port re-probe of the elected primary's own address performed AFTER _wait_for_primary (CTRL_PRIMARY marker) + a new _wait_for_standbys (both other nodes show CTRL_STANDBY) + a 3s settle sleep all already succeeded.", + "file": "src/xceadmin/tests/test_e2e_live_ha_push.py (live_ha_cluster fixture); root cause is in src/controller (exact site not yet isolated -- C-side investigation out of this task's boundary)", + "root_cause": "NOT a pure test-side readiness race as round-1 review assumed. Live forensic capture (ps aux mid-run) caught the freshly-elected ctrl-1 as a zombie process moments after its own log recorded the full raft_cb_become_leader promotion sequence ending at 'HA: repl registered standby ep[1] (slot 1, ...)' -- the log then goes silent (no crash trace, no further lines) and the process is gone. stderr was DEVNULL'd in the fixture so no ASAN/signal diagnostic was captured from a real failing pytest run. Confusingly, 3 separate standalone (non-pytest) repro scripts using byte-identical spawn code (same xce_controller build.dbg binary, same deploy-ha.sh cluster, same peers/certs/workdir args) ran the exact same primary-promotion sequence successfully every single time with the primary staying alive and the port reachable for 20-30s post-election -- while pytest-invoked runs of the identical fixture code failed roughly 24/25 times. Ruled out during investigation: pytest's default fd-capture (reproduced with -s / capturing disabled, still failed 3/3), ulimits (NPROC/NOFILE/AS/STACK identical between nix-develop plain-shell and pytest-invoked-via-python contexts), and orphaned-process port contention (ps aux clean before each batch). True root cause not isolated -- prime suspects are a genuine timing-sensitive controller-side crash/race in the CTRL_STANDBY->CTRL_PRIMARY raft promotion path (raft_cb_become_leader / repl registration) that pytest's process tree somehow makes far more likely to trigger, or a process-group/session/signal-mask difference inherited by subprocess.Popen children when the parent is pytest vs a bare python3 script.", + "fix": "NOT FIXED. Task 6.3 round-2 remediation implemented exactly what the round-1 reviewer asked for (_wait_for_standbys mirroring test-heartbeat-tolerance.sh's two-phase primary+standby gate, a heartbeat_interval_ms-justified 3s settle delay, and a fresh wait_for_port re-probe of the primary before yielding the fixture) but this did not close the flake because the underlying failure is the primary process disappearing, not merely its port being slow to open -- no test-side wait can outlast a process that is gone. Reported BLOCKED back to the task's parent controller rather than continuing to chase a C-level root cause outside this task's explicit boundary (controller-side C changes forbidden). Next step for whoever picks this up: capture stderr (not DEVNULL) from a real pytest-triggered failure to get an ASAN report or signal number, and/or strace the primary process across a live failing pytest run to see whether/why its listening socket closes.", + "tags": [ + "flaky-test", + "ha", + "raft-election", + "controller-crash", + "admin-config-tool", + "task-6.3", + "e2e-live", + "unresolved", + "pytest-specific" + ], + "related_bugs": [ + "bug-1477", + "bug-1479", + "bug-606" + ], + "occurrences": 24, + "last_seen": "2026-07-30T14:35:00Z" + }, + { + "id": "bug-1486", + "timestamp": "2026-07-31T03:48:00Z", + "error_message": "Backgrounded `xce-build.sh all` run went silently stale mid-flight ([360/362], no ninja FAILED/error line, no completion marker, log just stopped growing at 03:38:35) with no matching build process left in `ps aux`", + "file": "src/tools/xce-build.sh", + "root_cause": "Multiple DIFFERENT Claude agent sessions independently invoked xce-build.sh against the same shared worktree's src/xce.build directory at the same time (confirmed via `ps auxf`: sibling `bash src/tools/xce-build.sh controller` and a separate `... all` invocation running under different parent `claude --output-format stream-json` PIDs). xce-build.sh has no lock/mutex around its unconditional `rm -rf \"$BUILD_DIR\"` + `meson setup` step (same code path as bug-1464), so a peer session's rm -rf tore the build directory out from under this session's own in-progress ninja/meson compile with no error propagation -- the backgrounded process's output just stops, indistinguishable at first glance from a hang.", + "fix": "No code change; workflow fix. Before trusting a backgrounded xce-build.sh log that has gone stale, run `ps auxf | grep -E 'xce-build|meson|ninja|cc1'` to check for a sibling xce-build.sh invocation from a different session targeting the same worktree. If found, do not start a third concurrent build -- bounded-poll (`while kill -0 $PEER_PID; do sleep 5; done`, not a passive wait for a background-task notification) until all peer invocations exit, then run exactly one clean blocking `xce-build.sh all` and treat only that run's own output as ground truth. Real fix would be a flock/lockfile around setup_build()'s rm-rf+meson-setup step in xce-build.sh itself so concurrent sessions serialize instead of clobbering.", + "tags": [ + "build", + "xce-build.sh", + "meson", + "ninja", + "race-condition", + "concurrent-sessions", + "multi-agent", + "workflow" + ], + "related_bugs": [ + "bug-1464" + ], + "occurrences": 1, + "last_seen": "2026-07-31T03:48:00Z" + }, + { + "id": "bug-1487", + "timestamp": "2026-07-31T04:50:00Z", + "error_message": "30-round chaotic HA soak (run-ha-soak.sh --chaotic 30): committed_job_loss=1 at round 25/30 (VERDICT result=FAIL). expect-job reported job 0-6-1785473261-216067 not found on newly-elected primary ctrl-2 (term=27) immediately after the round-25 kill of ctrl-1 (term=26). committed_divergence stayed 0 for the entire run; the job (and all others) was confirmed present on every subsequent verify (rounds 26-30) and the final post-run sweep of all 93 tracked jobs.", + "file": ".claude/skills/xce-test-ha/run-ha-soak.sh", + "root_cause": "NOT a controller bug and NOT genuinely-uncommitted-at-kill-time -- test-harness false-positive, root-caused with log/timestamp evidence from the preserved run (/home/claude/tmp/xce-ha-chaos30-run1/logs/ctrl-{1,2,3}.log). ctrl-1 (primary, term=26) majority-committed all 3 round-25 jobs (lsn 101,102,103; self + ctrl-2 ack) between 04:47:41.839 and 04:47:42.052 -- confirmed via commit_advance_locked log lines -- moments before being killed at 04:47:42+. ctrl-2 was elected primary at term=27 at 04:47:52.470 with ha_compute_safe_committed_lsn reporting safe_committed_lsn=99 \"(from 2 granted voters)\" -- the conservative Raft floor, since ctrl-3 (the only other reachable voter) was itself mid-restart/catch-up from round 25s own overlapping-kill design and had not yet caught up past lsn 99. Per the documented Raft Figure-8 safety mechanism (ha_arm_own_term_gate, ha.c:4997-5046: \"the universal commit barrier still requires per-entry majority of a new-term entry\"), a newly-elected primary cannot fold a PRIOR-term entry into its own committed_lsn watermark merely because it holds it durably -- it must first get a fresh majority ack, under its OWN term, for its own-term WAL_NOOP (armed at promotion). ctrl-2s committed_lsn stayed at 100 (excluding lsn 101-103) until ctrl-3s WAL catch-up stream let it ack the term-27 noop at lsn=104, at 04:47:58.702 -- 6.232s after promotion (commit_advance_locked: \"committed_lsn 100 -> 104\"). expect-job (joblist query) reads c->jobmgr, which the apply pump only populates for entries that have reached this committed_lsn watermark -- so the job was genuinely invisible, by design, for that 6.232s window. run-ha-soak.shs verify_classify() (chaotic mode) runs its expect-job check immediately once wait_for_new_primary detects the new primary is SERVING at a higher term -- unlike verify_no_loss (sequential mode; already carries a 3-attempt/2s-settle retry from bug-1422 for a related but distinct client-retry-storm race) and unlike wait_for_full_convergence (which chaotic mode intentionally skips between kills, by design, to land kills inside overlap windows) -- so its single, instantaneous query landed inside the 6.232s barrier window and counted a false LOSS. Comparison: round 24s election (ctrl-1, term=26) closed the identical barrier window in only 167ms because the other voting peer was not mid-catch-up at that moment -- the window duration is directly proportional to how far behind the second required peer is, which chaotic modes overlapping-restart design can occasionally push to several seconds.", + "fix": "Added a bounded retry (5 attempts, 2s settle between) around the expect-job/verdict-classify check in verify_classify() (.claude/skills/xce-test-ha/run-ha-soak.sh) -- mirrors verify_no_loss/bug-1422s \"retry the whole check\" precedent, only retrying on a LOSS classification (BUG854/OK still resolve on the first attempt, matching prior semantics). ~8s of total settle margin comfortably covers the measured 6.232s worst-case gap while staying bounded -- a job still missing after 5 attempts still counts as a genuine LOSS, so real committed-job loss detection is unweakened. Verified with a full, fresh 30-round chaotic re-soak (see run2 VERDICT).", + "tags": [ + "xce-test-ha", + "chaotic-soak", + "verify_classify", + "raft-commit-barrier", + "apply-decoupling", + "false-positive", + "test-harness" + ], + "related_bugs": [ + "bug-1422", + "bug-1431", + "bug-1432" + ], + "occurrences": 1, + "last_seen": "2026-07-31T04:50:00Z" } ] diff --git a/.wolf/cerebrum.md b/.wolf/cerebrum.md index 2981121..d6c73a1 100644 --- a/.wolf/cerebrum.md +++ b/.wolf/cerebrum.md @@ -587,3 +587,21 @@ bug-1479 (permanent quorum loss when a standby log-conflicts during chaotic elec ## Key Learning (2026-07-29, raft-adapter-conformance task 5.1) — the bug-1479 fix commit (34ab78d7) already shipped a reply-construction-boundary regression test; the spec's "motivating finding" premise ("no test was ever written asserting the reply itself gets constructed") was not fully accurate `test_config_repl.c`'s `test_bug1479_ae_reject_sends_nack_not_silence` (added IN the bug-1479 fix commit itself, before this spec existed) already asserts `ha_wal_ack_send_hook` fires with `success=0` on a WAL catch-up logOk reject — exactly the "reply itself gets constructed" boundary requirements.md's motivating finding claimed was untested. Confirmed by `git log -p -S` on the test name: it landed in 34ab78d7, not in this spec. Task 5.1's explicit `_Boundary:_` (`test_ha_core_safety.c`) still called for an independent copy built from that file's own `hcs4_*` fixture family, so it was added anyway (`test_5_1_wal_catchup_reject_sends_nack_reply`) — genuinely useful redundant coverage (a future change to the reject branch is now caught in two files' fixture families instead of one), just not closing a gap that was actually still open. **Do-not-repeat**: when a spec's "motivating finding" describes a coverage gap, grep for the exact assertion shape (here: the hook name `ha_wal_ack_send_hook` + `success=0`) across the WHOLE test suite before treating the gap as confirmed-empty — a fresh audit pass can miss a test that already exists in a sibling file, especially one added in the same commit as the fix it's paired with. Report the discrepancy as a CONCERN in the task's status report rather than silently either skipping the task or presenting it as if it closed a real gap. + +## Do-Not-Repeat (2026-07-30, admin-config-tool task 6.3) — a bare `re.search()` against a log with MULTIPLE occurrences of the same pattern silently matches the FIRST one, not the one you actually care about +Writing `test_e2e_live_ha_push.py`'s standby-ACK evidence check as `_STANDBY_SAVED_RE.search(standby.log_file.read_text())` looked correct and even matched a real, live `handle_repl_config_push` line — but a standby's log legitimately gets MULTIPLE `handle_repl_config_push` events over one test's lifetime (an automatic bootstrap sync of the primary's already-loaded config fires right after election, BEFORE the test's own `xceadmin config push`), so `search()`'s first match was always the OLDER bootstrap tag, never the specific push under test, and the assertion failed unconditionally regardless of whether the real ACK happened. Fixed with `re.finditer(...)` checked against ALL occurrences. **Do-not-repeat**: when asserting "this specific event happened" against a log a long-lived process keeps appending to, always consider whether the SAME log line shape can legitimately appear more than once for unrelated reasons before reaching for `re.search()` — default to `finditer`/`findall` + an explicit identity check (here: the exact tag) unless you've confirmed the pattern is provably unique in that log. + +## Key Learning (2026-07-30, admin-config-tool task 6.3) — design.md's own "Boundary Commitments"/"Revalidation Triggers" sections are the first place to check before writing a live test whose task text assumes a capability might not exist server-side +Task 6.3 asked for a live redirect-following test (`config push` to a standby → follows redirect to primary → succeeds). Live-verified against a real 3-node cluster: it does NOT redirect — `ha_dispatch_gate()` rejects a standby's `OP_upgradeConfig` with `E_XCE_STANDBY` (10014) BEFORE the opcode-specific handler runs, and `fill_redirect_reply()` (`join.c`) is only ever wired for `OPCode_join`, never `OPCode_upgradeConfig`. This was NOT a surprise requiring fresh investigation — `design.md`'s own "Out of Boundary" section already documented this exact gap verbatim ("Redirect wiring for `OP_upgradeConfig`... it will not fire for `config push` until the controller is extended"), and "Revalidation Triggers" already lists the fix as a future, not-yet-done item. **Do-not-repeat**: before writing ANY live/E2E test whose premise is "component X's capability Y works end-to-end," grep the spec's own design.md for "Boundary Commitments"/"Out of Boundary"/"Revalidation Triggers" sections FIRST — if the capability is already flagged there as not-yet-implemented, the test should be written to lock in the REAL current (rejection) behavior with a pointer to the trigger that will make it stale, not spend a debugging cycle rediscovering a documented gap from scratch via trial and error. + +## Do-Not-Repeat (2026-07-30, admin-config-tool task 6.3) — Bash tool calls that `pkill` a process this session itself backgrounded can report a misleading exit code (144) even when the command's actual effect (killing the process, running rm -rf) succeeded +Multiple `pkill -f xce_controller; sleep 1; ...` bash calls in this session reported exit code 144 (not a standard shell exit code — looks harness-level, not `$?`-derived) even though a follow-up `pgrep -af xce_controller` in the NEXT call confirmed the kill had actually taken effect. This only ever happened on calls that killed/interacted with background xce_controller processes this same session had spawned (via `subprocess.Popen`/pytest fixtures or manual `&`/`setsid nohup`), never on unrelated trivial commands. **Do-not-repeat**: don't treat a 144 exit code as proof a cleanup/pkill command failed — verify with an independent follow-up check (`pgrep`, `ls`) in a SEPARATE bash call before concluding anything is actually broken; retrying the exact same command (or just checking state) is usually enough, no special handling needed. + +## Do-Not-Repeat (2026-07-31, bug-1464 extended) — `xce-build.sh`'s unconditional `rm -rf $BUILD_DIR` races across MULTIPLE CONCURRENT AGENT SESSIONS on this same worktree, not just across sequential single-component invocations +Ran `/xce-build all` (backgrounded) in this session while at least two OTHER Claude sessions were, unbeknownst to this session at launch time, ALSO independently invoking `xce-build.sh` (`controller`-only, then a separate `all` run) against the exact same shared `src/xce.build` dir in `/home/rshen/projects/xce/worktrees/config` — visible via `ps auxf` as sibling `bash src/tools/xce-build.sh ...` processes under different parent `claude --output-format stream-json` PIDs. This session's own backgrounded `all` run got silently torn out mid-flight ([360/362], no error, no completion marker, log just stopped growing) — almost certainly because a peer's `xce-build.sh` invocation hit line ~59's unconditional `rm -rf "$BUILD_DIR"` (same bug-1464 root cause, `BUILD_DIR` defaults to `xce.build` regardless of which component(s) you pass) out from under the still-running ninja/meson process. **This is a strictly worse variant of bug-1464**: the original note was about ONE session sequencing single-component builds; this shows even two *concurrent* full `all` builds from *different* sessions collide the same way, because `xce-build.sh` has no lockfile/mutex around its clean-then-setup step — there is no cross-session coordination at all. **Do-not-repeat**: before trusting a backgrounded `xce-build.sh` run's own log as authoritative (silent, no error, log just stops growing), run `ps auxf | grep -E 'xce-build|meson|ninja|cc1'` to check for a SIBLING invocation targeting the same worktree/BUILD_DIR from a different session — if found, do not stack a third concurrent build on top; wait (bounded poll on the peer PID, not a passive "background notification" — see next entry) for it to fully exit, THEN run your own single clean blocking build and treat only that run's own output as ground truth for a report. If this recurs, the real fix belongs in `xce-build.sh` itself (e.g. `flock` around the `rm -rf`+`meson setup` step), not in caller-side workarounds. + +## Do-Not-Repeat (2026-07-31) — a Bash `run_in_background` task inside a background *subagent* invocation may never deliver its "you'll be notified when it completes" notification; don't wait passively on it +As a subagent (spawned via the `Agent` tool, running in the background from the parent's perspective), a `Bash` call with `run_in_background: true` did not visibly notify this session on completion even after several idle turns — a peer/coordinator message eventually had to point out "you're a subagent, you don't get woken up by background task notifications, check `ps aux` and wait blocking instead," which held up on inspection (the process really had died, torn out by the concurrent-build race in the entry above). **Do-not-repeat**: when running as a background subagent (not the top-level session), do NOT rely on Bash background-task completion notifications to resume work — either (a) run the long command in the foreground with a generous explicit `timeout` (up to 600000ms), or (b) if backgrounding is unavoidable (command may exceed 10 min), actively self-poll with a bounded `while kill -0 $PID; do sleep N; done` foreground Bash call rather than idling and waiting for a push notification that may never arrive in this execution context. + +## Key Learning (2026-07-31, bug-1487) — a "committed job loss" in `--chaotic` xce-test-ha soaks can be a false positive caused by the Raft own-term commit barrier, not real data loss — always check `verify_classify`'s timing before touching controller code +Root-caused a `committed_job_loss=1` chaotic-soak FAIL entirely from logs/timestamps, no code change to `src/controller/`. Mechanism: a newly-elected primary cannot fold a PRIOR-term entry into its own `committed_lsn` watermark just because it holds it durably (Raft Figure-8 safety; `ha_arm_own_term_gate` in `ha.c` — every promotion appends an own-term `WAL_NOOP` and only advances `committed_lsn` past the inherited prefix once THAT noop itself gets a fresh majority ack under the new term). `expect-job` reads `c->jobmgr`, populated only by the apply pump once entries cross `committed_lsn` — so a genuinely majority-committed job can be transiently invisible on the brand-new primary until that fresh ack lands. In steady state this closes in <200ms, but `--chaotic` mode's own "restart the previous round's downed node with no convergence wait" design means the peer whose ack is needed can itself be mid-catch-up, stretching the window to several seconds (measured live: 6.232s). `run-ha-soak.sh`'s chaotic-mode `verify_classify()` ran its `expect-job` check immediately on primary detection with zero settle/retry (unlike `verify_no_loss`, which already had a bug-1422 3-attempt/2s retry, and unlike `wait_for_full_convergence`, which chaotic mode deliberately skips between kills). Fix was a bounded retry in `verify_classify` alone (5×2s), never touching `src/controller/`. **Do-not-repeat**: before treating any xce-test-ha `committed_job_loss` count as a real controller bug, first check (a) whether the SAME job shows up as present in every LATER verify/final-sweep in the same run (a real loss never comes back; this class of false-positive always does), and (b) whether `verify_classify`/whichever check flagged it has an equivalent settle/retry to its sibling `verify_no_loss` — chaotic and sequential modes have historically drifted out of sync on this (bug-1422 fixed sequential only; bug-1487 caught chaotic's matching gap 3 weeks later).