checkpoint: bug-851 root cause + raft TLA+ conformance spec family

Investigation & fixes (failover committed-job loss):
- root-cause bug-851 on an owned 3-node cluster: chaotic failover causes
  silent committed-prefix divergence (WAL hdr.term always 0; two leaders
  per term; no (term,lsn) reconcile). Evidence in repro-851/ + INVESTIGATION.
- live-validated fixes 848/849/850 (recovery-on-promotion, advertise real
  applied_lsn, persist-layer contiguity guard); add waldump WAL inspector.

Specs (strict raft.tla conformance — library owns the log):
- TLA-gap-analysis.md: impl vs raft/raft.tla, gaps G1-G6.
- raft-log-replication, raft-commit-safety, raft-sim-conformance: extend
  src/lib/raft to own log/commit/verification via callbacks (specs generated,
  cross-spec review passed).
- ha-term-safety: controller-side adapter + config marker (R1-R7); design done.
- config-upgrade-snapshot: R8 descoped here (deps entity-bearing-snapshots, bug-857).
- roadmap + buglog (851/854/857) + .wolf knowledge updated.
This commit is contained in:
Rongsong Shen 2026-06-21 14:02:15 +00:00
parent 7d70820aac
commit 20e59d0b42
85 changed files with 10525 additions and 1993 deletions

View file

