myxce/.wolf/bugs/bug-1569.md
Rongsong Shen d26ff8870d
feat(buglog): one Markdown record per bug, checked against a record standard
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>
2026-09-28 03:40:11 +00:00

9.7 KiB

id status status_updated status_note component severity timestamp last_seen occurrences files tags related legacy
bug-1569 fixed 2026-09-24 scheduler unknown 2026-08-17T10:50:00Z 2026-09-19T09:00:00Z 4
scheduler
controller
worker
normal-mode
resource-values
job-dispatch
job-pick-plugin
resval-host-mismatch
picker-registration-gap
null-pointer-crash
off-by-one
sigsegv
fully-fixed
test-methodology-artifact
bug-1567
bug-1568
true

bug-1569: TWO related, still-open problems on a live normal-mode (non-sim) deployment, found while verifying…

Description

TWO related, still-open problems on a live normal-mode (non-sim) deployment, found while verifying bug-1567/bug-1568's fixes actually let a real job dispatch: (A) 'info worker'/xceadmin-recorded snapshot still shows 0.00 for 'mem'/'r1m'/'r15m'/'r15s'/'ut'/'pg'/'ls'/'it'/'swp'/'io'/'tmp' (the 11 periodic resource_sync 'load index' metrics) even though xce_test's live 'resval -n mem -m pc13v' / 'resval -n r15s -m pc13v' show correct non-zero values on the SAME worker at the SAME time -- hostattrs-derived resources (slots/maxcpus/maxmem/maxswap/maxtmp/cpuf/ndisks, all fixed correctly by bug-1568) display fine; only the periodic/dynamic ones are still wrong. (B) A submitted job (single or array, queue 'xce', resreq 'type == any', worker 'pc13v' with 22 real slots available) never leaves PEND -- xce_sched_driver_run_normal_mode_round logs 'decision = (nil)' on EVERY round, forever (60+ consecutive rounds observed), meaning the scheduler never produces even a PEND decision, let alone DISPATCH, for any job.

Environment

Not recorded (migrated from buglog.json).

Reproduction

Not recorded (migrated from buglog.json).

Root cause

