From 0d1ab09eb77377e82f291c801a5d1cdefe723705 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Mon, 17 Aug 2026 10:35:47 +0000 Subject: [PATCH] chore(wolf): checkpoint buglog.json (949 bugs) --- .wolf/buglog.json | 61 ++++++++++++++++++++++++++++++++++++++++++----- 1 file changed, 55 insertions(+), 6 deletions(-) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 0b4d4639..9db8e3a3 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -16866,25 +16866,26 @@ "timestamp": "2026-08-17T09:00:00Z", "error_message": "xce_scheduler -i -s : 'info worker ' shows total=0.00 available=0.00 for every resource, even though the live cluster (xce_test resval/workerlist) reports real non-zero values for the same worker -- CONFIRMED ROOT CAUSE (superseding this entry's earlier 'architecture gap' theory, which was wrong -- corrected after the user pointed to worker.c's real mark_host_res()/update_val_res() write path)", "file": "src/scheduler/src/repl_info.c, src/scheduler/src/snapshot_wire.c, src/scheduler/src/snapshot_load.c, src/controller/sched.c", - "root_cause": "CONFIRMED via live value-level TRACE instrumentation (not just counts this time): xce_core_push_events()'s XCE_CORE_EVENT_WORKERS_PUSH handler (src/scheduler/src/core_events.c) calls sched_add_worker() UNCONDITIONALLY on every push -- and sched_add_worker() (src/scheduler/src/core.c:270) is a plain key_add() (ADD-ONLY semantics: fails -EEXIST if the worker name is already registered, never updates in place). A worker connecting triggers MULTIPLE WORKERS_PUSH events in quick succession (confirmed live: sched.c's collect_resval()/xcesched_push_workers() fire more than once during join sequencing -- e.g. an early push before src/controller/worker.c's apply_join_state()->add_hostattrs_resvals()/set_host_slots() has finished writing real hostattrs-derived values into w->host.resvals, carrying stale/zero data, followed by a later push carrying the real values). The FIRST push's sched_add_worker() call succeeds and registers the worker (confirmed: 'sched_add_worker(\"pc13v\") ok (idx=0)' at 10:02:34.848, immediately preceded by a TRACE showing it received maxmem=0.000000). The SECOND push's freshly-built xce_sched_worker_t -- this time carrying the REAL values (confirmed: 'resource maxmem received fvalue=33182089216.000000', matching xce_test's own real 30.9GB reading, at 10:02:36.849 -- silently fails sched_add_worker() with rc=-17 (-EEXIST) one line later in the SAME log, and its return value was unchecked until this investigation's own instrumentation added the WARN (core_events.c, added this session) that finally surfaced it. The correctly-valued worker object is discarded/leaked; core->workers['pc13v'] permanently keeps the FIRST, zero-valued object. This is not limited to the initial-join race -- because there is no 'update an existing worker in place' event type (unlike jobs, which have XCE_CORE_EVENT_JOB_STATE_CHANGE/JOB_UPDATE for in-place mutation of an already-added job), EVERY subsequent WORKERS_PUSH for an already-registered worker (sched_worker_change's ongoing per-event pushes throughout normal cluster operation, not just at join) hits the identical silent EEXIST-discard. The scheduler's view of a worker's resources freezes forever at whichever push happened to land first and win the race, and never updates again for the lifetime of the process.", - "fix": "NOT YET FIXED -- root cause confirmed live with reproducible TRACE evidence (this session's own instrumentation across src/controller/worker.c, dataex.c, sched.c and src/scheduler/src/core_events.c). Correct fix: XCE_CORE_EVENT_WORKERS_PUSH's handler (core_events.c, xce_core_push_events()) should look up an existing worker by name first (sched_get_worker()) and update it in place (status + resvals, mirroring how XCE_CORE_EVENT_JOB_STATE_CHANGE/JOB_UPDATE mutate an existing job rather than re-adding) instead of unconditionally building a fresh xce_sched_worker_t and calling sched_add_worker() (add-only, key_add()-backed) every time. Reported to user with full evidence chain; awaiting go-ahead to implement + TDD regression test.", + "root_cause": "CONFIRMED via live value-level TRACE instrumentation (not just counts this time): xce_core_push_events()'s XCE_CORE_EVENT_WORKERS_PUSH handler (src/scheduler/src/core_events.c) calls sched_add_worker() UNCONDITIONALLY on every push -- and sched_add_worker() (src/scheduler/src/core.c:270) is a plain key_add() (ADD-ONLY semantics: fails -EEXIST if the worker name is already registered, never updates in place). A worker connecting triggers MULTIPLE WORKERS_PUSH events in quick succession (confirmed live: sched.c's collect_resval()/xcesched_push_workers() fire more than once during join sequencing -- e.g. an early push before src/controller/worker.c's apply_join_state()->add_hostattrs_resvals()/set_host_slots() has finished writing real hostattrs-derived values into w->host.resvals, carrying stale/zero data, followed by a later push carrying the real values). The FIRST push's sched_add_worker() call succeeds and registers the worker (confirmed: 'sched_add_worker(\"pc13v\") ok (idx=0)' at 10:02:34.848, immediately preceded by a TRACE showing it received maxmem=0.000000). The SECOND push's freshly-built xce_sched_worker_t -- this time carrying the REAL values (confirmed: 'resource maxmem received fvalue=33182089216.000000', matching xce_test's own real 30.9GB reading, at 10:02:36.849 -- silently fails sched_add_worker() with rc=-17 (-EEXIST) one line later in the SAME log, and its return value was unchecked until this investigation's own instrumentation added the WARN (core_events.c, added this session) that finally surfaced it. The correctly-valued worker object is discarded/leaked; core->workers['pc13v'] permanently keeps the FIRST, zero-valued object. This is not limited to the initial-join race -- because there is no 'update an existing worker in place' event type (unlike jobs, which have XCE_CORE_EVENT_JOB_STATE_CHANGE/JOB_UPDATE for in-place mutation of an already-added job), EVERY subsequent WORKERS_PUSH for an already-registered worker (sched_worker_change's ongoing per-event pushes throughout normal cluster operation, not just at join) hits the identical silent EEXIST-discard. The scheduler's view of a worker's resources freezes forever at whichever push happened to land first and win the race, and never updates again for the lifetime of the process. UPDATE: after fixing sched_add_worker's EEXIST discard, live re-testing showed 'info worker' STILL displayed 0.00 for every resource despite value-level TRACE evidence confirming the real number (e.g. slots=22, maxmem=33182089216) survived the FULL round trip intact -- controller push -> scheduler apply -> snapshot save (20/20 captured) -> snapshot load/decode (20/20 restored, correct fvalue) -- so the remaining gap had to be in the DISPLAY layer itself, unconnected to the push/save/load pipeline. Found: repl_info_worker_one()/repl_info_resource_one() (src/scheduler/src/repl_info.c) checked `avail_v->which == XCE_VAL_NUMERIC` to decide whether an xce_val_t held a real number. XCE_VAL_NUMERIC (xce/types.h, value 1) is a RESOURCE-DEFINITION value-type constant (xce_resource_t.valtype's own enum) -- a completely different enum from xce_val_t.which's real domain, Value_u_which (controller.capnp.h, Value_u_fvalue=5). Every producer in this codebase sets xce_val_t.which to Value_u_fvalue, never XCE_VAL_NUMERIC, so the comparison was ALWAYS false for a genuinely-numeric resval -- 'info worker'/'info resource' printed total=0.00/available=0.00 unconditionally, regardless of whether the underlying data was correct (which it was, once bug-1567's picker fix and the sched_add_worker EEXIST fix were both in place). This display bug is what made the user's originally-reported symptom persist even after both upstream fixes.", + "fix": "FIXED (TDD, RED->GREEN), TWO independent root causes, both confirmed and fixed: (1) src/scheduler/src/core_events.c: XCE_CORE_EVENT_WORKERS_PUSH now goes through a new core_upsert_worker() (mirrors the existing core_upsert_queue() add-or-update precedent) -- looks up the worker by name first (sched_get_worker()), updates status+resvals in place if found (via a new shared core_apply_worker_resvals() helper, safe without a wipe step since zarray_put() already frees any existing value at a given index), else builds+adds a new one via the original core_build_worker()/sched_add_worker() path. New regression test in test_core_events.c: two WORKERS_PUSH events for the SAME worker name with DIFFERENT resource values must both apply -- resvals end up at the SECOND push's values, not stuck at the first, no duplicate/orphaned worker object. (2) src/scheduler/src/repl_info.c: all 4 `->which == XCE_VAL_NUMERIC` checks (2 in repl_info_worker_one(), 2 in repl_info_resource_one()) corrected to `->which == Value_u_fvalue` (added #include \"controller.capnp.h\"). New regression test in test_repl_breakpoints_inspection.c: `info worker` on a worker with a real numeric resval (42.5) must display it, not fall back to 0.00. Both RED confirmed before the fix (unit tests), then GREEN after. Live-validated end-to-end against a real deployed cluster (controller + xcecd_virtual worker + scheduler), reproducing the user's EXACT original command sequence (deploy, record, `xce_scheduler -i -s `, `info worker pc13v`) -- now shows the real values matching the user's own report exactly: slots=22.00, maxmem=33182089216.00 (30.9GB), mem=17151664128.00 (16GB), etc. Full scheduler suite green (41/41 excluding pre-existing bug-1560); controller suite green (1102/1104, the same pre-existing bug-1561 pair, confirmed unrelated).", "tags": [ "scheduler", "controller", "simulation-mode", "resource-values", "worker-resvals", - "root-caused", "live-verified", "confirmed-bug", "sched_add_worker", - "key_add-eexist" + "key_add-eexist", + "fixed", + "tdd" ], "related_bugs": [ "bug-1567" ], - "occurrences": 3, - "last_seen": "2026-08-17T10:05:00Z" + "occurrences": 4, + "last_seen": "2026-08-17T10:35:00Z" }, { "id": "bug-945", @@ -16917,6 +16918,54 @@ "related_bugs": [], "occurrences": 1, "last_seen": "2026-08-17T09:14:35.731Z" + }, + { + "id": "bug-947", + "timestamp": "2026-08-17T10:14:50.237Z", + "error_message": "Wrong reference: test_job_rusage_applies_state_when_hook_is_null should be test_workers_push_twice_updates_existing_worker_in_place", + "file": "src/scheduler/testsuite/test_core_events.c", + "root_cause": "Used \"test_job_rusage_applies_state_when_hook_is_null\" instead of \"test_workers_push_twice_updates_existing_worker_in_place\"", + "fix": "Changed test_job_rusage_applies_state_when_hook_is_null \u2192 test_workers_push_twice_updates_existing_worker_in_place", + "tags": [ + "auto-detected", + "wrong-reference", + "c" + ], + "related_bugs": [], + "occurrences": 1, + "last_seen": "2026-08-17T10:14:50.237Z" + }, + { + "id": "bug-948", + "timestamp": "2026-08-17T10:16:21.240Z", + "error_message": "Significant refactor of ", + "file": "src/scheduler/src/core_events.c", + "root_cause": "3 lines replaced/restructured", + "fix": "Rewrote 74\u2192151 lines (3 removed) | Also: xce_sched_worker_t* worker; = core_build_worker(core, ev->u.workers_push.worke | Also: * WORKERS_PUSH core_build_worker() + sched_; * No picker hook (Req 1 AC 2:", + "tags": [ + "auto-detected", + "refactor", + "c" + ], + "related_bugs": [], + "occurrences": 3, + "last_seen": "2026-08-17T10:16:56.266Z" + }, + { + "id": "bug-949", + "timestamp": "2026-08-17T10:31:46.356Z", + "error_message": "Significant refactor of ", + "file": "src/scheduler/src/repl_info.c", + "root_cause": "2 lines replaced/restructured", + "fix": "Rewrote 4\u21929 lines (2 removed)", + "tags": [ + "auto-detected", + "refactor", + "c" + ], + "related_bugs": [], + "occurrences": 1, + "last_seen": "2026-08-17T10:31:46.356Z" } ] }