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>
9.7 KiB
| id | status | status_updated | status_note | component | severity | timestamp | last_seen | occurrences | files | tags | related | legacy | |||||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| bug-1687 | fixed | 2026-09-24 | lib | unknown | 2026-08-25T17:30:00Z | 2026-09-19T09:00:00Z | 1 |
|
|
|
true |
bug-1687: xce-audit-invariants finding: WAL_JOB_START silently drops job fields on a controller restart…
Description
xce-audit-invariants finding: WAL_JOB_START silently drops job fields on a controller restart replay -- the same bug class as bug-1678 (WAL_JOB_DISPATCH/job.allocs), but for the worker-confirmed-start fact. apply_job_start_transition() (job.c) sets job->job.pidinfo (real pids/pgids/exdata a worker reported) and job->job.start_time, but the WAL_JOB_START fact written by record_job_start_fact() only carried wal_jobstate_t{jobid, state} -- pidinfo was never in the log at all, and start_time was re-fabricated with time(NULL) at every apply (both boot replay and standby catch-up) instead of carrying the true worker-reported value. Confirmed live-relevant: user reported StartTime always showing 0 in xcecli joblist for both RUN and DONE jobs on a live deployment -- deferred as a distinct follow-up investigation (that deployment's controller predates this fix; whether StartTime=0 specifically, rather than the pre-fix fabricated-nonzero time(NULL), indicates a SEPARATE live-apply-pump gap has not yet been root-caused).
Environment
Not recorded (migrated from buglog.json).
Reproduction
Not recorded (migrated from buglog.json).
Root cause
record_job_start_fact() (job.c, on_job_start()'s only caller) called persist_submit_job_fact(&c->persist, WAL_JOB_START, job->job.jobid, JOB_STAT_RUN) -- a thin wrapper whose payload type wal_jobstate_t is exactly {jobid, state, _pad}, discarding the info (job_pidinfo_t*) parameter entirely even though it was available at the call site (the worker's real START report). Both apply seams -- apply_committed_entry()'s shared WAL_JOB_START/.../DISPATCH fall-through group (persist.c, comment confirms 'these types' payloads are deterministic... start_time... stamped directly below... apply_job_update_transition() only ever touches state') for primary boot replay AND live commit-advance apply, and apply_wal_entry()'s identical shared group -> restore_job_state() (job.c, state-only) for standby catch-up -- never restored pidinfo, and apply_committed_entry() additionally fabricated start_time = time(NULL) at apply time rather than carrying the receipt-time value, so a restarted/promoted node's start_time drifts from the true worker-reported time even though it is non-NULL.
Fix
FIXED (2026-08-25). Mirrors bug-1678's WAL_JOB_DISPATCH fix pattern exactly, using the already-existing controller.capnp JobPIDInfo struct (job_pidinfo_t's mapped type -- the existing Job.pidinfo field) with its already-generated encode_JobPIDInfo/decode_JobPIDInfo/free_JobPIDInfo_ptr functions; no schema change needed. src/controller/persist.c gains capnp_encode_pidinfo()/decode_pidinfo() (mirroring capnp_encode_joballoc()/decode_joballoc()) and persist_submit_job_start_fact(persist_t*, jobid, state, start_time, info) -- WAL_JOB_START's payload is now wal_jobstate_t header + a fixed uint64_t start_time (the receipt-time clock, captured ONCE by record_job_start_fact() rather than re-derived independently at each apply seam) + trailing Cap'n Proto-encoded JobPIDInfo bytes, declared in src/include/persist.h. src/controller/job.c's record_job_start_fact() now calls persist_submit_job_start_fact(..., time(NULL), info) instead of persist_submit_job_fact(...). Both apply seams updated: apply_wal_entry() (standby catch-up) splits WAL_JOB_START out of its shared group into its own case (mirroring how bug-1678 split WAL_JOB_DISPATCH out), decoding trailing start_time/pidinfo and calling new restore_job_start_state() (job.c, restore_job_dispatch_state()'s sibling, takes ownership of an optional decoded job_pidinfo_t and a wire-carried start_time -- 0 means 'not carried, leave untouched', matching this seam's pre-fix behavior of never touching start_time for WAL_JOB_START at all). apply_committed_entry() (primary boot replay / live apply pump) stays in its existing shared fall-through group (mirroring how WAL_JOB_DISPATCH joined that same group in bug-1678) but extends its wal_type==WAL_JOB_START branch: a payload with trailing bytes (len >= sizeof(wal_jobstate_t)+sizeof(uint64_t)) decodes and adopts the wire start_time and pidinfo directly; a payload of exactly sizeof(wal_jobstate_t) (any WAL_JOB_START entry written before this fix) falls through unchanged to the old fabricated-time(NULL)/pidinfo-untouched behavior -- full backward compatibility, verified by every pre-existing WAL_JOB_START test in test_apply_committed_entry.c/test_apply_reapply_idempotency.c/test_ha_role_lifecycle.c/test_apply_pump.c (all still using the old bare-wal_jobstate_t shape) passing unchanged.
Incidental fix required to reach GREEN: test_commit_barrier_reply.c's cbrp_count_jobstate_entries_ex() (a test-only helper that manually scans the on-disk WAL segment) matched WAL_JOB_START/DISPATCH/etc entries via hdr.payload_len == sizeof(wal_jobstate_t) -- an exact-size match that silently undercounted (returned 0 instead of 1) once WAL_JOB_START legitimately grew past that fixed size, in turn making a downstream test in that file poll/spin forever on a count that could never be reached (observed as a genuine deadlock -- all 3 threads futex-blocked, 0 CPU time accruing over 12+ minutes wall clock, reproduced deterministically via -t test_commit_barrier_reply and bisected by temporarily inserting/removing an early return; in the test group's own RUN_TEST driver to narrow it to one of 8 candidate tests, then to a clean isolated PASS/FAIL once the helper was fixed). Changed the match to >= (jobid/state always live at the same fixed leading offset regardless of trailing bytes) -- the general, correct fix, not a workaround; resolves the hang completely (verified: full test_commit_barrier_reply group and the full controller suite both complete in ~38s with zero hangs, both before and after this specific fix was isolated via bisection). Also applied test_commit_barrier_reply.c's cbrp_teardown() the same persist_stop()-before-commit_engine_fini() ordering bug-1452 already established as the fix for this exact TOCTOU-race class (that fix's own note explicitly flagged this file as a same-pattern, not-yet-observed-to-crash follow-up) -- confirmed via bisection that this ordering was NOT the actual cause of this particular hang, but it is a genuine latent race per bug-1452's analysis and the fix is harmless/idempotent, so it was kept as defense-in-depth rather than reverted.
Primary regression tests: new src/controller/testsuite/test_wal_job_start_fact.c (6 tests, wired into src/controller/meson.build and testsuite/controller_test.c), mirroring test_wal_job_dispatch_fact.c's structure: (1) apply_committed_entry sets pidinfo+start_time from a new-format payload; (2) apply_committed_entry backward-compat with an old-format (bare wal_jobstate_t) payload -- pidinfo stays NULL, start_time still fabricated via time(NULL), unchanged from pre-fix; (3) apply_wal_entry sets pidinfo+start_time, fires no hook; (4) apply_wal_entry backward-compat -- pidinfo stays NULL, start_time left untouched; (5) direct-payload restart-replay (WAL_JOB_SUBMIT + new-format WAL_JOB_START via persist_wal_async + persist_recover()) recovers the exact wire start_time and pidinfo; (6) test_wjs_real_on_job_start_survives_restart -- drives the REAL production on_job_start() path (record_job_start_fact()'s only caller) with a real job_pidinfo_t (3 real pids, 2 real pgids, real exdata string), through a real WAL-write + persist_recover() restart cycle (the exact technique test_dispatch_commit.c's test_dc_success_appends_wal_job_dispatch_durably already established for bug-1678), asserting pidinfo AND start_time (bounded to the real wall-clock window around the on_job_start() call) survive the restart intact -- the audit's exact confirmed root cause and the user's exact acceptance criterion.
RED->GREEN independently verified live (not just narrated): git-stashed job.c+persist.c (keeping the new test file, persist.h, wal_types.h unchanged) via git stash push -- src/controller/job.c src/controller/persist.c, rebuilt, ran ./controller_unit_test -t test_wal_job_start_fact -- 6 Tests 4 Failures 0 Ignored (the 2 backward-compat tests correctly PASS unchanged; all 4 new-behavior tests correctly FAIL with the exact expected mismatches, e.g. 'Expected 1700000001 Was 1787645264' for the fabricated-vs-wire start_time, 'must set job.pidinfo... not just state' for the real on_job_start test). Restored via git stash pop, rebuilt, re-ran -- 6 Tests 0 Failures 0 Ignored. Full controller_unit_test suite re-run after all fixes (including the test_commit_barrier_reply.c hang fix and the buglog-id renumber from a concurrent session's own bug-1686 claim): 1146 Tests 2 Failures 0 Ignored, ~38s, zero hangs -- the 2 failures are test_conf_trim_keeps_only_n_versions ('Expected 2 Was 3') and test_conf_get_saved_tag_no_config ('Expected 0 Was ') in test_config_repl.c, an already-logged, pre-existing, unrelated overlayfs sandbox fdatasync artifact (bug-1561, re-observed identically across multiple unrelated sessions with zero diff to test_config_repl.c/config_repl.c each time) -- confirmed by exact signature match, not a new regression.
Verification
Not recorded (migrated from buglog.json).
References
- Related: bug-1678, bug-1452, bug-1561