(A) FULLY ROOT-CAUSED AND FIXED. The periodic resval update path is DIFFERENT from the join-time hostattrs push bug-1568 fixed: src/controller/opupd.c's do_update_resvals() applies a worker's periodic report locally using the CORRECT connection-resolved worker w, but then re-fires HOOK_DETAIL_RESOURCE_UPDATE with the wire resvals list's OWN unmodified .host field, forwarded unchanged by src/controller/sched.c's sched_resource_hook_fun() -> notify() -> scheduler's handler.c/driver.c/core_events.c XCE_CORE_EVENT_RESVALS_DELTA case, which does sched_get_worker(core, rv->host). The true source of the wrong .host was WORKER-side, not xcecd_virtual-specific: src/worker/src/resource_sync.c's collect_load_indices() tagged every periodic report with gethostname() (the raw OS/container hostname -- 'xce' in this sandbox) instead of xcecd_ctx.virtual_name (the worker's actual join identity from -n/--name, e.g. 'pc13v'), which is what every OTHER worker-keyed lookup (mark_host_res()/sched_get_worker()) uses. FIXED (this session): collect_load_indices() now tags .host with xcecd_ctx.virtual_name, falling back to gethostname() only when virtual_name is unset. IMPORTANT CORRECTION to this entry's earlier note: after applying this fix, 'info worker'/'resval' via the INTERACTIVE REPL (xce_scheduler -i -s <replay>) appeared to still show 0.00 for mem/r1m/r15m/r15s/ut/pg/ls/it/swp/io/tmp -- this was a TEST-METHODOLOGY ARTIFACT, not a residual bug: the REPL starts PAUSED at the initial snapshot and requires an explicit step/continue command to advance the simulated clock past the recorded resvalsDelta ReplayEvent before querying state; querying immediately after load (as this investigation's own test scripts did, e.g. echo -e "info worker pc13v\nquit" with no step/continue first) only ever shows the pre-periodic-report baseline. Live-confirmed end-to-end via -vvv scheduler.log (schedUpdateResvals notify arrives, zero 'unknown worker'/'unknown resource' WARNs, xceadmin scheduler dump shows the resvalsDelta event correctly captured with all 11 metrics @pc13v) AND via step N in the REPL (mem=16786444288.00, r1m=0.64, r15m=0.99, r15s=0.64, ut=2.08, pg=463.20, it=3341.19, tmp=65732259840.00 -- all correct; ls/swp/io legitimately 0 on this idle sandbox). (B) FULLY ROOT-CAUSED AND FIXED -- THREE independent causes stacked on the same symptom, each one masking the next (each was only reachable once the prior one was fixed), all live-confirmed via gdb backtraces on real SIGSEGVs: B1 (legacy xce_sched_fcfs picker active) was RULED OUT via the main.c diagnostic INFO log -- confirmed 'active job picker plugin: builtin_fcfs'. B2 (resource-starvation) was RULED OUT -- dynamic resvals confirmed correctly flowing into live core state (thread A's fix), yet decisions stayed nil. The TRUE causes: (B-i) scheduler.c's sched_init_queues() -- the scheduler's ONE-TIME synchronous initial-config-push handler (handler.c's scheduler_req_handler, Request_body_configpushmsg) -- only called the pre-scheduler-core-rewrite plugin_queue_update() fan-out, which reaches a plugin's OLD job_elect_fn-era .hooks.queue_hook only; builtin_fcfs has no .hooks, only picker_iface, so on_queue_update() was NEVER called for any of the cluster's initial queues. builtin_fcfs's own internal per-queue candidate registry (fcfs_plugin_data_t.queues) stayed permanently empty from process start, so next_job() found zero candidates every session forever -- exactly 'decision=(nil) forever', regardless of resources/readiness. Every OTHER queue-registration path (core_events.c's core_upsert_queue(), used by QUEUE_UPDATE and a later CONFIG_PUSH config upgrade) already fired on_queue_update() correctly -- this was the one remaining call site still skipping it. (B-ii) Once B-i was fixed and a job first reached the picker, core_events.c's core_build_job() was found to never construct job->schedobj -- a DELIBERATE, DOCUMENTED omission from the scheduler-core rewrite ('no picker hook reads job->schedobj... belongs to the allocation path (scheduler-allocation spec), out of this task's scope') whose assumption was wrong: scheduler.c's sched_allocator() thread (plugin_job_election() + sched_make_allocation()) dereferences job->schedobj directly with no NULL check, and no 'scheduler-allocation spec' construction step exists anywhere in the live codebase -- every job built via JOBS_PUSH has had schedobj==NULL since the rewrite, reproduced live as a SIGSEGV in plugins/limit.c's limit_job_election() (obj->configver dereference on NULL obj), gdb-confirmed. (B-iii) Once B-i and B-ii were both fixed, a job reached genuine allocation (sched_make_allocation returned 1, a real DISPATCH) for the first time ever, and crashed a THIRD time inside resource.c's put_resvals() (gdb: NULL deref on xvals[0]) during post-dispatch resource-charge accounting -- an off-by-one: if (idxs[i] <= 0) continue; incorrectly treated resource index 0 ('slots', almost always the first resource resmgr registers) as an invalid sentinel, so the 'create a zero-value entry if missing' step was skipped for it, leaving xvals[0] NULL for the unconditional xvals[i]->u.fvalue = vals[i] write two lines later. get_resvals() (its read-side sibling in the same file) has no such guard, confirming this was a bug, not intentional design.

Fix

(A) FIXED -- src/worker/src/resource_sync.c's collect_load_indices() now tags .host with xcecd_ctx.virtual_name (fallback: gethostname() if unset). TDD: RED test confirmed the bug (test_collect_load_indices_tags_host_with_virtual_name_not_gethostname expected 'pc13v', got 'xce'), GREEN after fix; new src/worker/testsuite/test_resource_sync.c (2 tests) added to src/worker/testsuite/meson.build, full worker suite green (3/3). Live-validated on a real 3-process deployment (controller+scheduler+xcecd_virtual): 'unknown worker' WARN eliminated, resvalsDelta event correctly recorded/replayed with real values. (B) FIXED, all 3 stacked causes: (B-i) src/scheduler/src/scheduler.c's sched_init_queues() now resolves the active picker once and calls picker->picker_iface->on_queue_update(picker, q) for every queue from the initial config, in addition to the pre-existing plugin_queue_update() legacy fan-out (kept for job_elect_fn-only plugin compat) -- best-effort, logs+continues on a picker-resolve failure the same way core_upsert_queue() does. (B-ii) src/scheduler/src/core_events.c: new core-scoped core_build_schedobj()/core_build_primary_schedobj()/core_build_compound_schedobj()/core_build_alter_schedobj() (a port of schedobj.c's make_sched_obj()+3 helpers, parameterized WITHOUT xce_scheduler_t* since the original's sched param was verified dead/unused in its own body -- preserves this file's zero-controller-I/O boundary), wired into core_build_job() right after job->resreq is parsed. (B-iii) src/scheduler/src/resource.c's put_resvals(): idxs[i] <= 0 -> idxs[i] < 0 (idx 0 is a legitimate resource index, not a sentinel), plus a defensive NULL guard added to the second loop for the (now-unreachable except on OOM) calloc-failure case get_resvals() already guards against. All 3 confirmed via TWO independent live 1-node deployments (controller+scheduler+xcecd_virtual, real jobsub via xce_test): first with temporary WARN-level diagnostics in builtin_fcfs.c pinpointing exactly where each fix took effect (removed before commit, confirmed via grep DIAG returning empty), then a clean run with a 3-element job array -- ALL elements reached state DONE (PEND -> DISPATCH -> RUN -> DONE), scheduler process stayed alive throughout (no crash), decision log showed a real non-nil decision pointer (previously always (nil)). Root-caused the two post-B-i crashes via gdb bt full on the live SIGSEGVs, not guesswork. Full scheduler suite green (40/41, the 1 failure is bug-1479-unrelated pre-existing symlink-escape filename-validation test flakiness, confirmed unaffected -- same failure present both before and after this fix's stash/rebuild).

Verification

Not recorded (migrated from buglog.json).

References

  • Related: bug-1567, bug-1568