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.9 KiB
| id | status | status_updated | status_note | component | severity | timestamp | last_seen | occurrences | files | tags | related | legacy | ||||||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| bug-1688 | fixed | 2026-09-24 | scheduler | unknown | 2026-08-25T17:40:00Z | 2026-09-19T09:00:00Z | 1 |
|
|
|
true |
bug-1688: User-reported issue in the scheduler's interactive simulator REPL (xce_scheduler -i/--sim)…
Description
User-reported issue in the scheduler's interactive simulator REPL (xce_scheduler -i/--sim): info worker all and info worker <name> (e.g. info worker pc13v) initially print full per-resource detail ([sim] resource slots: value=22.00 used=0.00, resource mem: value=..., etc -- ~19 resource lines including slots/mem/r1m/r15m/r15s/ut/pg/ls/it/swp/io/tmp/type/model/cpuf/maxcpus/maxmem/maxswap/maxtmp/ndisks). After stepping the simulation forward through several sessions (step 5 repeated, crossing RESVALS_DELTA, JOB_PUSH (2 batches, 40+80 jobs), JOB_UPDATE, and WORKERS_PUSH events across sessions 2 through 30), the SAME commands later in the SAME REPL session regress to printing ONLY the header line: [sim] worker pc13v: status=online -- zero resource lines, even though the worker still exists and is still 'online' (not removed/dead). Binary under test: ./build.dbg/controller/xce_controller --version reports xce v0.0.1-bc3f76b4-5ff97622 built 2026-08-25T08:56:58Z (a build.dbg build -- note the user ran the CONTROLLER binary's --version, though the symptom itself is in the SCHEDULER's sim REPL; worth confirming which binary actually serves xce_scheduler -i/--sim and its own version once investigated). A real replay file reproducing the sequence is preserved at /tmp/scheduler-replay-20260825-090251.replay (~1MB, captured 2026-08-25 09:24 UTC) for a future investigation to replay directly instead of needing to reproduce from scratch.
Environment
Not recorded (migrated from buglog.json).
Reproduction
Not recorded (migrated from buglog.json).
Root cause
FULLY ROOT-CAUSED (2026-08-26), via live TRACE against the same /tmp/scheduler-replay-20260825-090251.replay this bug was originally reported with (build.dbg/scheduler/xce_scheduler --sim -i -vvv, driving the exact step 5 sequence, plus temporary per-call TRACE instrumentation in core_events.c/core_session.c/lib/zarray.c added and then fully removed once the trigger was pinned down). TWO independent bugs, both now fully understood and fixed:
(1) core_apply_worker_resvals() (core_events.c) -- the count-doubling anomaly's ACTUAL trigger turned out to be neither an idx-resolution bug nor external memory corruption (both hypotheses from the prior session are RULED OUT: a per-resource resolved idx= trace across both pushes showed the SAME resource name always resolves to the SAME r->idx both times, and core_reset_workers()/xce_core_begin_session()/xce_core_end_session() were bracket-traced across many session boundaries with resvals.data's pointer, .count, and slot occupancy all provably untouched -- confirming core_reset_workers() only ever touches w->resInUse, exactly as previously suspected). The REAL mechanism, pinned down via a direct per-entry trace of nv->val itself: a WORKERS_PUSH re-announcing an already-registered worker's resource NAME list can legitimately decode nv->val to NULL for EVERY entry (confirmed: controller.capnp.c's decode_Value_ptr(), line ~2966-2976, sets *d = NULL whenever the wire NameValue.val capnp pointer is CAPN_NULL -- a faithful decode of what the controller-side encoder chose to send, not a decode bug). core_apply_worker_resvals() unconditionally MOVE_PTR'd this NULL into val and called zarray_put(&worker->resvals, r->idx, NULL) for every one of the 20 resources, silently overwriting each previously-known-good value with NULL. Because zarray_put_ex() (zarray.c:267-303) only increments array->count when the slot being written was NULL beforehand, this FIRST NULL-write left resvals.count unchanged (the snapshot-restored slot was non-NULL, so the 'else count++' branch never fired) while silently zeroing the slot's DATA -- confirmed live via a watched-array TRACE in zarray_put_ex() showing new_data=(nil) for all 20 writes on BOTH the first and second WORKERS_PUSH. A THIRD push then found every slot already NULL (from the first push's own corruption) and hit the 'was NULL, count++' branch for all 20, producing the literal 20 -> 40 doubling this bug was originally reported with. Ownership of the 'why does the controller push a repeat announce with no values' question is out of scope for this session (src/controller/ is off limits per this task's boundaries, and the fix does not depend on the answer) -- the defensive scheduler-side fix protects worker resvals regardless of why the wire push omitted a value.
(2) repl_info_worker_one() (repl_info.c:324, confirmed unchanged from prior session's diagnosis) -- its resource-print loop used for (i = 0; i < w->resvals.count; i++), treating .count as a safe index upper bound. .caps (resource.c:228's own established convention for this identical structure) is correct; .count can legitimately be less than the highest occupied index once entries are sparse -- exactly the state bug (1) produces (9 static resources nulled by a WORKERS_PUSH, 11 dynamic ones kept fresh by later RESVALS_DELTA events, live-confirmed as the actual after-fix-1-absent steady state for this replay: info worker pc13v after 30x step 5 showed only mem/r1m/r15m/r15s/ut/pg/ls/it/swp/io/tmp, missing slots/type/model/cpuf/maxcpus/maxmem/maxswap/maxtmp/ndisks -- a real, reproduced PARTIAL instance of the reported symptom, not the fully empty header-only case, which likely needs a longer replay or a worker with no periodically-refreshed resources at all to reach).
Fix
FIXED (2026-08-26), TDD RED->GREEN for both root causes, both verified independently and together:
(1) src/scheduler/src/core_events.c: core_apply_worker_resvals()'s per-resval loop guard extended from if ((nv == NULL) || (nv->name == NULL)) to if ((nv == NULL) || (nv->name == NULL) || (nv->val == NULL)) -- a NULL nv->val is now skipped (preserve whatever value is already there), the same defensive 'continue' posture already applied to the other two NULL checks. The pre-existing if (nv->val != NULL && nv->val->which == Value_u_fvalue) TRACE guard just below was simplified to if (nv->val->which == Value_u_fvalue) since nv->val == NULL can no longer reach that line. New regression test in src/scheduler/testsuite/test_core_events.c: test_workers_push_with_null_val_does_not_clobber_existing_resval -- pushes 2 resources (mem=100.0, r1m=5.0) for worker 'hostA', then pushes the SAME names with nv->val==NULL for both, asserts resvals.count stays 2 and both values survive unchanged; a THIRD identical NULL push re-confirms count stays 2 (would have been 4 under the pre-fix count- doubling behavior). RED confirmed live (git stash of just this file's fix, rebuilt, ran sched_core_events_test: 'Expected Non-NULL' failure at the post-second-push value check, 10/11 tests passing otherwise); GREEN confirmed after git stash pop + rebuild (11 Tests 0 Failures).
(2) src/scheduler/src/repl_info.c: repl_info_worker_one()'s resource loop bound changed from w->resvals.count to w->resvals.caps, mirroring resource.c:228's int num_res = (int)w->resvals.caps; convention exactly; the loop's existing avail_v==NULL/rname==NULL skip is unchanged and already handles the now-larger, sparser index range safely. New regression test in src/scheduler/testsuite/test_repl_breakpoints_inspection.c: test_info_worker_shows_all_populated_resources_when_count_is_stale -- worker with 2 populated resvals slots (idx0 'mem', idx1 'r1m') but resvals.count forcibly set to 1 (the exact stale/sparse shape bug (1)'s prior failure mode produced), asserts info worker output contains BOTH resource lines. RED confirmed live (git stash of just this file's fix, rebuilt sched_repl_breakpoints_inspection_test: 28/29 passing, new test failing with the exact expected message 'a populated slot at an index >= the (stale) .count must still display'); GREEN confirmed after git stash pop + rebuild (29 Tests 0 Failures).
End-to-end reproduction against the ORIGINAL /tmp/scheduler-replay-20260825-090251.replay, driving info worker pc13v before any steps, then 30x step 5, then info worker pc13v again: BEFORE the fix, the final info worker pc13v printed only 11 of 20 resource lines (mem/r1m/r15m/r15s/ut/pg/ls/it/swp/io/tmp survive via RESVALS_DELTA refresh; slots/type/model/cpuf/maxcpus/maxmem/maxswap/maxtmp/ndisks silently vanish) -- a live-reproduced instance of the reported regression class. AFTER both fixes, the same sequence's final info worker pc13v shows all 20 resource lines identical in shape to the very first (pre-step) dump, with only the naturally-updated dynamic values (mem/r1m/r15m/etc.) differing in magnitude as expected from real RESVALS_DELTA updates over 30 rounds -- status=online, zero missing lines.
Full scheduler suite (xce-build.sh scheduler, ASAN profile): 53/54 tests OK, 1 failure -- test_recordstart_symlink_escape_replies_error (sched_admin_request_test), the exact pre-existing bug-1560 sandbox artifact (Expected 'invalid record file name' Was 'permission denied accessing record file'), confirmed unrelated (no files this bug touches -- core_events.c/repl_info.c/zarray.c -- are anywhere near record-file-path validation). Zero new failures; both new tests (sched_core_events_test 21/54, sched_repl_breakpoints_inspection_test 52/54) pass in the full suite run.
Verification
Not recorded (migrated from buglog.json).
References
- Related: bug-1568