@ -16,19 +16,36 @@ Decoded the raw WAL bytes at `/tmp/xce-ha-deploy/controller/ctrl-{1,2,3}/data/wa
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).
## DECISIVE EVIDENCE 2 — catch-up streaming DROPS payloads (bug-847, REPRODUCED 2026-06-20)
A live restart of ctrl-1 (kill ctrl-1 → restart) showed it rejoin and catch up to the cluster length `[1..14]` with **correct LSN/type/CRC chain but EMPTY payloads** — `waldump` reports every JOB_SUBMIT as `PLEN=0 PCRC=00000000 jobid=?`, while ctrl-2/ctrl-3 still hold full 872-byte payloads. So the WAL is **structurally intact but content-empty** — silent corruption that passes every check that doesn't decode the payload (the `PCRC` column is what exposed it). This, not just the missing-prefix gap, is a concrete committed-job-loss mechanism: if the empty-payload node ever leads, the empty entries become authoritative.
**Root cause (reproduced in a unit test):** the catch-up batch wire path (`xce_wal_batch_encode_raw`/`wal_entry_to_wire` in `src/lib/request.c`) builds a `WalCatchupEntry` struct-list whose per-element `payload :Data` is allocated via `capn_new_list8(cs=root_seg,…)`. When the batch outgrows its first capnp segment, the per-element payload `Data` pointer is **lost across the segment boundary** → on decode `extract_data_bytes(we.payload)` reads `CAPN_NULL` → `raw_payload_len=0` → the receiver writes a payload-less entry. **`test_wal_batch_roundtrip_large_payloads` (14×872B) FAILS "Expected 872 Was 0"; the 2-entry round-trip PASSES** — the threshold is message SIZE (segment overflow), not entry count. **Live replication (`repl_broadcast`) carries payloads fine — only the catch-up/rejoin path corrupts**, which is exactly why loss surfaces only after a node restarts and catches up. Candidate fix: carry all sub-entry payloads as ONE top-level capnp `Data` blob + lengths (single `Data` round-trips correctly), sidestepping per-element cross-segment pointers. RED test is in `src/lib/testsuite/test_wal_wire.c`.
## 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.**
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.** (Still worth confirming for the exact trigger ordering, but no longer the architectural question — see VERDICT.)
- 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.**
- If cleaned → **catch-up never backfills the prefix + no snapshot** = the architectural gap (CONFIRMED below).
2. **Catch-up start point — ✅ SETTLED (2026-06-20).** Traced. `handle_ctrlhello` (`config_repl.c:1436`) is connection-setup ONLY; catch-up is driven by the heartbeat decision loop. The standby reports its **REAL `applied_lsn`** — `ha_process_standby_state(ha, peer_idx, sr.config_tag, sr.applied_lsn, …)` at `ha.c:3518`, where `sr.applied_lsn` is the standby's own state-report value (an empty standby reports 0). The decision `ha_evaluate_repl_action` (`ha.c:1811`) is CORRECT: `standby_lsn+1 < oldest_wal_lsn → SEND_SNAPSHOT`, `else standby_lsn < committed → STREAM_WAL`. So advertise is NOT the bug — a fresh standby correctly asks for a snapshot when the primary's WAL no longer starts at 1.
3. **Snapshots — ✅ SETTLED: THIS IS THE ROOT CAUSE (2026-06-20).** `write_snapshot` (`persist.c:1051`) writes a **16-byte SENTINEL**: `"XCESNAP\0"` (8) + `checkpoint_lsn` (8) — its own comment says *"Full Cap'n Proto serialization is Task 11."* It carries **ZERO job/queue entities.** `load_snapshot` (`persist.c:1267`) just does `p->checkpoint_lsn = p->current_lsn = stored_lsn` — it **advances the watermark past entries it never received, restoring nothing.** And `persist_checkpoint` → `trim_wal_segments` (`persist.c:1090`) **deletes WAL segments below the checkpoint.** So checkpoint = "trim the committed prefix + write an empty backup": a WAL-eating loop with no recoverable safety net. This is the "entity-bearing snapshots" gap (ha-convergence-recovery backlog) — and it makes any empty-rejoin/prefix-trim below committed **unrecoverable BY DESIGN.**
## VERDICT (2026-06-20) — architectural root confirmed, code-grounded end-to-end
The loss is **not** an advertise/start-point bug and **not** a recovery bug. It is the **absence of entity-bearing snapshots** combined with **prefix-trimming checkpoints**. Full mechanism:
1. A fresh/empty member (applied_lsn=0), or any member catching up against a primary whose own `oldest_wal_lsn > 1` (its prefix was trimmed by a prior checkpoint).
2. `ha_evaluate_repl_action` → `SEND_SNAPSHOT` (when `1 < oldest_wal_lsn`) or `STREAM_WAL` from the high watermark.
3. SEND_SNAPSHOT path: `persist_checkpoint` writes the **sentinel** (no entities) + **trims the prefix WAL**, then ships the sentinel; receiver `persist_load_snapshot` sets `current_lsn = checkpoint_lsn` with **no entity restore**.
4. STREAM_WAL path: `ha_stream_wal_to_standby` streams `[standby_lsn+1 .. committed]`; `ha_apply_wal_catchup_entry`/`ha_apply_single_entry` **physically persist** those entries (consistent with ctrl-3's on-disk seg holding LSN 13–18) — but the prefix `[1..oldest-1]` is **never streamed and has no snapshot to backfill it.**
5. Net: the member's watermark reaches `committed` while the committed-prefix job entities are gone. **Permanent loss, BY DESIGN.**
**Fix layer (recommendation — option (b), question-the-architecture):** implement **entity-bearing snapshots** — `write_snapshot` Cap'n-Proto-serializes all live job/queue entities at `checkpoint_lsn`; `load_snapshot` deserializes + `restore_job`/restore_queue them BEFORE advancing `current_lsn`; and `trim_wal_segments` must NOT trim below the LSN covered by a durable entity-bearing snapshot (install-snapshot-before-stream on the receive side). Option (a) "stream `[1..committed]`" only works while some node still retains LSN 1 (false after any trim), so it is a partial mitigation, not the fix. This is the **ha-convergence-recovery** "entity-bearing snapshots" item; route the fix there (or a new `ha-entity-snapshots` spec) under the ha-commit-durability umbrella.
## SECONDARY FINDINGS
- **Double `WAL_JOB_SUBMIT` per job (bug-845, 2026-06-20, via waldump).** Every committed job appears as TWO consecutive entries with the SAME jobid (ctrl-1: 2,3 / 4,5 / … ; ctrl-3: 14,15 ; ctrl-2: 17,18). **Ruled out array expansion:** `job_submit` assigns array members DISTINCT ids (`base_id+i`, job.c) and the `Job` capnp has a single jobid field, so identical-jobid pairs are NOT two array tasks — a single submit is double-appending. **CONFIRMED a literal byte-for-byte double-append** by the enhanced waldump (payload-CRC + subtime columns, 2026-06-20): each pair is byte-identical — same PCRC (LSN 2,3 both `6d79074e`; 4,5 `c25ac163`; …) and same `subtime` (e.g. 1781959730), so all 12 ctrl-1 submits = 6 jobs × 2. A failover retry would re-stamp `subtime=time(NULL)` and differ → **retry definitively ruled out; it's the SAME encoded `job_t` written twice in one submit flow.** It is replicated *consistently* (F=…555020288 at 14,15 on BOTH ctrl-1 and ctrl-3; G at 17,18 on BOTH ctrl-2/3), so not itself divergence, but it doubles LSN consumption and is a latent cross-node divergence risk if the duplicate count ever varies by primary. Next: trace `handle_jobsubmit`→`persist_job_hook_fun` AFTER_EVENT loop (jlist holding the job twice, or a double hook-fire).
- **Raft cross-node consistency check (user request, 2026-06-20).** Per-LSN comparison of the three dumps: at every OVERLAPPING index the entries AGREE — ctrl-1∩ctrl-3 = {13:NOOP, 14:F, 15:F}; ctrl-2∩ctrl-3 = {16:NOOP, 17:G, 18:G}. So **State Machine Safety (no two members hold different entries at the same index) is NOT violated** in this snapshot; no job sits at different LSNs on different nodes. The broken guarantee is **Leader Completeness / durability**: jobid E=…394588160 was committed+acked at LSN 11–12 (present on ctrl-1) but is ABSENT from the surviving majority (ctrl-2/3) — a committed entry lost (exactly the root-cause mechanism: it was below the survivors' empty-rejoin catch-up start, with no entity snapshot to backfill it). Conversely G=…630517760 is on the survivors but absent on ctrl-1, which was already down before G — losing an entry a crashed minority-node never had is Raft-legal. So the cluster ended with two committed histories sharing only the F segment: ctrl-1's {…,E@11-12,F@14-15} vs survivors' {F@14-15,…,G@17-18}.
- **`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).
@ -45,14 +62,39 @@ The loss **predates** it, so it is **not the origin**. But two real concerns it
- 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.
1. **Build the WAL/snapshot inspection tooling in `xce_test`** — ✅ `waldump` DONE (2026-06-20). `snapdump`/`walcompare` still TODO. Gap-location is now a one-liner per 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).
## DECISIVE EVIDENCE 3 — bug-851 REPRODUCED & ROOT-CAUSED on an owned cluster (2026-06-21)
Stood up a fresh local 3-node cluster (`/xce-deploy-ha`, binary built with the 848/849/850 fixes) and drove two scenarios with full log access. Artifacts: `repro-851/{ctrl-1,ctrl-2,ctrl-3}.log` + `waldump-ctrl-{1,2,3}.txt`.
**Scenario 1 — clean single failover: PASS (848/849/850 validated end-to-end).**
6 jobs → identical `1..13` on all 3 (matching PCRCs). Kill primary ctrl-1 → ctrl-3 promoted: `cluster_init_phase2: persist_recover done — recovered durable_floor=13 … applied_lsn=14 advertised` (bug-849 recovery-on-promotion + bug-848 advertise-real-LSN both fire). 4 jobs on new primary → ctrl-2 converges `14..22`. Restart old primary → recovers `1..13`, catches up `14..22`. **Final: all three WALs byte-identical `1..22`, identical PCRC fingerprint `cc5d361e…`, 0 gaps.**
**Scenario 2 — chaotic leadership churn (3× kill-the-primary): FAIL — silent committed-prefix divergence.**
After 3 rounds, all three report `committedLsn=54`, all `lsn range 1..54`, 0 gaps, CRC intact — **but the logs DIVERGE at LSN 45–54**:
- ctrl-1: `45=NOOP`, `46..53 = faead246/be0059bf/fe7a3d0b/37d54e4d` → fp `bfeb26ad…`, 25 jobids
- ctrl-2: `45=NOOP`, `46..53 = d32ac747/97c04cbe/d7ba280a/1e155b4c` (DIFFERENT jobs) → fp `216af434…`, 25 jobids
- ctrl-3: `45 = 4c6d24e6` (a JOB, no noop), `45..52 = 4c6d24e6/0887af1f/48fdcbab/8152b8ed` → fp `865304ec…`, 26 jobids
Three different "committed" tails, each node reporting them committed. This violates the Raft committed-prefix invariant (a committed entry must be byte-identical on every member).
**ROOT CAUSE (code-grounded, three compounding defects):**
1. **Term not monotonic across the cluster.** Election term = *locally-persisted* term + 1; PreVote explicitly does NOT persist/propagate ("starting PreVote round … no persist"). Under chaotic kills a leader wins term N, appends its own-term noop + jobs, and is killed **before term N is durably propagated to a majority**. A restarted node recovers a *stale* term and elects at the **same** N+1. Logs show **two leaders at term 3** (ctrl-3 @08:40, ctrl-1 @08:47:39) and **two leaders at term 4** (ctrl-2 @08:47:52, ctrl-3 @08:48:04) — each appending its own-term noop at the **same LSN 45**. Persisted terms ended split: ctrl-1=4, ctrl-2=4, ctrl-3=3.
2. **The WAL entry term field is DEAD (always 0).** `wal_entry_hdr_t.term` exists (wal_types.h:30) and the replication envelope carries `term` (typemap.h:381), but the writer does `hdr.term = p->term` (persist.c:588/726/1040) and **`p->term` is NEVER assigned from `ha->term` anywhere in the controller** (zero matches). Every entry, every term, persists `term=0`. waldump confirms term=0 cluster-wide.
3. **No (term,lsn) reconcile → divergent tails never truncated.** Because the WAL has no usable per-entry term, rejoin-reconcile (`ha_convergence.c`) cannot do Raft log-matching: entry 45@ctrl-1 (term 3) and 45@ctrl-2 (term 4) look identical (both term 0, both JOB_SUBMIT/NOOP), so the divergent suffix is taken as already-present and is never overwritten. `ha_compute_safe_committed_lsn` then advances committed (44, 53) "from 1 granted voter" over content that other members never received.
Net: under leadership churn, acked entries written by a short-lived leader become a permanent divergent tail, and `committed` advances over it → silent loss + cross-node divergence. This is distinct from the catch-up payload-drop (bug-847) and the empty-rejoin gap (bug-828); it is a **Raft-safety gap in term establishment + WAL term recording**.
**Keystone fix candidate (smallest correct lever):** stamp `hdr.term` from the live raft term (`ha->term`) on the primary append path + carry it through the replication envelope + persist it, THEN make reconcile truncate any local suffix whose (term,lsn) does not match the leader's — standard Raft log-matching. Must be paired with making the election term durably-established-before-acting (no two leaders per term). **HA-core + persistence → full spec workflow required (per CLAUDE.md); not a quick patch.**
**Secondary (separate) finding — client primary-discovery is positional, not failover-correct.** With `masters = [m0, m1, …]`, the client (`xcecli_ctrlstatus_primary`, client.c:403) only reaches the primary if `m0` IS the primary: a standby answers `primaryName=""` ("unknown" by design, ctrlstatus.c:104) so no redirect hint is captured, and the inner `xcecli_ctrlstatus` SUCCEEDS on the reachable non-primary so transport failover never rotates. Confirmed: `9993`(primary-first)→ok 45ms; `9992,9993`(standby-first)→"no primary"; `9991,9993`(dead-first)→"no primary"; `9993,9991`→ok. Also the dead node returns `ctrlstatus failed: Invalid argument` (bug-846 EINVAL). This is what made earlier remote sessions read as "committed frozen" — the client was pinned to a stale/standby node. Fix options: (a) standby tracks+reports the primary name it heartbeats with (enable redirect), or (b) client rotates to the next master on a reachable-but-non-authoritative reply.
## 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`).
Read-only debug commands in `xce_test`. **NOTE (correction):** `xce_test` does NOT link `persist.c`/`job.c` — it builds from `test.c` only + `libxce`. But `read_Job` is generated into `controller.capnp.c` which IS compiled into `libxce`, so the capnp decode is reachable; `waldump` adds `c_capnproto_dep`+`zlib_dep` to `xce_test_deps` and ships its own zero-alloc jobid decode (reads `struct Job.jobid` after `read_Job`, no `decode_Job`).
- `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.