From 6bb9d81225aaefeab02af673e32f69c0e1d81078 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Wed, 1 Jul 2026 00:21:23 +0000 Subject: [PATCH] =?UTF-8?q?docs(ha-commit-durability):=20sharpen=20bug-130?= =?UTF-8?q?6=20root=20cause=20=E2=80=94=20xce=5Frun=5Fhooks=20clobbers=20c?= =?UTF-8?q?ommit=20-ETIMEDOUT?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 10-round soak waldump+log bisect: the chaotic committed_job_loss is NOT the catch-up/entity-snapshot prefix gap. All 3 WALs gapless/CRC-intact/full payloads; lost job only on ctrl-1@LSN30 term9 vs term-10 NOOP on the majority. The durable-majority gate worked (commit_submit -> -ETIMEDOUT), but xce_run_hooks (hook.c:134-157) returns only the LAST-registered hook's rc, so a later JOB AFTER_EVENT hook (sched/apiserver) returning 0 clobbered persist's -ETIMEDOUT -> handle_jobsubmit replied jobsubmit ok for an uncommitted entry -> term-10 leader legally overwrote it. Fix per raft-apply-decoupling item #1: move the WAL append + commit barrier out of the hook into an explicit handle_jobsubmit-driven raft step whose rc is read directly (down payment on the full apply-after-commit inversion). Entity-snapshot gap is a separate, still-real defect (not this soak's mechanism). --- .../INVESTIGATION-failover-job-loss.md | 23 ++++++++++++++++++ .wolf/buglog.json | 24 +++++++++++-------- 2 files changed, 37 insertions(+), 10 deletions(-) diff --git a/.kiro/specs/ha-commit-durability/INVESTIGATION-failover-job-loss.md b/.kiro/specs/ha-commit-durability/INVESTIGATION-failover-job-loss.md index 0ada671..2e48a29 100644 --- a/.kiro/specs/ha-commit-durability/INVESTIGATION-failover-job-loss.md +++ b/.kiro/specs/ha-commit-durability/INVESTIGATION-failover-job-loss.md @@ -98,3 +98,26 @@ Read-only debug commands in `xce_test`. **NOTE (correction):** `xce_test` does N - `waldump ` — ✅ **DONE 2026-06-20.** Per node/segment, lists every entry `lsn | term | type | payload_len | jobid`, flags **LSN gaps** (non-contiguous / missing prefix) + the CRC recovered tip; nonzero exit on gap/CRC-break so it doubles as an E2E assertion. Impl: `src/controller/testsuite/waldump.{c,h}` (module), `cmd_waldump` wired into `top_commands` in `test.c`; unit test `test_waldump.c` (5 cases, hand-built raw segments). **Validated live** against `/tmp/xce-ha-deploy/controller/ctrl-{1,2,3}` — reproduced the exact bug table (ctrl-1 full 1–15; ctrl-2 missing prefix 1–15; ctrl-3 missing prefix 1–12). Also surfaced a NEW anomaly: each JOB_SUBMIT appears as a **consecutive duplicate pair** (same jobid at LSN N and N+1) — worth a follow-up. - `snapdump ` — TODO. Decode the `XCESNAP` header (lsn) and report whether it carries entities (it likely does NOT — confirms Fork #3). - `walcompare ` — TODO. Diff two nodes' logs by `lsn → crc/jobid` to flag divergence/gaps instantly. + +## UPDATE 2026-06-30 — SHARPENED ROOT CAUSE for the chaotic-soak loss: `xce_run_hooks` clobbers the durability `-ETIMEDOUT` + +The 10-round chaotic soak (`/home/claude/tmp/ha-1296`) loss is **NOT** the prefix-gap/entity-snapshot mechanism above. Decisive WAL evidence (waldump): +- All three nodes are **gapless, CRC-intact, full 6504B payloads** (so NOT bug-847 payload-drop, NOT a trimmed prefix — `seg-...001` present on all three, `snap/` empty, no trim fired). +- Lost job `0-0-1782854622-0` exists **only on ctrl-1 @ LSN 30, term 9**; ctrl-2/ctrl-3 hold a **term-10 NOOP @ LSN 30** (the new leader's first entry). Classic divergent uncommitted tail at the term 9→10 boundary. + +ctrl-1's controller log (PID 406309, term-9 leader) shows the durable-majority gate **worked correctly**: +``` +commit: WAIT deadline expired without commit (lsn=29 committed_lsn=0 writable_lsn=28 timeout_ms=500) +commit: WAIT deadline expired without commit (lsn=30 ...) <- the lost job +commit: WAIT deadline expired without commit (lsn=31 ...) +``` +The standby was still catching up (`standby[1] lsn=23 < committed_lsn=29`), so LSN 30 never reached majority → `repl_wait_majority_ack` → `commit_submit` returned **`-ETIMEDOUT`**, and `persist_wal_sync_append` propagated it (persist.c:2550-2551), and `persist_job_hook_fun` returned it (persist.c:2849). + +**The leak is in `xce_run_hooks` (src/lib/hook.c:134-157).** It runs all hooks for the type but `rc` is **overwritten every iteration** and it `return rc` — i.e. it returns ONLY the LAST-registered hook's value (the `break` is `BEFORE_EVENT`-only). Multiple JOB `AFTER_EVENT` hooks are registered (`apiserver_job_hook_fun` apiserver.c:545, `sched_job_hook_fun` sched.c:651, `persist_job_hook_fun` persist.c:615 + re-added on promotion ha.c:3436). When `persist_job_hook_fun` returns `-ETIMEDOUT` but a later-registered hook returns 0, **the `-ETIMEDOUT` is clobbered to 0**. `handle_jobsubmit` (job.c:593-611) then sees `hook_rc == 0`, skips the reject path (job.c:603 — confirmed: NO "rejecting job" line in ctrl-1's log), and replies `jobsubmit ok` (job.c:613-618) for an entry that was never majority-committed. A term-10 leader then legally overwrites LSN 30 → **committed-job-loss** + the harness's `committed_job_loss` count. + +This VIOLATES the CLAUDE.md **Commit Durability** invariant (reply-success ⇒ majority-durable). `handle_jobsubmit`'s gate is correct; the durability signal is destroyed one layer down in the shared hook runner. + +### Fix (surgical, libxce) +`xce_run_hooks` must not let a later hook's success clobber an earlier hook's failure on `AFTER_EVENT`: fold to a **sticky-negative** rc (run every AFTER_EVENT hook, but once any returns < 0 preserve it; return the first/any negative). `BEFORE_EVENT` keeps veto/break semantics. This restores "AFTER_EVENT fails if ANY hook failed," which is exactly what `handle_jobsubmit` already assumes. RED: register two AFTER_EVENT hooks where the first returns `-ETIMEDOUT` and the second returns 0; assert `xce_run_hooks` returns `-ETIMEDOUT`. Blast radius: shared by controller/worker/scheduler — audit any consumer relying on the *last* hook's positive rc (none known; consumers treat non-zero as failure). + +NOTE: the entity-bearing-snapshot / prefix-trim gap documented above is a SEPARATE, still-real defect (it bites a node that rejoins after a checkpoint trims the prefix). It is just not the mechanism this particular soak hit — confirm with a soak that forces a checkpoint+trim. diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 12e0e07..1168db3 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -21660,19 +21660,23 @@ "id": "bug-1306", "timestamp": "2026-06-30T14:31:00-07:00", "error_message": "6-round chaotic-failover soak FAIL: committed_job_loss=4 committed_divergence=7 (rounds 4-6). Committed job 0-0-1782829181-1 permanently absent on reachable primary from round 4 on, across 3 elected primaries; rounds 1-3 clean.", - "file": ".kiro/specs/ha-commit-durability/INVESTIGATION-failover-job-loss.md (persist.c/config_repl.c catch-up streaming)", - "root_cause": "PRE-EXISTING failover catch-up gap (bug-795/828/851 family): a just-restarted node rejoins mid-churn and is elected primary WITHOUT backfilling the full committed prefix (empty-rejoin catch-up streams [watermark..committed], no snapshot backfill) -> permanent gap that propagates as peers catch up FROM the gapped node. First OBSERVED here because the 5.8 endpoint-refcount fix (bug-1298) let a chaotic soak run past round 4 for the first time.", - "fix": "NOT FIXED \u2014 EXTERNAL spec ha-commit-durability (+ raft term/log-safety); raft-ha-core-safety task 5.9. NOT a regression: zero WAL/commit/catch-up code changed this session (only ep-refcount + 5.7 election-timeout); ASAN clean; rounds 1-3 loss-free; rounds 4-6 never reached before (no prior baseline).", + "file": "src/lib/hook.c (xce_run_hooks); job.c:603 gate is correct", + "root_cause": "SHARPENED 2026-06-30 (waldump+log bisect of the 10-round soak): NOT the catch-up prefix-gap/entity-snapshot mechanism. xce_run_hooks (src/lib/hook.c:134-157) returns only the LAST-registered hook's rc (rc overwritten each loop iter; break is BEFORE_EVENT-only). The durable-majority gate works: a term-9 leader's job at LSN 30 timed out commit (peers mid-restart, repl_wait_majority_ack -> commit_submit -> -ETIMEDOUT), persist_job_hook_fun returned -ETIMEDOUT, but a later-registered JOB AFTER_EVENT hook (sched/apiserver) returned 0 and CLOBBERED it -> handle_jobsubmit saw hook_rc==0 -> replied 'jobsubmit ok' for an uncommitted entry -> term-10 leader legally overwrote LSN 30 (term-10 NOOP) -> committed-job-loss. Violates the Commit Durability invariant (reply-success => majority-durable). Evidence: all 3 WALs gapless/CRC-intact/full payloads; lost job only on ctrl-1@LSN30 term9 vs term10 NOOP on majority; ctrl-1 log has the WAIT-deadline-expired WARNs and NO 'rejecting job' line.", + "fix": "PROPOSED (not yet applied): make xce_run_hooks fold to a sticky-negative rc on AFTER_EVENT (run all hooks, preserve the first/any rc<0; BEFORE_EVENT keeps veto/break). RED: two AFTER_EVENT hooks, first returns -ETIMEDOUT, second 0 -> assert xce_run_hooks returns -ETIMEDOUT. Then re-run the chaotic soak: committed_job_loss must be 0. SEPARATE still-real gap: entity-bearing snapshots for trimmed-prefix rejoin (not this soak's mechanism).", "tags": [ - "data-loss", - "failover", - "committed-job-loss", - "catch-up-gap", "ha-commit-durability", - "soak", "pre-existing", "not-a-regression", - "task-5.9" + "soak", + "task-5.9", + "committed-job-loss", + "commit-durability", + "term-boundary-divergence", + "catch-up-gap", + "failover", + "hook-rc-clobber", + "ack-before-majority", + "data-loss" ], "related_bugs": [ "bug-795", @@ -21681,7 +21685,7 @@ "bug-1298" ], "occurrences": 1, - "last_seen": "2026-06-30T14:31:00-07:00" + "last_seen": "2026-06-30T14:35:00Z" }, { "id": "bug-1307",