docs(ha-commit-durability): root-cause findings for failover committed-job loss (bug-828)

WAL-byte decode proves REAL data loss (not commit-index): committed prefix
entries physically absent from live nodes (ctrl-2 WAL starts LSN 16, ctrl-3 LSN
13), present only on the down node. Mechanism: empty-rejoin catch-up streams
[watermark..committed] not [1..], no snapshot to backfill the prefix -> permanent
gap. Predates libxce-failover. Full findings + open forks + xce_test waldump
tooling plan in INVESTIGATION-failover-job-loss.md. Not yet fixed.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-06-20 13:51:40 +00:00
parent 5508b0b51c
commit 7d70820aac
2 changed files with 990 additions and 567 deletions

View file

@ -0,0 +1,58 @@
# Investigation: committed jobs lost across controller failover (bug-795 family)
> Live investigation 2026-06-20. Status: **root-cause located, fix not yet applied.** This is the long-standing data-loss bug (PREDATES libxce-failover — confirmed by the user; libxce-failover + xce-test-e2e-primitives were *test-infrastructure* improvements, not the durability fix). Owning spec: **ha-commit-durability** (REOPENED for bug-795). Adjacent: ha-convergence-recovery, ha-single-leader-role, ha-peer-connection-reuse.
## Symptom
Running the **controller failover test** (kill primary / restart nodes while a client submits jobs), committed jobs that were ACKed (`jobsubmit ok`) and visible in `joblist` **disappear** after enough kill/restart cycles. In the captured run, jobs survived terms 2→4 then vanished at the term-4→5 transition; `ctrlstatus` then showed them absent. NOT a `committedLsn` display bug — the data is genuinely gone.
## DECISIVE EVIDENCE — it is real data loss, not a commit-index issue
Decoded the raw WAL bytes at `/tmp/xce-ha-deploy/controller/ctrl-{1,2,3}/data/wal/seg-0000000000000001.wal` (format: `wal_entry_hdr_t` 40B `{term,lsn,timestamp,type,payload_len,crc,prev_crc}` + payload; `src/include/wal_types.h`):
| Node | WAL entries (physical) | JOB_SUBMITs | State |
|------|------------------------|-------------|-------|
| ctrl-1 | LSN **1–15** (starts NOOP@1) | **12** | full history — but **DOWN** (`connect peer failed -111`) |
| ctrl-2 | LSN **16–18** (starts NOOP@16) | 2 | live, **missing 1–15** |
| ctrl-3 | LSN **13–18** (starts NOOP@13) | 4 | live, **missing 1–12** |
The committed prefix (LSN 2–12 = the lost jobs) is **physically absent** from both live nodes; it exists only on the down node. `snap/` dirs are **empty** on all nodes (no snapshot).
## ROOT CAUSE (mechanism, code-grounded)
A node that (re)joins with an **empty WAL** is brought up to the cluster's **current committed watermark by WAL streaming `[watermark..committed]` — NOT from LSN 1 — and there is no snapshot to backfill `[1..watermark-1]`.** So it ends up with a permanent prefix gap. When the failover test eventually has the only full-log node down while the others rejoined at high watermarks, the committed jobs are gone for good.
Why the `seg-...001` file contains LSN 16: a node booting empty defaults `current_lsn=1` (`persist.c:429`); the first write lazily calls `open_new_segment` which names the file by `current_lsn` → `seg-...001` and **`O_TRUNC`s** it (`persist.c:145`); catch-up then writes entries carrying explicit high LSNs (16…) from offset 0. So "writes from the beginning of the file" = **booted empty + caught up from the watermark**, not an in-place overwrite of recovered data. (`replay_wal` at `persist.c:1422` is correct — it opens existing segments **read-only** and advances `current_lsn` past what it recovers.)
## OPEN FORKS (what to settle next)
1. **Test procedure — clean vs preserve.** `scripts/cleanup.sh` does `rm -rf .../data/*`; `scripts/start.sh` only creates `data/` if missing (preserves). The on-disk files (named `001`, starting at 16/13) match the **cleaned** case. **Confirm with the user whether the failover test cleans data dirs before restart or restarts with data intact.**
- If preserved + node still returns gapped → **recovery bug** (`replay_wal` failing to restore).
- If cleaned → **catch-up never backfills the prefix + no snapshot** = the architectural gap below.
2. **Catch-up start point (the actual bug site, NOT yet read).** Trace the `CtrlHello` handshake: does a rejoining standby advertise its **real `applied_lsn`** (fresh ⇒ 0 ⇒ should stream from 1) or a **learned/committed watermark** (⇒ streams from 13/16)? `CtrlHelloRequest.appliedLsn @2` is the value the primary streams `[applied+1..committed]` from. This single field decides the fix: "stream from 1 / install a snapshot first" vs "advertise real applied, not learned committed."
3. **Snapshots.** `snap/` is empty everywhere. Is snapshot *creation* implemented/triggered in this build, or only `load_snapshot` (`persist.c:1266`, format `"XCESNAP\0"` + 8-byte lsn header — looks like a STUB carrying only an LSN, NO entities)? If snapshots never carry job entities (the "entity-bearing snapshots" backlog item in ha-convergence-recovery), then ANY WAL pruning/empty-rejoin below committed is unrecoverable BY DESIGN. **Strong candidate for the architectural root.**
## SECONDARY FINDINGS
- **`term=0` on every WAL entry.** `p->term` (the `hdr.term` source) is **never assigned** the election term anywhere (grep for `p->term =` / `->term =` in persist.c/ha.c returns nothing). So per-entry term is dead. XCE matches logs via the `prev_crc` chain, so possibly benign — but it means **no term-based divergence detection**. Worth a hard look (could let divergent same-LSN entries be treated as matching).
- **Cluster cannot hold a primary** under the test: peer connect `-111` (ECONNREFUSED), RDHUP, rapid term churn 2→5 in ~7 min, elections logged `safe_committed_lsn=X (from 1 granted voters)`. Logged separately in `ha-convergence-recovery/research.md` (2026-06-20 live finding).
- **Crash fixed en-route (unrelated):** `xce_strerror_r` global-buffer-overflow on HA error codes — bug-827, fixed in `src/lib/utils.c` (commit 1aa0761).
## Is the ha-heartbeat-committed-propagation change implicated?
The loss **predates** it, so it is **not the origin**. But two real concerns it introduces (it writes `last_known_committed_lsn` per-heartbeat, decoupled from WAL possession):
- `ha_enter_real_election` (`ha.c:4137`) truncates WAL above `last_known_committed_lsn` — a heartbeat-fed value now feeds a truncation path (violates the Req 3.1 "advisory-only" boundary I claimed; guarded by `if (committed>0)` so 0 is safe, but still a real boundary leak).
- If the rejoin/catch-up advertised position is derived from `last_known_committed_lsn`, the per-heartbeat freshness would **widen** the prefix gap (fresh node learns committed=13 via heartbeat → advertises 13 → streams from 14). **This is exactly Open Fork #2 — read the CtrlHello advertise path; it also settles aggravation.**
- Candidate-advertise is SAFE: `ha_candidate_advertise_lsn` (`ha.c:2598`) returns bare `persist_durable_floor`, NOT last_known — so a behind node cannot fake election freshness.
## REPRO / ARTIFACTS (on this host)
- Live deploy with the failed run: `/tmp/xce-ha-deploy/` — controller logs `logs/ctrl-{1,2,3}.log`, WAL `controller/ctrl-N/data/wal/seg-...001.wal`, empty `snap/`.
- Offline WAL decoder (Python, ad-hoc) — walks `wal_entry_hdr_t`, lists `lsn|term|type|payload_len`, flags submits by header timestamp. (To be productized as `waldump`, below.)
- Deployed binary includes controller-status (responderTime) + ha-heartbeat-committed (the `ha.c:4967 "learned committed_lsn=X from heartbeat"` logs are the consume path).
## NEXT STEPS
1. **Build the WAL/snapshot inspection tooling in `xce_test`** (in progress — see plan below) so clean-vs-preserve and gap-location become a 30-second check each run.
2. **Read the CtrlHello catch-up advertise/start-point** (`config_repl.c` handle_ctrlhello + the standby's CtrlHelloRequest build) — Open Fork #2.
3. **Confirm whether snapshot creation exists** or is a stub — Open Fork #3 (likely the architectural root: no entity-bearing snapshot ⇒ no prefix backfill).
4. Decide fix layer: (a) full-WAL stream `[1..committed]` when a node has no snapshot, (b) implement entity-bearing snapshots + install-before-stream, or (c) prevent empty-rejoin from advancing committed without holding the entries. Likely a **question-the-architecture** moment (catch-up assumes a snapshot safety net that does not exist).
## TOOLING PLAN (xce_test enhancement — requested by user)
Add read-only debug commands to `xce_test` (`src/controller/testsuite/test.c`; binary links `persist.c`/`job.c` per `controller/meson.build`, so the capnp `restore_job`/`read_Job` decode and `wal_types.h` are available):
- `waldump <data_dir|wal_dir|seg_file>` — per node/segment, list every entry `lsn | term | type | payload_len | jobid(submits, via capnp `read_Job`/`decode_Job`)`, flag **LSN gaps** (non-contiguous / missing prefix) and the recovered tip.
- `snapdump <snap_dir|snap_file>` — decode the `XCESNAP` header (lsn) and report whether it carries entities (it likely does NOT — confirms Fork #3).
- `walcompare <dirA> <dirB>` — diff two nodes' logs by `lsn → crc/jobid` to flag divergence/gaps instantly.
Start with `waldump` (highest value; decoder logic already proven in Python). Register in the `client_commands`/`top_commands` table (`test.c:175/207`).

File diff suppressed because it is too large Load diff