docs(ha-commit-durability): sharpen bug-1306 root cause — xce_run_hooks clobbers commit -ETIMEDOUT

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).
This commit is contained in:
Rongsong Shen 2026-07-01 00:21:23 +00:00
parent 08bdaba3dc
commit 6bb9d81225
2 changed files with 37 additions and 10 deletions

View file

@ -98,3 +98,26 @@ Read-only debug commands in `xce_test`. **NOTE (correction):** `xce_test` does N
- `waldump <data_dir|wal_dir|seg_file>` — ✅ **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 <snap_dir|snap_file>` — TODO. Decode the `XCESNAP` header (lsn) and report whether it carries entities (it likely does NOT — confirms Fork #3).
- `walcompare <dirA> <dirB>` — 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.