forked from lei.chen/myxce
fix(raft-apply-decoupling): bug-1419 layer 2 — checkpoint_lsn mislabeled from WAL tip instead of applied cursor
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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01VgT3n4vTv4ZjCuCTmzed1F
This commit is contained in:
parent
fe4352fb36
commit
0eb105431b
4 changed files with 292 additions and 9 deletions
|
|
@ -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"
|
||||
}
|
||||
]
|
||||
|
|
|
|||
208
.wolf/memory.md
208
.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 |
|
||||
|
|
|
|||
|
|
@ -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;
|
||||
|
||||
|
|
|
|||
|
|
@ -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);
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue