diff --git a/.wolf/buglog.json b/.wolf/buglog.json index ab0553ec..3f0a409a 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": "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.", + "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.\n\nADDENDUM (2026-07-08, post-fix re-soak): a fresh chaotic soak on a rebuilt binary (both layers included) cleared rounds 1-4 (previously stalled at round 4) but still hit a fresh APPLY_DIVERGENT fence at round 5. Deep dive (waldump + log correlation + code trace) proved BOTH layer 1 and layer 2 are working correctly and are NOT the cause: added test_jobsubmit_resubmit_after_full_resolution_rejected_no_second_job (test_commit_barrier_reply.c) proving the post-resolution dedup window is also airtight (-EEXIST, no second WAL entry) -- both known dedup windows are provably race-free. The round-5 duplicate jobid was traced instead to a TEST-HARNESS-ONLY defect: xce_test (test.c:1868) hardcoded idgen(&idctx, 0, 0, ...) (clusterId=apiserverId=0) and run-ha-soak.sh's submit_jobs() spawns a fresh xce_test process per retry attempt, resetting idgen's static idctx.sequence to 0 each time -- two unrelated job submissions from two fresh processes landing in the same wall-clock second collide on an identical jobid (ts+tag+seq all equal). Confirmed NOT a production risk: apiserver's GenerateJobID (clib.go) holds one process-lifetime idgen_ctx_t via sync.Once and each deployed apiserver instance has its own distinct apiserverId, so config.h's jobid bit-layout (cluster/apiserver bits) already partitions production's namespace. Fixed by folding getpid() into the harness's apiserverId (test.c:1868) so cross-process collisions become structurally impossible there too; filed as bug-1420. bug-1419 itself (both production layers) stands as correctly fixed -- this addendum exists so a future session doesn't misread the round-5 re-soak stall as evidence layer 1/2 are insufficient.", "tags": [ "ha", "election", @@ -12658,9 +12658,53 @@ "bug-1417", "bug-1060", "bug-845", - "bug-1418" + "bug-1418", + "bug-1420" ], "occurrences": 3, - "last_seen": "2026-07-07T16:00:00.000Z" + "last_seen": "2026-07-08T04:00:00.000Z" + }, + { + "id": "bug-1420", + "timestamp": "2026-07-08T04:00:00.000Z", + "error_message": "xce_test CLI harness generates colliding jobids across separate process invocations within the same wall-clock second, surfacing as a spurious APPLY_DIVERGENT fence in chaotic HA soak (misattributed at first to bug-1419's controller-side dedup logic).", + "file": "src/controller/testsuite/test.c", + "root_cause": "idgen() (src/lib/idgen.c) derives jobid from a per-context {timestamp (1s resolution), sequence (reset to 0 whenever the second rolls over or the context is freshly initialized)} pair, plus caller-supplied clusterId/apiserverId bits (src/include/config.h: 6+4 bits respectively) that are meant to partition the jobid namespace across independent generators. xce_test's cmd_jsub called idgen(&idctx, 0, 0, arsize, ...) -- both partition fields hardcoded to 0 -- so every xce_test process shares the SAME (degenerate, unpartitioned) jobid space. run-ha-soak.sh's submit_jobs() (run-ha-soak.sh:446) spawns a fresh xce_test process per submit/retry attempt (`printf script | xtest`, xtest() = `timeout 60 \"$XT\"`), and idgen_ctx_init() resets sequence=0 on every fresh process start. Two unrelated job submissions from two different xce_test process launches landing in the same wall-clock second therefore compute an IDENTICAL jobid (ts, tag, seq all equal) -- a genuine, reproducible collision between logically distinct jobs, not a retry of the same one. This is NOT a production defect: apiserver's GenerateJobID (src/frontend/apiserver/backend/clib.go) initializes its idgen_ctx_t exactly once per process via sync.Once (sequence only resets on an actual apiserver restart, far rarer than per-request), and each deployed apiserver instance is assigned its own distinct apiserverId, so config.h's bit layout already partitions the production jobid namespace across instances even in the rare restart-collision case.", + "fix": "Folded getpid() into the harness's apiserverId at the idgen() call site (test.c:1868): idgen(&idctx, 0, (size_t)((uint64_t)getpid() & MAX_APISERVER_ID), arsize, &(jobsubmit.jobid)) -- gives every xce_test process invocation its own slice of the same namespace partitioning production already relies on, making a same-second cross-process collision structurally impossible. Mechanical, test-tool-only change; no production code touched. Verified via clean rebuild of both xce_test and controller_unit_test targets (no coupling, no regressions).", + "tags": [ + "test-harness", + "jobid", + "idgen", + "chaotic-soak", + "false-positive", + "fixed" + ], + "related_bugs": [ + "bug-1419" + ], + "occurrences": 1, + "last_seen": "2026-07-08T04:00:00.000Z" + }, + { + "id": "bug-1418", + "timestamp": "2026-07-08T03:20:00.000Z", + "error_message": "[xce-test-ha --chaotic 10-round fresh binary] Rounds 1-4 clean, round 5+ permanent liveness deadlock. Both ctrl-2 and ctrl-3 win raft elections (became_leader) but promotion REFUSED every ~12s: apply_divergent=1 durable_floor=26 cluster_hwm=26 peer_reachable=1. Terms escalate 31→47+, no primary emerges for rounds 5-10.", + "file": "src/controller/ha.c (raft_cb_become_leader promotion gate)", + "root_cause": "RESIDUAL after bug-1418 layer-1 (fe4352f WAL dup-submit) and layer-2 (0eb1054 checkpoint-lsn) fixes — both layers confirmed working (sequential 10-round PASS, zero job loss, all 3 nodes led). The promotion gate (raft-apply-decoupling Req 8.4) correctly detects APPLY_DIVERGENT, but has NO recovery path when durable_floor >= cluster_hwm. In this case: durable_floor(26) == cluster_hwm(26) — node HAS the full committed WAL log, has NOT yet applied it (apply pump lagged behind WAL tip during kill). The gate requires applied_lsn >= cluster_hwm to promote, but no primary exists to stream entries for apply catch-up → circular deadlock. The node COULD self-apply (its WAL contains all committed entries) but the gate won't let it become primary to do so. Sequential mode avoids this (waits for full convergence → apply catches up before next kill); chaotic mode triggers it reliably (restarts a node then immediately kills the primary, so the restarted node's applied_lsn lags). Unlike prior bug-1418 occurrences, this is NOT a mislabeled watermark — it's a genuine applied-vs-committed gap that the gate correctly identifies but has no mechanism to resolve.", + "fix": "NOT FIXED. Proposed: relax promotion gate to allow CTRL_PRIMARY when durable_floor >= cluster_hwm (node has full committed log) even if apply_divergent=1. The new primary self-applies committed entries (apply_committed_entry is idempotent per Req 8.1) before serving read traffic. The gate should only permanently fence when durable_floor < cluster_hwm (node physically missing committed entries — would need snapshot backfill).", + "tags": [ + "ha", + "raft", + "apply-divergence", + "promotion-gate", + "chaotic-failover", + "liveness", + "liveness-deadlock", + "residual", + "self-apply-recovery" + ], + "related_bugs": ["bug-1418", "bug-1419", "bug-1417"], + "occurrences": 4, + "last_seen": "2026-07-08T03:20:00.000Z" } ] diff --git a/src/controller/testsuite/test.c b/src/controller/testsuite/test.c index 43201a0f..e86330cc 100644 --- a/src/controller/testsuite/test.c +++ b/src/controller/testsuite/test.c @@ -1865,7 +1865,19 @@ int cmd_jobsub(int argc, char* argv[]) submit.mintasks = min; submit.maxtasks = max; - idgen(&idctx, 0, 0, arsize, &(jobsubmit.jobid)); + /* apiserverId=0 here let two unrelated jobs collide on the same jobid + * whenever the harness spawns a fresh xce_test process within the same + * wall-clock second (idgen_ctx_init resets sequence to 0 each time, + * and ts/tag/seq alone were then identical for both processes' first + * submission). Production apiserver instances never hit this: each + * holds one process-lifetime idgen_ctx_t (clib.go's sync.Once) and is + * assigned its own distinct apiserverId, so the jobid namespace is + * already partitioned by config.h's bit layout. Folding this process's + * pid into apiserverId gives each xce_test invocation its own slice of + * that same partitioning, making a same-second cross-process collision + * structurally impossible here too. */ + idgen(&idctx, 0, (size_t)((uint64_t)getpid() & MAX_APISERVER_ID), arsize, + &(jobsubmit.jobid)); if (NULLSTR(submit.start_info->execuser)) { submit.start_info->execuser = strdup(submit.user); diff --git a/src/controller/testsuite/test_commit_barrier_reply.c b/src/controller/testsuite/test_commit_barrier_reply.c index 52f7292a..f78b6600 100644 --- a/src/controller/testsuite/test_commit_barrier_reply.c +++ b/src/controller/testsuite/test_commit_barrier_reply.c @@ -1305,6 +1305,82 @@ static void test_jobsubmit_resubmit_before_resolution_rejected_no_dup_wal_entry( printf("test_jobsubmit_resubmit_before_resolution_rejected_no_dup_wal_entry: PASS\n"); } +/* bug-1419 residual: does the SAME dedup guard still hold AFTER the first + * attempt has fully resolved (committed, applied, replied, in-flight claim + * released via jobsubmit_async_ctx_release) -- not just DURING the + * still-unresolved window the test above proves. A live chaotic-soak run + * (2026-07-08) showed a genuine WAL-level jobid duplicate (two committed + * WAL_JOB_SUBMIT entries, same term, same primary) that neither known guard + * should have let through if the retry arrived strictly before OR strictly + * after resolution -- this test pins down whether the "after" window is as + * airtight as jobid_range_exists()'s own doc comment claims, by driving the + * first attempt all the way to a fully-applied, fully-replied, + * fully-released state before firing the retry. */ +static void test_jobsubmit_resubmit_after_full_resolution_rejected_no_second_job(void) +{ + const uint64_t jobid = 9150; + uint64_t lsn_before, lsn_before_second, watermark, watermark_second; + cbrp_reply_obs_t obs = { 0 }; + int rc_second; + + cbrp_setup(2000); + cbrp_arrange_jobsubmit(jobid, 1); + + pthread_mutex_lock(&g_hc.persist.lock); + lsn_before = g_hc.persist.current_lsn; + pthread_mutex_unlock(&g_hc.persist.lock); + + /* First attempt: append, commit (ACK delivered), apply, and reply -- + * drive it all the way to the fully-resolved, fully-released state. */ + g_op_arg.fn = handle_jobsubmit; + g_op_arg.req = &g_jobsub_req; + g_op_arg.rc = -9999; + TEST_ASSERT_EQUAL_INT(0, pthread_create(&g_op_tid, NULL, + cbrp_op_thread_fn, &g_op_arg)); + TEST_ASSERT_EQUAL_INT(0, pthread_join(g_op_tid, NULL)); + + watermark = cbrp_poll_append(&g_hc.persist, lsn_before, 1000); + TEST_ASSERT_TRUE_MESSAGE(watermark > 0, + "the first attempt must append its WAL entry"); + + repl_on_ack(&g_hc.persist.repl, &g_hep_a, watermark); + cbrp_poll_reply(&g_req_ep, 2000, &obs); + + TEST_ASSERT_TRUE_MESSAGE(obs.n_replies > 0, + "the first attempt must reach a replied, fully-applied state " + "before the retry below fires"); + TEST_ASSERT_TRUE_MESSAGE(cbrp_job_exists(jobid), + "the first attempt's job must be visible in c->jobmgr before the " + "retry below fires -- otherwise this test does not actually " + "exercise the AFTER-resolution window"); + + /* Second attempt: the retry arrives strictly AFTER the first has fully + * committed, applied, replied, and released its in-flight claim -- the + * window jobid_range_exists()'s own doc comment claims is "airtight + * against a genuinely completed prior submission". */ + cbrp_arrange_jobsubmit(jobid, 1); + + pthread_mutex_lock(&g_hc.persist.lock); + lsn_before_second = g_hc.persist.current_lsn; + pthread_mutex_unlock(&g_hc.persist.lock); + + rc_second = handle_jobsubmit(&g_hc, &g_req_ep, &g_jobsub_req); + + watermark_second = cbrp_poll_append(&g_hc.persist, lsn_before_second, 300); + + cbrp_teardown(); + + TEST_ASSERT_EQUAL_INT_MESSAGE(-EEXIST, rc_second, + "a resubmit for a jobid already fully committed+applied must be " + "rejected -EEXIST via jobid_range_exists()"); + TEST_ASSERT_EQUAL_INT_MESSAGE(0, (int)watermark_second, + "a rejected post-resolution resubmit must NOT append a second " + "WAL_JOB_SUBMIT entry for the same jobid"); + + printf("test_jobsubmit_resubmit_after_full_resolution_rejected_no_second_job:" + " PASS\n"); +} + /* The explicit-FAILED (non-timeout) sibling of the repeated-timeout test * above: repeats the truncation-forced FAILED path * CBRP_JOBSUBMIT_REPEAT_N times in the same fixture, proving the @@ -3270,6 +3346,7 @@ void test_commit_barrier_reply(void) RUN_TEST(test_jobsubmit_truncation_forces_failed_no_phantom_job); RUN_TEST(test_jobsubmit_repeated_timeout_failures_no_phantom_jobs); RUN_TEST(test_jobsubmit_resubmit_before_resolution_rejected_no_dup_wal_entry); + RUN_TEST(test_jobsubmit_resubmit_after_full_resolution_rejected_no_second_job); RUN_TEST(test_jobsubmit_repeated_truncation_forced_failures_no_phantom_jobs); RUN_TEST(test_jobsubmit_array_mixed_outcome_no_phantom_job_for_failed_elements); /* handle_jobsubmit success path via the ordered apply pump