From 673759f83b854c311eae8662e5c760675fdb0a6c Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Mon, 17 Aug 2026 12:38:43 +0000 Subject: [PATCH] chore(wolf): checkpoint buglog.json (950 bugs) --- .wolf/buglog.json | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index b5aac78d..69b6e292 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -16971,8 +16971,8 @@ "id": "bug-1569", "timestamp": "2026-08-17T10:50:00Z", "error_message": "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.", - "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 `) 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) STILL OPEN, root cause NOT found. B1 (legacy xce_sched_fcfs picker active) was RULED OUT via the main.c diagnostic INFO log -- live-confirmed 'active job picker plugin: builtin_fcfs'. B2 (resource-starvation: dynamic resvals never reaching live core state so every candidate fails a resource-sufficiency check) is NOW ALSO RULED OUT: re-verified against the SAME live deployment used to confirm (A)'s fix, with dynamic resvals CONFIRMED correctly flowing into the live (non-replay) scheduler core (338+ consecutive driver rounds, schedUpdateResvals notifies landing every ~15s, no WARNs) -- yet a freshly submitted job (queue 'xce', resreq 'type == any', worker 'pc13v' online with 22 free slots) still never leaves PEND; xce_sched_driver_run_normal_mode_round still logs 'decision = (nil)' on every single round. True root cause for (B) is UNKNOWN -- candidates not yet investigated: on_queue_update()/on_job_push() picker hooks not actually firing or not populating builtin_fcfs's internal candidate list correctly, sched_job_is_ready()/sched_queue_is_ready() unexpectedly evaluating false, or sched_allocator()/sched_make_allocation() itself silently failing before ever reaching the picker.", - "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) NOT YET FIXED -- root cause still unknown after ruling out both B1 (legacy picker) and B2 (resource starvation). Needs a fresh investigation pass into the picker-hook-firing / candidate-eligibility / allocator path specifically.", + "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 `) 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).", "tags": [ "scheduler", "controller", @@ -16982,17 +16982,19 @@ "job-dispatch", "job-pick-plugin", "resval-host-mismatch", - "thread-a-fixed", - "thread-b-open", - "needs-investigation", + "picker-registration-gap", + "null-pointer-crash", + "off-by-one", + "sigsegv", + "fully-fixed", "test-methodology-artifact" ], "related_bugs": [ "bug-1567", "bug-1568" ], - "occurrences": 3, - "last_seen": "2026-08-17T11:59:00Z" + "occurrences": 4, + "last_seen": "2026-08-17T12:32:00Z" } ] }