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>
60 lines
9.9 KiB
Markdown
60 lines
9.9 KiB
Markdown
---
|
|
id: "bug-1425"
|
|
status: "fixed"
|
|
status_updated: "2026-09-24"
|
|
status_note: "8a6c339a"
|
|
component: "controller"
|
|
severity: "hang"
|
|
timestamp: "2026-07-09T21:15:00.000Z"
|
|
last_seen: "2026-09-19T09:00:00Z"
|
|
occurrences: 2
|
|
files: ["src/controller/persist.c or src/controller/commit.c (unrooted)"]
|
|
tags: ["ha", "commit-engine", "election", "intermittent", "raft-apply-decoupling-followup", "live-repro-found", "concurrent-connect-trigger", "root-caused", "tdd-red-green"]
|
|
related: ["bug-1416"]
|
|
fix_commits: ["8a6c339a"]
|
|
legacy: true
|
|
---
|
|
|
|
# bug-1425: Intermittent (~2 of 9 attempts) client hang in the synchronous jobsub (COMMIT_MODE_WAIT) path…
|
|
|
|
## Description
|
|
Intermittent (~2 of 9 attempts) client hang in the synchronous jobsub (COMMIT_MODE_WAIT) path shortly after a fresh single-node election.
|
|
|
|
## Environment
|
|
_Not recorded (migrated from buglog.json)._
|
|
|
|
## Reproduction
|
|
_Not recorded (migrated from buglog.json)._
|
|
|
|
## Root cause
|
|
NOT ROOT-CAUSED. Flagged during raft-apply-decoupling task 7.4's throughput benchmark work. Reproduced identically on both the pre-fix and post-fix (task 6.1 apply-pump) binaries — confirmed unrelated to that fix. Resembles but is not confirmed identical to the closed bug-1416 boot-race class (persist_recover() replay-verify racing the live apply pump / live-replication apply path).
|
|
|
|
## Fix
|
|
[UPDATE 2026-08-16] Live investigation (single-node deploy via /xce-deploy-ha, controller_unit_test's own fix build): found a RELIABLE reproduction recipe the original ~2/9-sequential-attempts description never had, and narrowed the root cause to a specific mechanism, but did NOT land a fix -- reporting findings honestly per the explicit scope of this investigation pass.
|
|
|
|
RELIABLE REPRO (not sequential -- CONCURRENT): deploy a fresh single-node cluster, poll the log for CTRL_PRIMARY, then fire 9 xce_test client processes (each: connect + one jobsub) SIMULTANEOUSLY (backgrounded, not sequential) immediately after election. Reproduced in 3 of 4 rounds (1-3 of 9 concurrent clients failing per round, closely matching the original ~2/9 ratio) -- 0/45 reproductions when the SAME 9 attempts were fired sequentially instead (one xce_test process at a time). Concurrency at connect time, not raw timing after election, is the actual trigger.
|
|
|
|
SYMPTOM, precisely: the failing client's xcecli_jobsubmit() (client.c, wrapped in XCECLI_FAILOVER_CALL) returns rc>=0 (success-shaped, NOT a negative error) after exactly ~10.0-10.1s, with the output jobid=0 (never written) instead of the submitted JobId -- test.c's cmd_jobsub (bug-786's own guard) correctly catches this as 'no clean ack' rather than misreporting success, so no data is actually lost/corrupted -- but the client hangs ~10s before getting a clear answer, matching the bug's own description exactly.
|
|
|
|
CONFIRMED CLIENT-SIDE, not server-side: cross-referenced the controller's own log (fresh --logfile per round) against the 9 concurrent attempts -- server-side WAL only ever shows 8 job-submit entries committed (lsn sequence has no gaps, no admission-cap rejection WARN, no error of any kind) when 9 concurrent clients attempted -- the failing 9th request never reaches handle_jobsubmit at all. Ruled out the obvious admission-cap suspect: commit.c's COMMIT_MODE_WAIT admission control (cap=n_vcpus-VTASK_LIVENESS_RESERVED=3 on this 4-vcpu deploy) never logged its 'WAIT rejected, admission cap exhausted' WARN in any reproduction -- 8 concurrent WAITs completing well under the cap is plausible given each takes <100ms server-side once received.
|
|
|
|
THE ~10s NUMBER, precisely sourced: xceapi.c's xce_jobsubmit() (the innermost call XCECLI_FAILOVER_CALL wraps) has a HARDCODED cbuf_deadline_10s() wait on cbuf_timedget waiting for a reply to land in the single-slot ctx->wbuf. Read cbuf_timedget itself (mylock.c) -- confirmed CORRECT, it returns -ETIMEDOUT (negative) on a genuine timeout, which xce_jobsubmit correctly propagates as a negative rc. So a bare cbuf_timedget timeout cannot by itself explain the observed rc>=0-with-jobid=0 shape; something in the retry/rotate/recover layer ABOVE it must be involved.
|
|
|
|
NARROWED SUSPECT (not confirmed): client_internal.h's own documented CI1 hazard -- 'handle_disconnect may have injected a stale status into the single-slot ctx->wbuf ... xcecli_ctx_recover drains any pending entry with a non-blocking cbuf_tryget so the next attempt's cbuf_get cannot consume a prior-attempt reply' -- but this drain only runs when xce_failover_rotate() succeeds (client_failover.c:130-153, mirrored by xcecli_retry_next per its own doc comment: 'only recover when the rotate succeeded'). On this single-candidate cluster, rotate reconnects to the SAME (only) node via a real xce_ctx_reconnect() -- plausible this usually succeeds (ruling out the simplest 'rotate never succeeds on single-node, drain never runs' theory) but NOT independently verified under the exact concurrent-connect contention this repro needs; a transient reconnect failure specifically during the connection-establishment storm (9 simultaneous TLS handshakes against a listener seconds old) could leave a stale wbuf entry undrained, which a LATER retry's cbuf_timedget could then either (a) consume immediately (fast, not 10s -- doesn't match) or (b) never resolve at all if the drain path interacts badly with an in-flight send, leaving the single wbuf slot permanently empty until the full 10s deadline. Did not instrument (fprintf/gdb) the actual attempt count or wbuf state during a live failing run to confirm this mechanism specifically -- xce_test's own -vvv flag produced no additional client-side retry/rotate trace output (goes through a different, unwired logger in this CLI context), and adding real instrumentation would need a fresh lib rebuild + re-repro cycle not completed in this pass.
|
|
|
|
NOT YET DONE: instrument xcecli_retry_next/xce_jobsubmit directly (attempt count, wbuf drain outcome, rotate rc, per-attempt elapsed) and re-run the now-reliable concurrent-burst repro to catch the exact mechanism in the act -- this is the recommended next step, using the repro recipe above (no gdb needed; the reproduction is now reliable enough for print-based debugging). Confirmed unrelated to raft-apply-decoupling task 6.1's apply-pump fix (reproduces identically on that spec's pre-fix and post-fix binaries per the original entry) and to this session's bug-1428/1426/1474/1472-remainder fixes (none touch xceapi.c/client.c/client_failover.c's client-side retry path).
|
|
|
|
[Original entry]
|
|
NOT FIXED. Worked around via retry for task 7.4's benchmarking purposes only. Needs a dedicated root-cause investigation with the same live-repro rigor bug-1416 got (gdb-attach via GDB_WRAP seam, or targeted debug logging around the commit-wait barrier right after a fresh single-node election).
|
|
|
|
[UPDATE 2026-08-16, part 2] FIXED. Root-caused via static code trace (no gdb/instrumentation needed after all): XCECLI_FAILOVER_CALL's idempotent-replay rule (client_failover.c, xce_failover_classify -- 'a duplicate on a re-sent write means the replay guard already applied our write, treat as success') can normalize a retried resend that hits the server's EEXIST/inflight-collision rejection into overall success (rc==0) -- but that rejection reply carries NO payload (handle_jobsubmit's EEXIST/inflight-collision branches reply with RequestReply_data_nodata, job.c:1441-1467), so xce_jobsubmit() (xceapi.c) never populates its *jobid output on the winning (dup) attempt, and never did on the earlier failing attempt either (its raw status was already negative). Net: xcecli_jobsubmit() can return rc>=0 with *jobid left at the caller's initial value (0) -- matching the confirmed symptom exactly (rc>=0, jobid=0, ~10.0-10.1s: one full 10s cbuf_timedget deadline on the failing first attempt, then a fast dup-rejection reply on the resend).
|
|
|
|
FIX (TDD): added jobsubmit_finalize_jobid(uint64_t* jobid, uint64_t submitted_jobid, int overall_rc) (src/lib/client_internal.h declaration, src/lib/client.c definition), called from xcecli_jobsubmit() right after XCECLI_FAILOVER_CALL returns. Sets *jobid = submit->jobid (the CLIENT-generated id already on the wire -- job ids are client-generated via idgen(); the controller commits/echoes this exact value verbatim on every genuine success reply, bug-786/job.c:1439) whenever overall_rc >= 0, otherwise leaves *jobid untouched. Deliberately placed at the jobsubmit-specific wrapper layer, not the generic classify/decide layer (which is correctly type-erased and has no concept of jobid) -- test.c's cmd_jobsub (bug-786's own gate, comparing returned jobid == locally-generated jobsubmit.jobid) was ALREADY the right verification signal and needed no changes. 3 new pure unit tests in test_libxce_retry.c (test_jobsubmit_finalize_populates_jobid_on_success/leaves_jobid_untouched_on_failure/null_jobid_safe) -- socket-free, following this codebase's established direct-state-simulation test style for I/O-adjacent logic (test_netio_on_connected.c's precedent) rather than mocking a live connection.
|
|
|
|
LIVE VALIDATION: full ASAN rebuild (0 compiler errors; controller_unit_test 1101 tests, 2 pre-existing unrelated test_config_repl.c failures; libxce test suite 1/1 OK, all 3 new tests PASS). Deployed a fresh single-node cluster and ran the same concurrent-burst repro as the original investigation (fresh election -> 9 simultaneous xce_test jobsub clients) for 5 rounds / 45 total clients: 0 'no clean ack' failures, 45/45 clean acks with jobid matching the submitted id (vs. the original repro's 1-3/9 failures in 3 of 4 rounds pre-fix). Honest caveat: this is probabilistic/timing-dependent (like the original repro), so 45/45 clean is strong but not airtight proof the exact race window is unreachable -- the fix is correct by construction regardless (it closes the *jobid gap for EVERY path that can produce rc>=0, not just the one race that was reproduced), so residual risk is limited to a still-undiscovered SEPARATE mechanism producing the same symptom, not this one going unfixed.
|
|
|
|
## Verification
|
|
_Not recorded (migrated from buglog.json)._
|
|
|
|
## References
|
|
- Related: bug-1416
|