From f5e105ea9fbffbb6ad8fe4ad651b6d18a632bcff Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Wed, 26 Aug 2026 04:17:52 +0000 Subject: [PATCH] chore(wolf): checkpoint buglog.json (1038 bugs) --- .wolf/buglog.json | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index fb09de57..4a64dab2 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -18794,8 +18794,8 @@ "timestamp": "2026-08-25T17:40:00Z", "error_message": "User-reported issue in the scheduler's interactive simulator REPL (`xce_scheduler -i`/`--sim`): `info worker all` and `info worker ` (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.", "file": "src/scheduler/src/repl_info.c (repl_info_worker_one(), ~line 309-388, the `info worker` print path), src/scheduler/src/core_events.c (core_apply_worker_resvals(), ~line 478, the WORKERS_PUSH resval-merge path), src/lib/zarray.c (zarray_put_ex(), ~line 267-303, count-vs-slot bookkeeping)", - "root_cause": "PARTIALLY ROOT-CAUSED (2026-08-25), via live reproduction against the user-supplied /tmp/scheduler-replay-20260825-090251.replay (`build.dbg/scheduler/xce_scheduler --sim -i`, driving the exact `step 5` sequence from the report) plus -vvv DEBUG3 TRACE log inspection -- TWO independent bugs found, neither fully pinned to its exact trigger line yet:\n(1) A count-doubling anomaly in core_apply_worker_resvals() (core_events.c): the first WORKERS_PUSH for worker 'pc13v' carries 20 resvals and correctly leaves worker->resvals.count=20. A SECOND WORKERS_PUSH for the SAME worker, carrying the SAME 20 resource names again, makes worker->resvals.count jump to 40 instead of staying at 20 (confirmed via TRACE: 'applied 20 resval(s)' then 'applied 40 resval(s)'). zarray_put_ex() (zarray.c:267-303) only increments array->count when the target slot's existing pointer is NULL ('if (ptr != NULL) { killer(ptr); } else { array->count++; }') -- a doubling means all 20 second-push writes landed on slots that read NULL at write time, implying something zeroed those 20 worker->resvals.data[] slots between the two pushes WITHOUT going through zarray's own removal path (which would have decremented count back down first). The exact clearing site was not isolated within the investigation's time budget -- core_reset_workers() (core_session.c:84-108) was checked and ruled out (only touches w->resInUse, not w->resvals); no resmgr rebuild/re-registration appears in the log either. Next step: add a one-line TRACE of each resource's zarray index (r->idx) per name across both pushes in core_apply_worker_resvals() and re-run this exact replay to see whether the same resource name maps to two different indices (an idx-resolution bug) or whether the backing array is being cleared by something else entirely.\n(2) A SEPARATE, independent display-layer bug in repl_info_worker_one() (repl_info.c:324): its resource-print loop uses `for (i = 0; i < w->resvals.count; i++)` -- treating `.count` (number of currently-populated slots) as a safe index upper bound for iterating the zarray by index. resource.c:228 shows the correct convention already established elsewhere in this codebase for the identical structure: `int num_res = (int)w->resvals.caps;` -- `.caps` (allocated capacity, monotonic, never shrinks) is the right loop bound for index-based zarray iteration, NOT `.count` (which can legitimately be less than the highest occupied index once entries are sparse/non-contiguous -- exactly the state bug (1)'s stale/over-reported count produces, but this display bug is real and reachable independently of bug (1) ever occurring, any time resvals becomes sparse for any reason). This is very likely the DIRECT cause of the user-visible symptom (all resource lines vanishing while status=online persists): once bug (1) leaves the array in a sparse state relative to a wrong/stale count, this loop bound mis-computes and silently under-iterates to zero visible lines.\nNo matching prior bug found in buglog.json (searched WORKERS_PUSH/resvals/'info worker'/resource-value-disappear) or cerebrum.md. Closest relative: bug-1568 (multiple WORKERS_PUSH on worker join dropping resvals via an add-only key_add()), already fixed via the core_upsert_worker() merge path -- but that very merge path (core_apply_worker_resvals()) is what this NEW count-doubling anomaly now implicates, so a full fix should re-examine bug-1568's fix for a second-push-specific edge case it may not have covered.", - "fix": "NOT FIXED -- root cause (1) (the count-doubling trigger site) still needs one more targeted trace to pin down exactly; root cause (2) (repl_info.c:324's `.count` vs `.caps` loop-bound bug) is independently understood and fixable on its own (mirror resource.c:228's `.caps` convention) but has NOT been implemented yet -- deferred as a follow-up task, not done in this session (this session's primary task was the unrelated bug-1687 controller/WAL fix). No code changes made for this bug yet.", + "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:\n(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.\n(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:\n(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).\n(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).\nEnd-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.\nFull 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.", "tags": [ "scheduler", "simulator", @@ -18803,11 +18803,11 @@ "info-worker", "resource-values", "regression", - "partially-root-caused", - "needs-followup", "zarray-count-vs-caps", "resvals-merge", - "worker-push" + "worker-push", + "null-value-overwrite", + "fixed" ], "related_bugs": [ "bug-1568"