From 0eb105431b74c4ba026c57a78b848b00fdedd2ca Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Wed, 8 Jul 2026 00:05:19 +0000 Subject: [PATCH] =?UTF-8?q?fix(raft-apply-decoupling):=20bug-1419=20layer?= =?UTF-8?q?=202=20=E2=80=94=20checkpoint=5Flsn=20mislabeled=20from=20WAL?= =?UTF-8?q?=20tip=20instead=20of=20applied=20cursor?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit persist_checkpoint() stamped checkpoint_lsn from p->current_lsn (physical WAL append tip) instead of p->last_applied_lsn (the true "jobmgr reflects up through here" cursor), uncoordinated with the async apply pump introduced by raft-apply-decoupling. write_snapshot() serializes live jobmgr state, so a checkpoint taken while apply lags the WAL tip mislabels the snapshot: on restart last_applied_lsn is re-seeded from checkpoint_lsn and replay resumes strictly above it, silently skipping committed-but-not- yet-applied entries jobmgr never received. This is the actual mechanism behind kill-mid-apply producing a permanent APPLY_DIVERGENT fence — apply_committed_entry() is deterministic/idempotent and write_snapshot() is crash-atomic, so the bug was a mislabeled watermark, not a structural divergence requiring a safety/liveness tradeoff. Fix stamps checkpoint_lsn from last_applied_lsn and holds apply_pump_lock across the label capture + write_snapshot() so the label and the jobmgr state it describes are captured atomically w.r.t. the live apply pump. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01VgT3n4vTv4ZjCuCTmzed1F --- .wolf/buglog.json | 11 +- .wolf/memory.md | 208 ++++++++++++++++++ src/controller/persist.c | 28 ++- .../testsuite/test_persist_checkpoint.c | 54 +++++ 4 files changed, 292 insertions(+), 9 deletions(-) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index ebe66ed9..ab0553ec 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -12640,7 +12640,7 @@ "error_message": "[xce-test-ha --chaotic] genuine, reproducible election-liveness stall (not the bug-1418 harness process-stacking artifact, which was a separate, now-fixed issue): after 2+ overlapping kills, the surviving 2-node set can permanently deadlock -- neither node can ever become primary again for the rest of the run.", "file": "src/controller/persist.c (apply-correctness verification) + src/controller/ha.c (PreVote freshness gate) + WAL duplicate-submit mechanism (unlocated)", "root_cause": "Direct log/WAL analysis (waldump on the affected node's data dir) during a live repro superseded two prior, less-precise theories filed as bug-1418 (a shell-script process-stacking artifact, unrelated and separately fixed; and an unverified ha->term/ha->raft.term \"term desync\" claim that does not match the code -- raft_begin_pre_vote/ha_start_prevote_async both read s->term == ha->raft.term directly, there is no separate stale-field read on the PreVote path).\n\nACTUAL mechanism observed: waldump on ctrl-3's WAL (the node with the longest/freshest log after the chaotic kill sequence) showed \"duplicate submits: 3 (byte-identical: 0)\" -- the SAME jobid appended to the WAL twice with DIFFERING payloads (different subtime, different CRC), e.g. lsn=13 and lsn=14 both jobid=0-0-1783418222-0 but distinct subtime/PCRC. This is NOT bug-845's mechanism (that fix, landed 2026-06-23, was for byte-IDENTICAL double-hook-registration dupes and is confirmed still working -- these are non-identical). count_jobmgr_entries() legitimately sees these as 2 distinct job-table mutations (or the entity count otherwise fails to match the WAL-replay-derived expectation), so persist_recover()'s post-replay apply-correctness check (task 5.1, Req 8.1/8.2) correctly fires APPLY_DIVERGENT -> the loud, sticky, non-promotable fence (raft-apply-decoupling Req 8.3/8.4) -- this fencing behavior is WORKING AS DESIGNED, not itself a bug.\n\nThe resulting LIVENESS bug: with the fenced node holding the only sufficiently-fresh (longest) log, the other surviving node can never win the PreVote freshness gate against it (correctly, per Raft/PreVote semantics -- it really is behind), while the fenced node itself can win Raft elections (quorum_reached/became_leader observed at terms 27/30/32 in logs) but its own raft_cb_become_leader promotion gate refuses CTRL_PRIMARY every time (apply_divergent=1). With the third node dead (killed by the chaotic driver) and never restarted long enough to catch up, NO node can ever become primary again -- a genuine, reproducible liveness deadlock, distinct from (and downstream of) the WAL duplicate-submit root cause. Confirmed via direct log grep across ctrl-1.log/ctrl-3.log at the exact stall timestamps (09:57:16 divergence detected, repeating \"PreVote DENIED ... reason=freshness\" and \"promotion REFUSED ... apply_divergent=1\" through 10:05+); NOT root-caused via speculation.", - "fix": "PARTIALLY FIXED (2026-07-07). Root cause of layer (1), the WAL duplicate-non-identical-submit mechanism, is now located and fixed: raft-apply-decoupling task 3.1 deferred job/entity construction in c->jobmgr until AFTER commit (apply_committed_entry, post-commit apply pump), but jobid_range_exists() -- the sole dup guard in handle_jobsubmit -- only checks c->jobmgr. A submission that is durably WAL-appended and awaiting its commit outcome does not yet exist in c->jobmgr, so a client-side retry for the SAME jobid (XCECLI_FAILOVER_CALL/xce_failover_classify's idempotent-replay contract resends on a transport error or failover-mid-flight) sailed straight past the guard and appended a second, non-identical WAL_JOB_SUBMIT entry (different subtime/CRC) for the same jobid -- exactly the 'duplicate submits: N (byte-identical: 0)' signature waldump showed. Fix: src/controller/job.c adds a process-lifetime in-flight-jobid-range registry (s_inflight_submits, guarded by s_inflight_submits_lock) that handle_jobsubmit atomically check-and-claims (inflight_range_try_add) immediately after the existing jobid_range_exists check, and releases (inflight_range_remove) from jobsubmit_async_ctx_release -- the same release point already shared by the commit-continuation and apply-complete paths, so the range stays claimed for exactly the window a duplicate could land in. A resubmit for a still-in-flight jobid now gets -EEXIST immediately, with no second WAL append. Regression test test_jobsubmit_resubmit_before_resolution_rejected_no_dup_wal_entry added to test_commit_barrier_reply.c (RED confirmed -EEXIST not returned pre-fix; GREEN after). Verified via the full 78-group controller_unit_test sweep (782 tests, 0 failures) -- zero regressions, including the 6 apply-pump/commit-barrier groups most adjacent to this change.\n\nLayer (2), the PreVote-freshness/apply-divergence liveness deadlock itself (when the ONLY sufficiently-fresh candidate is apply-divergent-fenced and no reconciliation path exists), remains UNFIXED and is now the sole open part of this bug -- it needs its own design discussion (forcing promotion of a divergent node, or truncating its uncommitted-but-locally-applied entries, both have real correctness implications), not a quick patch. With layer (1) fixed, this deadlock should no longer be reachable via the duplicate-submit path specifically, but the underlying design gap in raft-apply-decoupling's promotion-refusal logic is independent and could still be triggered by any other cause of a genuine, permanent APPLY_DIVERGENT fence on the only fresh-enough node.", + "fix": "FIXED (2026-07-07). Layer (1), the WAL duplicate-non-identical-submit mechanism: raft-apply-decoupling task 3.1 deferred job/entity construction in c->jobmgr until AFTER commit (apply_committed_entry, post-commit apply pump), but jobid_range_exists() -- the sole dup guard in handle_jobsubmit -- only checks c->jobmgr. A submission that is durably WAL-appended and awaiting its commit outcome does not yet exist in c->jobmgr, so a client-side retry for the SAME jobid (XCECLI_FAILOVER_CALL/xce_failover_classify's idempotent-replay contract resends on a transport error or failover-mid-flight) sailed straight past the guard and appended a second, non-identical WAL_JOB_SUBMIT entry (different subtime/CRC) for the same jobid -- exactly the 'duplicate submits: N (byte-identical: 0)' signature waldump showed. Fix: src/controller/job.c adds a process-lifetime in-flight-jobid-range registry (s_inflight_submits, guarded by s_inflight_submits_lock) that handle_jobsubmit atomically check-and-claims (inflight_range_try_add) immediately after the existing jobid_range_exists check, and releases (inflight_range_remove) from jobsubmit_async_ctx_release. Regression test test_jobsubmit_resubmit_before_resolution_rejected_no_dup_wal_entry added to test_commit_barrier_reply.c (RED->GREEN confirmed). Committed fe4352f.\n\nLayer (2), the PreVote-freshness/apply-divergence liveness deadlock: initially framed as needing a fundamental safety/liveness design tradeoff among 3 unpalatable options (force-promote a divergent node / truncate committed-but-unapplied entries / relax the freshness gate) -- this framing was WRONG, corrected after user pushback (\"kill-mid-apply should be recoverable per Raft protocol\", \"I do not think break FSM invariant is a good idea\"). Root-caused instead to a concrete, scoped bug: persist_checkpoint() (persist.c:2261-2263, now fixed) stamped p->checkpoint_lsn from p->current_lsn (the physical WAL append tip) instead of p->last_applied_lsn (the true 'jobmgr reflects up through here' cursor, persist.h:344-363 documents these as DISTINCT once apply is decoupled from commit). write_snapshot() serializes live c->jobmgr, so a checkpoint taken while the async apply pump lags behind the WAL tip mislabels the snapshot: on restart, last_applied_lsn is re-seeded FROM checkpoint_lsn and replay resumes strictly above it, silently skipping committed-but-not-yet-applied entries that jobmgr never actually received -- the real mechanism behind kill-mid-apply producing a permanent APPLY_DIVERGENT fence. Confirmed apply_committed_entry() is fully deterministic/idempotent (rules out non-determinism) and write_snapshot() is crash-atomic at the file level (temp+fdatasync+rename, rules out torn-file corruption) -- the bug is purely a mislabeled watermark, not a structural divergence. Fix: persist_checkpoint() now reads checkpoint_lsn from last_applied_lsn and holds apply_pump_lock across the label-capture + write_snapshot() call so the label and the jobmgr state it describes are captured atomically w.r.t. the live apply pump (the pump only ever moves last_applied_lsn/jobmgr forward, so freezing it here rules out the label ever claiming more than jobmgr actually holds). test_checkpoint_sets_checkpoint_lsn updated (now simulates apply catch-up explicitly, since a cluster-less unit-test persist_t never runs the apply pump); new regression test test_checkpoint_lsn_tracks_last_applied_not_current_lsn added to test_persist_checkpoint.c (RED confirmed pre-fix: checkpoint_lsn took the WAL tip=7 instead of the simulated applied cursor=2; GREEN after). Full 78-group/782-test controller_unit_test sweep: 0 failures.", "tags": [ "ha", "election", @@ -12650,8 +12650,9 @@ "chaotic-failover", "liveness", "wal-duplicate-submit", - "partially-fixed", - "liveness-gap-open" + "checkpoint-lsn", + "kill-mid-apply", + "fixed" ], "related_bugs": [ "bug-1417", @@ -12659,7 +12660,7 @@ "bug-845", "bug-1418" ], - "occurrences": 2, - "last_seen": "2026-07-07T14:30:00.000Z" + "occurrences": 3, + "last_seen": "2026-07-07T16:00:00.000Z" } ] diff --git a/.wolf/memory.md b/.wolf/memory.md index f6e9959d..04e37ca7 100644 --- a/.wolf/memory.md +++ b/.wolf/memory.md @@ -3641,3 +3641,211 @@ | 00:50 | Task 7.2 round-2 fixes complete: (1) fixed phantom-check `started` derivation in run-ha-soak.sh to check WAL_JOB_START presence directly instead of inferring from terminal state bits (real false-positive, proven via manual jfail-without-jstart repro against a live cluster); (2) root-caused+fixed bug-1416 with new persist_t.recovery_complete gate (persist.h/persist.c) closing persist_apply_pump_kick + ha_apply_single_entry/ha_apply_term_entry_via_library's in-memory apply during boot-time persist_recover(), PLUS persist_mark_recovery_pending() wired into myapp_run() (closes a live-verification-discovered gap: election-retry candidates apply live traffic before persist_recover() is ever first called). Verified: live 3-node --factstream soak PASS (2 rounds, kill+restart both, zero APPLY_DIVERGENT across 5 persist_recover calls); controller_unit_test 23-group sweep zero new failures (2 pre-existing task-6.1/6.2 FAILs unchanged); real-divergence fence tests still PASS | src/include/persist.h, src/controller/persist.c, src/controller/ha.c, src/controller/myapp.c, .claude/skills/xce-test-ha/run-ha-soak.sh | GREEN | ~9000 | | 00:51 | Session end: 48 writes across 12 files (jun29-jul04-2026.md, raft_sim.c, tasks.md, test.c, waldump.c) | 28 reads | ~389364 tok | | 05:07 | Session end: 48 writes across 12 files (jun29-jul04-2026.md, raft_sim.c, tasks.md, test.c, waldump.c) | 30 reads | ~407960 tok | +| 08:10 | Edited .claude/skills/xce-build/SKILL.md | 3→4 lines | ~22 | +| 08:10 | Edited .claude/skills/xce-deploy-ha/SKILL.md | 2→3 lines | ~56 | +| 08:10 | Edited .claude/skills/xce-test-ha/SKILL.md | 2→3 lines | ~70 | +| 08:11 | Session end: 51 writes across 12 files (jun29-jul04-2026.md, raft_sim.c, tasks.md, test.c, waldump.c) | 32 reads | ~408119 tok | +| 08:14 | Edited .claude/skills/xce-deploy-ha/SKILL.md | 2→3 lines | ~8 | +| 08:14 | Edited .claude/skills/xce-test-ha/SKILL.md | 2→3 lines | ~8 | +| 08:15 | Session end: 53 writes across 12 files (jun29-jul04-2026.md, raft_sim.c, tasks.md, test.c, waldump.c) | 32 reads | ~408137 tok | + +## Session: 2026-07-06 20:39 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| + +## Session: 2026-07-06 20:54 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| + +## Session: 2026-07-06 21:02 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| + +## Session: 2026-07-06 00:50 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| +| 01:55 | Created .kiro/specs/admin-config-tool/spec.json | — | ~135 | +| 01:55 | Created .kiro/specs/admin-config-tool/brief.md | — | ~2639 | +| 01:56 | Edited .kiro/steering/roadmap.md | "OP_upgradeConfig" → "/kiro-discovery" | ~425 | +| 01:56 | Edited .kiro/steering/roadmap.md | 6→8 lines | ~571 | +| 01:57 | Edited .kiro/steering/roadmap.md | expanded (+9 lines) | ~295 | +| 01:58 | Session end: 5 writes across 3 files (spec.json, brief.md, roadmap.md) | 32 reads | ~87853 tok | +| 02:03 | Session end: 5 writes across 3 files (spec.json, brief.md, roadmap.md) | 32 reads | ~87853 tok | +| 02:57 | Edited .kiro/specs/admin-config-tool/brief.md | expanded (+13 lines) | ~415 | +| 02:58 | Edited .kiro/specs/admin-config-tool/brief.md | expanded (+43 lines) | ~531 | +| 03:00 | Session end: 7 writes across 3 files (spec.json, brief.md, roadmap.md) | 32 reads | ~89042 tok | +| 03:07 | Session end: 7 writes across 3 files (spec.json, brief.md, roadmap.md) | 32 reads | ~94392 tok | +| 03:08 | Edited .kiro/specs/admin-config-tool/brief.md | 5→6 lines | ~51 | +| 03:09 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~78 | +| 03:09 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~34 | +| 03:09 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~28 | +| 03:09 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~45 | +| 03:09 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~55 | +| 03:10 | Edited .kiro/specs/admin-config-tool/brief.md | 6→4 lines | ~45 | +| 03:10 | Session end: 14 writes across 3 files (spec.json, brief.md, roadmap.md) | 32 reads | ~94751 tok | +| 03:11 | Edited .kiro/specs/admin-config-tool/brief.md | list() → dev() | ~68 | +| 03:12 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~92 | +| 03:12 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~53 | +| 03:12 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~78 | +| 03:12 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~40 | +| 03:12 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~23 | +| 03:12 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~38 | +| 03:12 | Edited .kiro/specs/admin-config-tool/brief.md | inline fix | ~55 | +| 03:12 | Edited .kiro/specs/admin-config-tool/brief.md | "--cert" → "localhost:9991" | ~56 | +| 03:13 | Session end: 23 writes across 3 files (spec.json, brief.md, roadmap.md) | 32 reads | ~90437 tok | +| 03:15 | Edited .kiro/steering/roadmap.md | 2→3 lines | ~560 | +| 03:15 | Edited .kiro/steering/roadmap.md | inline fix | ~451 | +| 03:16 | Session end: 25 writes across 3 files (spec.json, brief.md, roadmap.md) | 32 reads | ~91860 tok | +| 03:18 | Edited .kiro/steering/roadmap.md | inline fix | ~433 | +| 03:18 | Session end: 26 writes across 3 files (spec.json, brief.md, roadmap.md) | 32 reads | ~92348 tok | + +## Session: 2026-07-06 03:33 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| +| 04:00 | Created .kiro/specs/scheduler-framework/brief.md | — | ~2749 | +| 04:00 | Edited .kiro/specs/scheduler-framework/brief.md | modified Deferred() | ~831 | +| 04:01 | Edited .kiro/steering/roadmap.md | "/kiro-spec-init " → "/kiro-discovery" | ~175 | +| 04:01 | Edited .kiro/steering/roadmap.md | 3→4 lines | ~131 | +| 04:03 | Session end: 4 writes across 2 files (brief.md, roadmap.md) | 15 reads | ~20186 tok | + +## Session: 2026-07-07 19:29 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| + +## Session: 2026-07-07 19:53 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| + +## Session: 2026-07-07 19:55 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| +| 20:02 | Edited .kiro/specs/raft-apply-decoupling/tasks.md | inline fix | ~24 | +| 20:03 | Edited .kiro/specs/raft-apply-decoupling/tasks.md | added error handling | ~1233 | +| 20:09 | Session end: 2 writes across 1 files (tasks.md) | 3 reads | ~35904 tok | +| 20:16 | Edited src/controller/testsuite/test_commit_barrier_reply.c | modified 2() | ~1068 | +| 20:18 | Edited src/controller/testsuite/test_commit_barrier_reply.c | added error handling | ~1371 | +| 20:19 | Created ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/run_all_groups.sh | — | ~301 | +| 20:24 | Session end: 5 writes across 3 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh) | 8 reads | ~170866 tok | +| 20:37 | Edited .kiro/specs/raft-apply-decoupling/tasks.md | inline fix | ~29 | +| 20:37 | Edited .kiro/specs/raft-apply-decoupling/tasks.md | modified Verified() | ~514 | +| 20:39 | Session end: 7 writes across 3 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh) | 8 reads | ~171764 tok | +| 20:51 | Created ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/factstream-throughput-bench.sh | — | ~1170 | +| 20:55 | Edited ../../xce/.claude/worktrees/agent-a0dfba18c450e4f5f/src/controller/testsuite/test.c | modified 4() | ~290 | +| 20:56 | Edited ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/factstream-throughput-bench.sh | 6→6 lines | ~82 | +| 20:56 | Edited ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/factstream-throughput-bench.sh | inline fix | ~7 | +| 21:21 | Edited ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/factstream-throughput-bench.sh | modified used() | ~277 | +| 21:21 | Edited ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/factstream-throughput-bench.sh | expanded (+7 lines) | ~189 | +| 21:22 | Edited ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/factstream-throughput-bench.sh | added 1 condition(s) | ~636 | +| 21:31 | Edited ../../xce/.claude/worktrees/agent-a0dfba18c450e4f5f/src/controller/testsuite/test.c | modified 4() | ~290 | +| 21:47 | Edited ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/factstream-throughput-bench.sh | "$XT" → "${XTEST_TIMEOUT:-180}" | ~23 | +| 22:06 | Session end: 16 writes across 5 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 13 reads | ~269734 tok | +| 22:12 | Session end: 16 writes across 5 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 14 reads | ~290165 tok | +| 22:16 | Edited src/include/persist.h | modified XCE_TESTING() | ~430 | +| 22:16 | Edited src/controller/persist.c | modified idle() | ~174 | +| 22:16 | Edited src/controller/persist.c | added 1 condition(s) | ~178 | +| 22:17 | Edited src/controller/persist.c | added 1 condition(s) | ~222 | +| 22:17 | Edited src/controller/persist.c | added 8 condition(s) | ~875 | +| 22:17 | Edited src/controller/persist.c | added 1 condition(s) | ~364 | +| 22:17 | Edited src/controller/persist.c | added 2 condition(s) | ~258 | +| 22:44 | Session end: 23 writes across 7 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 14 reads | ~292845 tok | +| 22:51 | Created ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/factstream-throughput-bench-v2.sh | — | ~1576 | +| 23:12 | Created ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/bench-v3.sh | — | ~843 | +| 23:14 | Created ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/bench-v4.sh | — | ~992 | +| 23:16 | Edited ../../../../../../tmp/claude-1000/-home-rshen-projects-xce-worktrees-raft-tla/5e55cf26-d05d-4a2e-8196-d2c70e0c063c/scratchpad/bench-v4.sh | added 1 condition(s) | ~478 | +| 06:43 | Fixed apply-pump O(n^2) regression (persist.c/.h): segment-lookup cache in apply_pump_read_entry, invalidated on init/fini/recover/truncate | src/controller/persist.c, src/include/persist.h | tests green (5/5,4/4,11/11 + broader sweep); live A/B: prefix 7.4x elapsed for 2x volume -> fixed 1.46x, throughput 1111->3831/s @N=2000 | ~4500 | +| 23:44 | Session end: 27 writes across 10 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 15 reads | ~297012 tok | +| 00:02 | Session end: 27 writes across 10 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 17 reads | ~299090 tok | +| 00:03 | Edited src/controller/persist.c | modified fix() | ~362 | +| 00:03 | Edited src/include/persist.h | added error handling | ~599 | +| 07:05 | Round-2 remediation for task 7.4 O(n^2) apply-pump review rejection: (1) wrapped persist_recover cache-invalidation in apply_pump_lock/unlock to match persist_truncate_wal_above and persist.h doc invariant, (2) added accepted-tradeoff doc comment on trim_wal_segments/cache interaction (deferred loud-fence via APPLY_DIVERGENT, not immediate -ENOENT) | src/controller/persist.c, src/include/persist.h | build OK, test_apply_pump 5/5, test_apply_pump_integration 4/4, test_persist_recovery 7/7, test_persist_truncate 8/8 | ~1800 | +| 00:06 | Session end: 29 writes across 10 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 17 reads | ~300119 tok | +| 00:13 | Edited .kiro/specs/raft-apply-decoupling/tasks.md | inline fix | ~23 | +| 00:13 | Edited .kiro/specs/raft-apply-decoupling/tasks.md | added error handling | ~1465 | +| 00:14 | Edited .kiro/specs/raft-apply-decoupling/tasks.md | inline fix | ~19 | +| 00:16 | Session end: 32 writes across 10 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 19 reads | ~320484 tok | +| 00:24 | Session end: 32 writes across 10 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 21 reads | ~323424 tok | +| 00:26 | Session end: 32 writes across 10 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 21 reads | ~323424 tok | +| 01:40 | Edited .kiro/steering/roadmap.md | inline fix | ~568 | +| 01:41 | Edited .kiro/specs/raft-drive-async/tasks.md | inline fix | ~19 | +| 01:42 | Edited .kiro/specs/raft-drive-async/tasks.md | inline fix | ~16 | +| 01:42 | Edited .kiro/specs/raft-drive-async/tasks.md | inline fix | ~26 | +| 01:42 | Edited .kiro/specs/raft-drive-async/tasks.md | inline fix | ~17 | +| 01:47 | Edited .kiro/specs/raft-apply-decoupling/design.md | inline fix | ~166 | +| 01:47 | Edited .kiro/specs/raft-apply-decoupling/design.md | "src/controller/ha.c" → "s trigger into " | ~182 | +| 01:48 | Edited .kiro/specs/raft-apply-decoupling/design.md | 3→4 lines | ~234 | +| 01:48 | Edited .kiro/specs/raft-apply-decoupling/tasks.md | modified exception() | ~252 | +| 01:49 | Session end: 41 writes across 12 files (tasks.md, test_commit_barrier_reply.c, run_all_groups.sh, factstream-throughput-bench.sh, test.c) | 23 reads | ~345020 tok | + +## Session: 2026-07-07 02:06 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| +| 07:36 | xce-test-ha 10-round chaotic soak launched | run-ha-soak.sh --chaotic | IN_PROGRESS (round 4/10 running) | ~15 min estimated | +| 02:34 | Created ../../../../../claude/.claude/projects/-home-rshen-projects-xce-xce/memory/project_bug1417_vote_index_mapping.md | — | ~815 | +| 02:34 | Edited ../../../../../claude/.claude/projects/-home-rshen-projects-xce-xce/memory/MEMORY.md | 1→2 lines | ~106 | +| 02:35 | Session end: 2 writes across 2 files (project_bug1417_vote_index_mapping.md, MEMORY.md) | 4 reads | ~103293 tok | +| 02:50 | Edited src/controller/testsuite/test_ha_vote_send.c | modified make_three_node_self1() | ~1488 | +| 02:51 | Edited src/controller/ha.c | expanded (+17 lines) | ~501 | +| 03:20 | Session end: 4 writes across 4 files (project_bug1417_vote_index_mapping.md, MEMORY.md, test_ha_vote_send.c, ha.c) | 8 reads | ~123006 tok | +| 03:21 | Session end: 4 writes across 4 files (project_bug1417_vote_index_mapping.md, MEMORY.md, test_ha_vote_send.c, ha.c) | 8 reads | ~123006 tok | +| 03:52 | Session end: 4 writes across 4 files (project_bug1417_vote_index_mapping.md, MEMORY.md, test_ha_vote_send.c, ha.c) | 8 reads | ~123322 tok | +| 04:23 | Session end: 4 writes across 4 files (project_bug1417_vote_index_mapping.md, MEMORY.md, test_ha_vote_send.c, ha.c) | 8 reads | ~123322 tok | +| 06:13 | Created ../../../../../claude/.claude/projects/-home-rshen-projects-xce-xce/memory/project_bug1418_term_desync_apply_divergent.md | — | ~772 | +| 06:13 | Edited ../../../../../claude/.claude/projects/-home-rshen-projects-xce-xce/memory/MEMORY.md | 1→2 lines | ~90 | +| 06:13 | Session end: 6 writes across 5 files (project_bug1417_vote_index_mapping.md, MEMORY.md, test_ha_vote_send.c, ha.c, project_bug1418_term_desync_apply_divergent.md) | 8 reads | ~124246 tok | +| 06:30 | Edited .claude/skills/xce-test-ha/run-ha-soak.sh | modified start_node() | ~286 | +| 07:03 | Edited src/controller/job.c | added 4 condition(s) | ~1436 | +| 07:04 | Edited src/controller/job.c | modified jobsubmit_async_ctx_release() | ~405 | +| 07:05 | Edited src/controller/job.c | added 1 condition(s) | ~515 | +| 07:06 | Edited src/controller/job.c | modified cannot() | ~263 | +| 07:06 | Edited src/controller/job.c | added 1 condition(s) | ~557 | +| 07:07 | Edited src/controller/job.c | modified if() | ~169 | +| 07:12 | Edited src/controller/testsuite/test_commit_barrier_reply.c | modified test_jobsubmit_resubmit_before_resolution_rejected_no_dup_wal_entry() | ~1108 | +| 07:12 | Edited src/controller/testsuite/test_commit_barrier_reply.c | 6→5 lines | ~54 | +| 07:12 | Edited src/controller/testsuite/test_commit_barrier_reply.c | 4→3 lines | ~39 | +| 07:13 | Edited src/controller/testsuite/test_commit_barrier_reply.c | 2→3 lines | ~63 | + +## Session: 2026-07-07 07:19 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| +| 07:22 | Edited src/controller/job.c | modified XCE_TESTING() | ~426 | +| 07:23 | Edited src/controller/include/cluster.h | modified XCE_TESTING() | ~149 | +| 07:23 | Edited src/controller/testsuite/test_commit_barrier_reply.c | modified cbrp_teardown() | ~159 | +| 07:24 | Edited src/controller/testsuite/test_commit_barrier_reply.c | 3→3 lines | ~40 | +| 07:24 | Edited src/controller/testsuite/test_commit_barrier_reply.c | 4→9 lines | ~99 | +| 07:31 | bug-1419 fix committed: in-flight jobid registry in job.c closes resubmit-dedup gap | src/controller/job.c, cluster.h, test_commit_barrier_reply.c, buglog.json | 78-group sweep 782/782 pass, commit fe4352f | ~9000 | +| 07:30 | Session end: 5 writes across 3 files (job.c, cluster.h, test_commit_barrier_reply.c) | 8 reads | ~205492 tok | +| 07:32 | Session end: 5 writes across 3 files (job.c, cluster.h, test_commit_barrier_reply.c) | 9 reads | ~205492 tok | +| 08:10 | Session end: 5 writes across 3 files (job.c, cluster.h, test_commit_barrier_reply.c) | 9 reads | ~205492 tok | +| 08:12 | Session end: 5 writes across 3 files (job.c, cluster.h, test_commit_barrier_reply.c) | 9 reads | ~205492 tok | +| 08:19 | Session end: 5 writes across 3 files (job.c, cluster.h, test_commit_barrier_reply.c) | 9 reads | ~205492 tok | +| 08:28 | Session end: 5 writes across 3 files (job.c, cluster.h, test_commit_barrier_reply.c) | 12 reads | ~285133 tok | + +## Session: 2026-07-07 16:47 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| + +## Session: 2026-07-07 16:48 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| + +## Session: 2026-07-07 16:53 + +| Time | Action | File(s) | Outcome | ~Tokens | +|------|--------|---------|---------|--------| +| 17:00 | Edited src/controller/persist.c | expanded (+20 lines) | ~543 | +| 17:01 | Edited src/controller/testsuite/test_persist_checkpoint.c | modified test_checkpoint_sets_checkpoint_lsn() | ~842 | +| 17:01 | Edited src/controller/testsuite/test_persist_checkpoint.c | 1→2 lines | ~33 | +| 17:02 | Edited src/controller/testsuite/test_persist_checkpoint.c | 10→11 lines | ~140 | +| 17:15 | bug-1419 layer 2 FIXED: persist_checkpoint() stamped checkpoint_lsn from current_lsn (WAL tip) not last_applied_lsn (applied cursor), uncoordinated with async apply pump -> kill-mid-apply permanently skipped committed-not-yet-applied entries on recovery, false APPLY_DIVERGENT fence | persist.c, test_persist_checkpoint.c, buglog.json | RED->GREEN confirmed via stash/pop; 78-group/782-test sweep 0 failures | ~11000 | diff --git a/src/controller/persist.c b/src/controller/persist.c index 19d857f4..a89c2f0d 100644 --- a/src/controller/persist.c +++ b/src/controller/persist.c @@ -2258,10 +2258,27 @@ int persist_checkpoint(persist_t* p) if (rc != 0) goto done; - /* 2. Record checkpoint_lsn = current position after the marker */ - pthread_mutex_lock(&p->lock); - p->checkpoint_lsn = p->current_lsn; - pthread_mutex_unlock(&p->lock); + /* 2. Record checkpoint_lsn = the APPLIED cursor (last_applied_lsn), not + * the physical WAL append tip (current_lsn). write_snapshot() below + * serializes live jobmgr state, which only reflects entries the + * apply pump has actually dispatched -- NOT every entry durably + * appended/committed, since apply is decoupled from commit + * (raft-apply-decoupling) and can lag behind current_lsn under load. + * Stamping current_lsn here mislabels the snapshot: on restart, + * last_applied_lsn is re-seeded FROM checkpoint_lsn and replay + * resumes strictly above it, so any committed-but-not-yet-applied + * entries between the true apply cursor and current_lsn at + * checkpoint time are silently skipped forever, even though jobmgr + * never actually contained them (persist.h last_applied_lsn doc). + * Held under apply_pump_lock together with 3a/3b so the label and + * the jobmgr walk it describes are captured atomically w.r.t. the + * live apply pump -- the pump can only ever move last_applied_lsn + * and jobmgr forward, never backward, so freezing it here rules out + * the label ever claiming more than jobmgr actually holds. */ + pthread_mutex_lock(&p->apply_pump_lock); + + p->checkpoint_lsn = atomic_load_explicit(&p->last_applied_lsn, + memory_order_acquire); /* 3a. Capture the latest committed config-marker reference BEFORE trimming * (ha-term-safety task 4.2 r1): the trim below can unlink the segment @@ -2272,6 +2289,9 @@ int persist_checkpoint(persist_t* p) /* 3b. Serialize in-memory state to a snapshot file * (P0: no live kvmgrs — writes sentinel header + cached config ref) */ rc = write_snapshot(p); + + pthread_mutex_unlock(&p->apply_pump_lock); + if (rc != 0) goto done; diff --git a/src/controller/testsuite/test_persist_checkpoint.c b/src/controller/testsuite/test_persist_checkpoint.c index f138694a..28305f22 100644 --- a/src/controller/testsuite/test_persist_checkpoint.c +++ b/src/controller/testsuite/test_persist_checkpoint.c @@ -108,6 +108,15 @@ static void test_checkpoint_sets_checkpoint_lsn(void) persist_wal_async(p, WAL_JOB_UPDATE, "x", 1); uint64_t lsn_before = p->current_lsn; + + /* No live apply pump runs in this cluster-less unit-test fixture, so + * last_applied_lsn stays 0 unless a test drives it directly — simulate + * apply having fully caught up to what was appended (persist_checkpoint + * now stamps checkpoint_lsn from last_applied_lsn, not current_lsn; + * see the checkpoint_lsn-vs-last_applied_lsn fix). */ + atomic_store_explicit(&p->last_applied_lsn, lsn_before, + memory_order_relaxed); + TEST_ASSERT_EQUAL_INT(0, persist_checkpoint(p)); /* checkpoint_lsn must have advanced to at least lsn_before */ @@ -117,6 +126,50 @@ static void test_checkpoint_sets_checkpoint_lsn(void) printf("test_checkpoint_sets_checkpoint_lsn: PASS\n"); } +/* ------------------------------------------------------------------ */ +/* Test 2b: checkpoint_lsn tracks the APPLIED cursor, not the WAL tip */ +/* ------------------------------------------------------------------ */ + +/* Regression test for the checkpoint_lsn/last_applied_lsn mislabeling bug + * (persist.h last_applied_lsn doc, "DISTINCT from current_lsn"): when the + * apply pump lags behind the physical WAL append tip -- the normal state + * under raft-apply-decoupling once a commit resolves before its entry is + * dispatched into jobmgr -- a checkpoint must label the snapshot with the + * position jobmgr ACTUALLY reflects (last_applied_lsn), never the tip + * (current_lsn). Stamping current_lsn here would seed the next recovery's + * last_applied_lsn/replay-resume point past entries jobmgr never received, + * permanently skipping them (the root cause behind bug-1419's apply-divergent + * fence on kill-mid-apply). */ +static void test_checkpoint_lsn_tracks_last_applied_not_current_lsn(void) +{ + char tmpdir[256]; + persist_t* p = make_ckpt_persist(tmpdir, sizeof(tmpdir)); + TEST_ASSERT_NOT_NULL(p); + + /* Append 5 entries, but only simulate the apply pump having dispatched + * the first 2 of them (jobmgr reflects up through lsn_before + 1). */ + uint64_t lsn_before = p->current_lsn; + for (int i = 0; i < 5; i++) + persist_wal_async(p, WAL_JOB_UPDATE, "z", 1); + + TEST_ASSERT_EQUAL_UINT64(lsn_before + 5, p->current_lsn); + + const uint64_t simulated_apply_cursor = lsn_before + 1; + atomic_store_explicit(&p->last_applied_lsn, simulated_apply_cursor, + memory_order_relaxed); + + TEST_ASSERT_EQUAL_INT(0, persist_checkpoint(p)); + + /* checkpoint_lsn must equal the applied cursor, NOT the WAL tip -- a + * checkpoint_lsn of 5 here would mean recovery resumes replay above + * LSN 5, silently dropping entries 3-5 that jobmgr never applied. */ + TEST_ASSERT_EQUAL_UINT64(simulated_apply_cursor, p->checkpoint_lsn); + TEST_ASSERT_TRUE(p->checkpoint_lsn < p->current_lsn); + + cleanup_ckpt_persist(p); + printf("test_checkpoint_lsn_tracks_last_applied_not_current_lsn: PASS\n"); +} + /* ------------------------------------------------------------------ */ /* Test 3: checkpoint writes a WAL_CHECKPOINT marker (advances lsn) */ /* ------------------------------------------------------------------ */ @@ -192,6 +245,7 @@ void test_persist_checkpoint(void) { RUN_TEST(test_checkpoint_creates_snapshot_file); RUN_TEST(test_checkpoint_sets_checkpoint_lsn); + RUN_TEST(test_checkpoint_lsn_tracks_last_applied_not_current_lsn); RUN_TEST(test_checkpoint_writes_marker_to_wal); RUN_TEST(test_checkpoint_busy_guard); RUN_TEST(test_checkpoint_rotation_keeps_snap_keep_n);