Rongsong Shen
d26ff8870d
The buglog was one 27K-line JSON file whose fields covered only symptom,
root cause and fix, as free text: 2% of entries named the code version a
bug was found on, 12% the build profile, 36% a way to reproduce, and 58% of
the file was OpenWolf hook auto-detections ("Missing guard clause",
"Function not marked async" on .md files).
- .claude/skills/buglog/bug-record.md: the record standard. Eight
sections (Summary as the title, Description, Environment, Reproduction;
Root cause, Fix, Verification, References once fixed), each with the
content it must contain -- e.g. Environment needs the OS, the libc the
failing binary loads (from its ELF interpreter: glibc 2.42 in the nix
shell vs 2.40 on the host), toolchain, build profile and commit.
- .wolf/bugs/<id>.md: 500 records migrated from buglog.json; every field
verified to round-trip. They carry legacy: true and an explicit "not
recorded" where the old log had no such field; component derived from
file paths, severity from keywords (else unknown), fix_commits from
hashes in status_note/fix that git resolves (91 of 463 fixed).
- .wolf/buglog-archive.json: the 710 hook auto-detections, verbatim.
- .wolf/buglog.json is now an index generated from the records, keeping
the fields OpenWolf's hooks and `openwolf bug search` read.
- scripts/buglog.py rewritten: new (template + Environment collected from
the machine and --binary), check, status (refuses a status the record
doesn't support; fixed needs Root cause, Fix, Verification and
--commit hashes git resolves), note, recur, set, show, list, triage,
env, index. 29 unittest cases in scripts/tests/test_buglog.py.
- scripts/git-hooks/pre-commit runs `check --staged`: incomplete staged
records, a legacy record hand-changed to fixed without the fix-time
sections, a new record claiming legacy: true, or a stale index refuse
the commit.
- scripts/gitea-sync.py reads the records: issue body = the record's
sections plus linked fix commits (origin remote, GITEA_COMMIT_REPO to
override), and a body hash so an issue's text is refreshed when the
record changes.
- bug-1866 rewritten to the full standard as the worked example.
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
8.9 KiB
| id | status | status_updated | status_note | component | severity | timestamp | last_seen | occurrences | files | tags | related | fix_commits | legacy | |||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| bug-1419 | fixed | 2026-09-24 | controller | hang | 2026-07-07T14:00:00.000Z | 2026-09-19T09:00:00Z | 3 |
|
|
|
|
true |
bug-1419: [xce-test-ha --chaotic] genuine, reproducible election-liveness stall (not the bug-1418 harness…
Description
[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.
Environment
Not recorded (migrated from buglog.json).
Reproduction
Not recorded (migrated from buglog.json).
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).
ACTUAL 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.
The 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.
Layer (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.
ADDENDUM (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.
Verification
Not recorded (migrated from buglog.json).
References
- Related: bug-1417, bug-1060, bug-845, bug-1418, bug-1420