myxce/.kiro/specs/ha-commit-durability/INVESTIGATION-failover-job-loss.md

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).

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_TRUNCs 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. (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 (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).

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 — ✅ 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)

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.

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.