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>
7 KiB
| id | status | status_updated | status_note | component | severity | timestamp | last_seen | occurrences | files | tags | related | legacy | ||||||||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| bug-1697 | fixed | 2026-09-24 | controller | unknown | 2026-08-25T20:22:00Z | 2026-09-19T09:00:00Z | 1 |
|
|
|
true |
bug-1697: Job start_time is always 0 for every job, live, no restart needed (observed via xce_test REPL…
Description
Job start_time is always 0 for every job, live, no restart needed (observed via xce_test REPL joblist during an HA soak). run_time (finish_time - start_time) is consequently also wrong for every finished job.
Environment
Not recorded (migrated from buglog.json).
Reproduction
Not recorded (migrated from buglog.json).
Root cause
dispatch_a_job_() (job.c:1686, scheduler-dispatch-commit task 3.1) synchronously sets j->job.state = JOB_STAT_RUN at DISPATCH time, before the worker ever reports back -- this is a deliberate, already-made semantic change: the controller decides RUN at dispatch, it no longer waits for a worker ack. When the worker's LATER on_job_start()/WAL_JOB_START fact commits and apply_committed_entry()'s live apply pump (persist.c, shared WAL_JOB_START/FINISH/STOP/RESUME/RUSAGE/CKPT/PREASON/DISPATCH case group starting ~persist.c:4430) processes it, apply_job_update_transition(j, JOB_STAT_RUN) (job.c:2779) sees job->job.state already == JOB_STAT_RUN (set by dispatch, moments/seconds earlier) and returns JOB_TRANSITION_NOOP_DUPLICATE (job.c:2795-2799), never JOB_TRANSITION_APPLIED. The wire-carried start_time/pidinfo decode/adopt block bug-1687 added (persist.c ~4602-4637) is gated on result == JOB_TRANSITION_APPLIED (persist.c:4594), so for WAL_JOB_START it can now NEVER run, for any job -- start_time and pidinfo (pids/pgids/exdata) both silently stay at their zero-initialized defaults forever. This is the exact same class of bug already fixed for WAL_JOB_RUSAGE/WAL_JOB_CKPT/WAL_JOB_PREASON in this identical function (their own comments describe it verbatim: 'gating this adoption on result==JOB_TRANSITION_APPLIED ... would make it dead code ... decode/adopt unconditionally') -- WAL_JOB_START was never given the same treatment because bug-1687 (which added the start_time/pidinfo wire fields) predates/was unaware of the dispatch-time RUN semantic collision. bug-1679's own comment (job.c:1709-1719) already independently documented and worked around the SAME root collision for a different symptom (the apiserver update-notification hook silently not firing on this same NOOP_DUPLICATE path) -- the two symptoms were never connected as the same root cause until now.
Fix
FIXED -- start_time moved to dispatch-owned, pidinfo adoption made unconditional, exactly the confirmed scope. (1) job.c dispatch_a_job_() (job.c:1696-1708) stamps j->job.start_time = time(NULL) synchronously alongside j->job.state = JOB_STAT_RUN, under the same write lock, before j->job.allocs/persist_submit_job_dispatch_fact(). (2) wal_types.h adds WAL_JOB_DISPATCH_HAS_START_TIME_FLAG (new _pad bit, mirroring WAL_JOB_FAIL_STAGE_FLAG/WAL_JOB_UPDATE_POSTDONE_MARK). persist_submit_job_dispatch_fact() (persist.c:7670, persist.h:1465) gained a uint64_t start_time parameter; payload is now [wal_jobstate_t header, _pad=FLAG][uint64_t start_time][JobAlloc bytes] -- flag-gated, not length-based, since JobAlloc's own variable length would make a length heuristic ambiguous against the old header+alloc-only shape. (3) Both apply seams' WAL_JOB_DISPATCH cases (apply_committed_entry persist.c:4716 branch; apply_wal_entry persist.c:4183 case; restore_job_dispatch_state job.c:801) decode/adopt start_time when the flag is set, else fall through to the pre-fix alloc-only decode untouched. (4) apply_committed_entry's WAL_JOB_START handling (persist.c:4627-4660): start_time touching removed entirely (dead-code branch and its time(NULL) fallback deleted); pidinfo decode/adopt moved OUT of the result == JOB_TRANSITION_APPLIED gate to run unconditionally, mirroring the RUSAGE/CKPT/PREASON blocks in the same function. apply_wal_entry's WAL_JOB_START case (persist.c:4105) and restore_job_start_state() (job.c:840, dropped the start_time parameter) likewise stop touching start_time; pidinfo there was already unconditional (this seam never calls apply_job_update_transition, so it never had the NOOP-gating hazard). persist_submit_job_start_fact()'s wire format is UNCHANGED (still writes start_time for on-disk layout continuity) -- only the READ side stopped consuming it. Pre-fix WAL_JOB_DISPATCH/WAL_JOB_START entries (_pad flag unset) fall back to the exact pre-fix behavior, an accepted one-time migration-boundary gap consistent with every other fix in this campaign. TDD: RED confirmed by temporarily reverting just the two defect lines (job.c's start_time stamp; persist.c's pidinfo gate) and running the full suite -- 5 genuine new failures (test_dc_success_stamps_start_time_synchronously, test_dc_success_appends_wal_job_dispatch_durably, test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_dispatch, test_wjs_restart_replay_recovers_dispatch_start_time_and_started_pidinfo, test_ace_job_start_sets_start_time) plus the pre-existing baseline (2 known bug-1561 test_config_repl.c failures + 1 concurrent bug-1696 test_job_array_replay_fence.c failure, both left untouched). GREEN after restoring the fix: rebuilt clean (0 compile errors) in an isolated dir (avoided the live HA soak's build-asan), full controller_unit_test run 3x direct (ASAN_OPTIONS=detect_leaks=0, matching this binary's own meson.build env) -- consistently "1198 Tests 3 Failures 0 Ignored", exactly the known baseline, 0 new failures. Live manual verification: single-node controller+scheduler+xcecd_virtual worker deployed via deploy-ha.sh (isolated port 19991, isolated workdir, no interference with the concurrent bug-1696 soak); 4 real xce_test jobsub->dispatch->finish cycles via the REPL all showed nonzero StartTime in joblist immediately (e.g. jobid 0-14-...-55018: StartTime 1787718938, matching SubmitTime). pidinfo's live collision path (jstart is a worker-mode-only REPL command, racy/awkward to trigger against a job a real worker is also concurrently finishing) was left to the deterministic unit tests above rather than a flaky live race -- covered exhaustively there at the exact apply_committed_entry()/on_job_start() call sites. Files: src/controller/job.c, src/controller/persist.c, src/include/persist.h, src/include/wal_types.h, src/controller/testsuite/{test_wal_job_dispatch_fact.c,test_wal_job_start_fact.c,test_dispatch_commit.c,test_apply_committed_entry.c,test_repl_apply.c (weak stub signature only)}.
Verification
Not recorded (migrated from buglog.json).
References
- Related: bug-1679, bug-1687, bug-1678, bug-1690, bug-1691, bug-1692