diff --git a/.wolf/anatomy-index.json b/.wolf/anatomy-index.json index 32a8da36..a3f8a99c 100644 --- a/.wolf/anatomy-index.json +++ b/.wolf/anatomy-index.json @@ -1,13 +1,13 @@ { "version": 1, "meta": { - "lastScanned": "2026-08-30T15:51:46.646Z", - "fileCount": 570, + "lastScanned": "2026-08-31T03:54:00.658Z", + "fileCount": 575, "hits": 0, "misses": 0, - "renderedHash": "02917fcf201105c5a47a46990a85e3a5eadaf3094f63f46a074a1cfc48fa942d", - "storeUpdatedAt": "2026-08-30T15:51:46.654Z", - "rootHash": "1dc62110ed2beaa4" + "renderedHash": "43f330a5fcfd989b26ec5853b8cb7632a5076cce612284639278639770beea86", + "storeUpdatedAt": "2026-08-31T03:54:00.667Z", + "rootHash": "7cffb22d03bb7768" }, "files": { ".agent-shell/transcripts/2026-08-11-11-39-59.md": { @@ -2782,12 +2782,11 @@ ".kiro/specs/scheduler-dispatch-commit/tasks.md": { "description": "Implementation Plan", "tokens": 7090, - "hash": "7142047d578f92b0", + "hash": "a48cfc4324ee6b65", "size": 28456, - "mtimeMs": 1787521121559.772, - "updatedAt": "2026-08-27T19:00:00.115Z", - "source": "scan", - "importance": 0.21 + "mtimeMs": 1788147698604.6914, + "updatedAt": "2026-08-31T03:41:38.651Z", + "source": "hook" }, ".kiro/specs/scheduler-framework/brief.md": { "description": "Brief: scheduler-framework", @@ -6254,20 +6253,20 @@ }, "src/scheduler/testsuite/test_core_events.c": { "description": "Declares and", - "tokens": 12017, - "hash": "79747faef09c99f5", - "size": 45063, - "mtimeMs": 1788104586039.423, - "updatedAt": "2026-08-30T15:43:06.089Z", + "tokens": 14476, + "hash": "e73e198fa18f8668", + "size": 54284, + "mtimeMs": 1788146521984.0552, + "updatedAt": "2026-08-31T03:22:02.022Z", "source": "hook" }, "src/scheduler/src/core_events.c": { "description": "include ", - "tokens": 13231, - "hash": "b61d009c6f3960bb", - "size": 49616, - "mtimeMs": 1788105106599.9404, - "updatedAt": "2026-08-30T15:51:46.646Z", + "tokens": 15175, + "hash": "61bc369088277fa5", + "size": 56904, + "mtimeMs": 1788146214025.4373, + "updatedAt": "2026-08-31T03:16:54.071Z", "source": "hook" }, "src/controller/job.c": { @@ -6281,11 +6280,11 @@ }, "src/controller/sched.c": { "description": "include ", - "tokens": 6721, - "hash": "3613637e5df87619", - "size": 25211, - "mtimeMs": 1787979549837.7444, - "updatedAt": "2026-08-29T04:59:09.885Z", + "tokens": 7390, + "hash": "aaa462caf9bab242", + "size": 27719, + "mtimeMs": 1788146289436.4927, + "updatedAt": "2026-08-31T03:18:09.485Z", "source": "hook" }, "src/controller/main.c": { @@ -6505,11 +6504,11 @@ }, "src/scheduler/src/handler.c": { "description": "include ", - "tokens": 7162, - "hash": "96c47fc30962bfd5", - "size": 26856, - "mtimeMs": 1788085225504.2131, - "updatedAt": "2026-08-30T10:20:25.539Z", + "tokens": 7039, + "hash": "a5231654adc45cba", + "size": 26395, + "mtimeMs": 1788146348619.908, + "updatedAt": "2026-08-31T03:19:08.665Z", "source": "hook" }, "src/controller/config_repl.c": { @@ -6658,11 +6657,11 @@ }, "src/schema/controller.capnp": { "description": "Declares OPCode", - "tokens": 15126, - "hash": "db582a215ce32ffa", - "size": 57419, - "mtimeMs": 1788103256851.4102, - "updatedAt": "2026-08-30T15:20:56.894Z", + "tokens": 15246, + "hash": "3817c9ff90e9f674", + "size": 57867, + "mtimeMs": 1788146303302.0571, + "updatedAt": "2026-08-31T03:18:23.339Z", "source": "hook" }, "src/controller/testsuite/test_commit_barrier_rollout.c": { @@ -6772,6 +6771,51 @@ "mtimeMs": 1788104772616.135, "updatedAt": "2026-08-30T15:46:12.655Z", "source": "hook" + }, + "src/include/typemap.h": { + "description": "if !defined(_TYPEMAP_H_)", + "tokens": 8034, + "hash": "4d23285f09d459c2", + "size": 30513, + "mtimeMs": 1788146313749.4832, + "updatedAt": "2026-08-31T03:18:33.795Z", + "source": "hook" + }, + "src/lib/helper.c": { + "description": "include ", + "tokens": 3062, + "hash": "64596e94baff921d", + "size": 11479, + "mtimeMs": 1788146322998.8606, + "updatedAt": "2026-08-31T03:18:43.032Z", + "source": "hook" + }, + "src/scheduler/testsuite/test_handlers.c": { + "description": "define UNIT_TEST 1", + "tokens": 3218, + "hash": "1318307091ab299f", + "size": 12100, + "mtimeMs": 1788146395605.835, + "updatedAt": "2026-08-31T03:19:55.647Z", + "source": "hook" + }, + "src/scheduler/src/repl_info.c": { + "description": "include ", + "tokens": 10557, + "hash": "d571423379639162", + "size": 39589, + "mtimeMs": 1788148391995.0005, + "updatedAt": "2026-08-31T03:53:12.052Z", + "source": "hook" + }, + "src/scheduler/testsuite/test_repl_breakpoints_inspection.c": { + "description": "Declares and", + "tokens": 20658, + "hash": "d1cc28ebe7a077e6", + "size": 77467, + "mtimeMs": 1788148440614.8572, + "updatedAt": "2026-08-31T03:54:00.657Z", + "source": "hook" } } } \ No newline at end of file diff --git a/.wolf/anatomy.md b/.wolf/anatomy.md index c9643b7e..24703328 100644 --- a/.wolf/anatomy.md +++ b/.wolf/anatomy.md @@ -1,7 +1,7 @@ # anatomy.md -> Auto-maintained by OpenWolf. Last scanned: 2026-08-30T15:51:46.646Z -> Files: 570 tracked | Anatomy hits: 0 | Misses: 0 +> Auto-maintained by OpenWolf. Last scanned: 2026-08-31T03:54:00.658Z +> Files: 575 tracked | Anatomy hits: 0 | Misses: 0 ## ./ @@ -814,7 +814,7 @@ - `meson.build` (~3852 tok) - `misc.c` — include (~2257 tok) - `persist.c` — define _GNU_SOURCE (~109226 tok) -- `sched.c` — include (~6721 tok) +- `sched.c` — include (~7390 tok) ## src/controller/include/ @@ -847,6 +847,10 @@ - `handler.go` — Struct: DefaultHandler (~3107 tok) +## src/include/ + +- `typemap.h` — if !defined(_TYPEMAP_H_) (~8034 tok) + ## src/include/xce/ - `types.h` — < NULL. (~5452 tok) @@ -854,6 +858,7 @@ ## src/lib/ - `controller.capnp.c` — include "controller.capnp.h" (~167125 tok) +- `helper.c` — include (~3062 tok) - `meson.build` (~1757 tok) - `utils.c` — include (~7883 tok) - `vtaskmgr.c` — include (~3978 tok) @@ -870,17 +875,20 @@ ## src/scheduler/src/ -- `core_events.c` — include (~13231 tok) +- `core_events.c` — include (~15175 tok) - `driver.c` — include (~9779 tok) -- `handler.c` — include (~7162 tok) +- `handler.c` — include (~7039 tok) - `main.c` — include (~5330 tok) +- `repl_info.c` — include (~10557 tok) - `snapshot_load.c` — include (~5920 tok) - `snapshot.c` — include (~8498 tok) ## src/scheduler/testsuite/ - `test_admin_request.c` — Declares level (~13020 tok) -- `test_core_events.c` — Declares and (~12017 tok) +- `test_core_events.c` — Declares and (~14476 tok) +- `test_handlers.c` — define UNIT_TEST 1 (~3218 tok) +- `test_repl_breakpoints_inspection.c` — Declares and (~20658 tok) - `test_sim_contention_parity.c` — Declares calls (~18713 tok) - `test_sim_e2e_original_motivation.c` (~17120 tok) - `test_sim_session_ordering.c` (~8092 tok) @@ -889,7 +897,7 @@ ## src/schema/ -- `controller.capnp` — Declares OPCode (~15126 tok) +- `controller.capnp` — Declares OPCode (~15246 tok) ## src/tools/ diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 9e6be6e2..0fc1d04a 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -18264,8 +18264,7 @@ "normal-mode", "sched_account_jobs", "JOB_IS_RUN", - "race-condition", - "unfixed" + "race-condition" ], "related_bugs": [ "bug-1611", @@ -18287,8 +18286,7 @@ "dispatch-failure", "notify", "unhandled-event", - "resource-leak", - "unfixed" + "resource-leak" ], "related_bugs": [ "bug-1624" @@ -18331,8 +18329,7 @@ "memory-leak", "refcount", "dispatch_a_job_", - "pre-existing", - "unfixed" + "pre-existing" ], "related_bugs": [ "bug-1626" @@ -19822,29 +19819,31 @@ }, { "id": "bug-1727", - "timestamp": "2026-08-28T10:25:14Z", + "timestamp": "2026-08-30T22:00:00Z", "error_message": "User-reported (live REPL, real cluster-captured replay /tmp/scheduler-replay-20260828-085356.replay, 40 sessions, 60 jobs): after `xce_scheduler -i -s ` + `step`, `info worker all` shows `resource slots: value=44.00 used=22.00` for worker pc13v, but the worker's real installed capacity is 22 slots (confirmed by the same worker's own `resource maxcpus: value=22.00` line) and all 22 running jobs are 1-slot-each, so the correct display is `value=22.00 used=22.00` (fully packed, 0 free) -- `used=22.00` is correct, `value=44.00` is double the true installed capacity.", "file": "src/scheduler/src/repl_info.c (repl_info_worker_one, ~line 281-390)", - "root_cause": "NOT FIXED -- recorded for future investigation, but well-narrowed: repl_info_worker_one()'s own header comment (repl_info.c:281-291) asserts w->resvals holds 'currently-AVAILABLE' capacity that shrinks as jobs are charged, and that 'value=' should be printed as avail+inUse ('a conservation invariant this codebase's own resource accounting already relies on'), implemented at repl_info.c:376-390's Value_u_fvalue branch: `avail_v->u.fvalue + used` printed as value=. Traced the actual charge path (sched_account_jobs -> sched_charge_account, resource.c:586 -> sched_update_account, resource.c:559-583 -> sched_update_res_accounts, resource.c:401-470) and confirmed it ONLY ever writes to w->resInUse (`sched_update_res_accounts(core, &(w->resInUse), 0, haccount->naccount, haccount->accounts, charge)`, resource.c:580-581) -- it never touches w->resvals. Exhaustively grepped every `zarray_put(&(w->resvals), ...)`/`zarray_put(&(worker->resvals), ...)` call site in the scheduler (core_events.c:500, core_events.c:848, snapshot_load.c:333, schedobj.c:311): all four are WORKERS_PUSH / worker-update / snapshot-restore INGESTION paths only -- i.e. w->resvals is populated purely from what the worker daemon self-reports (its own configured/installed capacity, e.g. 'slots: 22'), and is architecturally NEVER decremented when a job is dispatched or charged. So for a live worker's CONSUMABLE resource like 'slots', w->resvals already IS the total installed capacity (not a live 'remaining free' counter), making repl_info.c's own documented 'avail+used = value, a conservation invariant' assumption appear to be FALSE in practice -- the comment's claimed invariant does not match how w->resvals is actually populated for this resource type. This makes `value = avail + used` double-count: true installed capacity (22) gets added to itself once resInUse also reads 22, yielding 44. CONFIRMED PRE-EXISTING, NOT caused by today's scheduler-snapshot-job-allocation task 4.6 fix (the sched_account_jobs()-at-load-time change earlier this session): this exact 44/22 pattern already appeared in the user's ORIGINAL first-ever paste this session, produced via the normal `step` -> sched_account_jobs() path (not the load-time path) -- task 4.6 only changed WHEN the display first goes wrong (now visible immediately at load, previously only after the first step/session, since sched_account_jobs() previously never ran until then). Two competing hypotheses for the real fix, not yet distinguished: (a) repl_info.c's display formula is simply wrong for how resvals is actually populated -- should print avail_v directly as value= (already the total) with used= from resInUse, no addition; or (b) w->resvals was INTENDED to be a live 'remaining free' counter (matching the comment's claimed invariant) and something is missing a `w->resvals -= charged_amount` step at dispatch/charge time that was never implemented -- but no evidence of (b) was found anywhere in resource.c's charge/uncharge functions, so (a) is the better-supported hypothesis pending closer investigation of what a live worker daemon (xcecd) actually reports for a 'slots' resval on each heartbeat (constant install size vs. something already load-adjusted).", - "fix": "NOT FIXED -- user asked to record this for future investigation only, no code change made. Likely fix direction (per root_cause hypothesis (a), needs confirming first): repl_info_worker_one()'s Value_u_fvalue branch (repl_info.c ~376-390) should print `avail_v->u.fvalue` directly as value= (not avail+used) for a CONSUMABLE resource, same as the non-CONSUMABLE branch already does -- verify against repl_info_resource_one()'s cluster-wide CONSUMABLE case (mentioned in the same comment as sharing 'an identical gate') to see if it has the same double-count bug or got this right, before changing anything. Also worth checking test_repl_breakpoints_inspection.c / any existing `info worker`-covering test for a hardcoded expectation that already bakes in the avail+used formula (would need updating alongside any fix, same pattern as this session's earlier test_sim_contention_parity.c/test_sim_session_ordering.c hardcoded-index fixes for task 4.6).", + "root_cause": "NOT FIXED -- recorded for future investigation, but well-narrowed: repl_info_worker_one()'s own header comment (repl_info.c:281-291) asserts w->resvals holds 'currently-AVAILABLE' capacity that shrinks as jobs are charged, and that 'value=' should be printed as avail+inUse ('a conservation invariant this codebase's own resource accounting already relies on'), implemented at repl_info.c:376-390's Value_u_fvalue branch: `avail_v->u.fvalue + used` printed as value=. Traced the actual charge path (sched_account_jobs -> sched_charge_account, resource.c:586 -> sched_update_account, resource.c:559-583 -> sched_update_res_accounts, resource.c:401-470) and confirmed it ONLY ever writes to w->resInUse (`sched_update_res_accounts(core, &(w->resInUse), 0, haccount->naccount, haccount->accounts, charge)`, resource.c:580-581) -- it never touches w->resvals. Exhaustively grepped every `zarray_put(&(w->resvals), ...)`/`zarray_put(&(worker->resvals), ...)` call site in the scheduler (core_events.c:500, core_events.c:848, snapshot_load.c:333, schedobj.c:311): all four are WORKERS_PUSH / worker-update / snapshot-restore INGESTION paths only -- i.e. w->resvals is populated purely from what the worker daemon self-reports (its own configured/installed capacity, e.g. 'slots: 22'), and is architecturally NEVER decremented when a job is dispatched or charged. So for a live worker's CONSUMABLE resource like 'slots', w->resvals already IS the total installed capacity (not a live 'remaining free' counter), making repl_info.c's own documented 'avail+used = value, a conservation invariant' assumption appear to be FALSE in practice -- the comment's claimed invariant does not match how w->resvals is actually populated for this resource type. This makes `value = avail + used` double-count: true installed capacity (22) gets added to itself once resInUse also reads 22, yielding 44. CONFIRMED PRE-EXISTING, NOT caused by today's scheduler-snapshot-job-allocation task 4.6 fix (the sched_account_jobs()-at-load-time change earlier this session): this exact 44/22 pattern already appeared in the user's ORIGINAL first-ever paste this session, produced via the normal `step` -> sched_account_jobs() path (not the load-time path) -- task 4.6 only changed WHEN the display first goes wrong (now visible immediately at load, previously only after the first step/session, since sched_account_jobs() previously never ran until then). Two competing hypotheses for the real fix, not yet distinguished: (a) repl_info.c's display formula is simply wrong for how resvals is actually populated -- should print avail_v directly as value= (already the total) with used= from resInUse, no addition; or (b) w->resvals was INTENDED to be a live 'remaining free' counter (matching the comment's claimed invariant) and something is missing a `w->resvals -= charged_amount` step at dispatch/charge time that was never implemented -- but no evidence of (b) was found anywhere in resource.c's charge/uncharge functions, so (a) is the better-supported hypothesis pending closer investigation of what a live worker daemon (xcecd) actually reports for a 'slots' resval on each heartbeat (constant install size vs. something already load-adjusted).\n\n--- CONFIRMED + FIXED 2026-08-30 (scheduler-framework session, user's live Symptom 2 report) ---\n\nHypothesis (a) from the prior investigation is CONFIRMED correct, and hypothesis (b) is definitively ruled out. Live-reproduced end to end: built a fresh scheduler+controller+worker (schema change for a separate bug bundled in the same build, unrelated to this fix), deployed a real 3-node HA cluster + xcecd_virtual worker (22 real cores, matching the user's original pc13v report), submitted a 50-element array job (`sleep 60 && hostname`, overlapping runtime) against the 22-slot worker, captured a scheduler recording mid-run (`step 100`, 19 jobs genuinely RUN), and inspected `info worker worker-1` on the UNPATCHED binary first: `resource slots: value=41.00 used=19.00` -- NOT even a clean 2x (44), because avail_v (=22, the worker's real installed capacity, confirmed never decremented -- grepped every zarray_put(&w->resvals,...) call site: all four (core_events.c:500/848, snapshot_load.c:333, schedobj.c:311) are WORKERS_PUSH/RESVALS_DELTA/snapshot-restore INGESTION only) plus used_v (=19, however many jobs happen to be running at inspection time) are ADDED together by repl_info_worker_one()'s own display formula -- so the displayed 'value' grows in lockstep with 'used' as more jobs run, not a fixed doubling. The ORIGINAL user report's exact 22+22=44 was simply the specific case of a fully-packed worker (used == the worker's own real capacity), which is why it read as a clean 2x. Cross-checked against the actual admission-control formula that this exact w->resvals field feeds -- resource.c's unsatisfy_(): `total[i] < inuse[i] + uncomitted[i] + wanted[i]` -- which treats get_resvals(&w->resvals,...) as `total` directly, already inclusive of whatever is `inuse`. This is airtight proof w->resvals[idx] is the STATIC TOTAL, not a live 'remaining available' counter that would need `used` added back to reconstruct the total (hypothesis (b), now ruled out -- no such 'w->resvals -= charged_amount' step exists anywhere, and none should, since the admission check already subtracts inuse separately). The real scheduling/admission decisions are UNAFFECTED by this bug -- they read w->resvals and w->resInUse directly, not through this display formula -- so job placement correctness was never at risk; this is a pure `info worker`/`info resource` REPL display defect. IMPORTANT DISAMBIGUATION: this display bug is entirely SEPARATE from Symptom 1 (phantom RUN jobs exceeding real worker capacity, logged as bug-1739) -- that symptom is a genuine allocation-bookkeeping gap in bug-1734's JOBS_PUSH resync-merge path, unrelated to this printf-time double-count.\n\nRebuilt with the SAME binary against the SAME live-captured replay file: `resource slots: value=22.00 used=19.00` -- matches `resource maxcpus: value=22.00` exactly, confirming the fix.", + "fix": "FIXED (2026-08-30). src/scheduler/src/repl_info.c: repl_info_worker_one()'s per-worker CONSUMABLE-resource branch and repl_info_resource_one()'s identical GLOBAL/SHARED-resource branch both changed from printing `avail + used` as `value=` to printing `avail` alone (used= is unchanged, still read from w->resInUse / core->sharedInUse) -- avail_v already IS the total capacity, so adding `used` on top double-counted it. Corrected the header comment above repl_info_worker_one() (previously asserted a false 'avail+used is a conservation invariant' claim) to document the real semantics, with a citation to resource.c's unsatisfy_() as the proof. TDD: updated the 2 existing tests that had baked in the wrong expected value (test_repl_breakpoints_inspection.c: test_info_worker_reports_consumable_value_and_used, expected string changed from 'value=7.00 used=2.00' to 'value=5.00 used=2.00' for avail=5/used=2; test_info_resource_reports_consumable_value_and_used, 'value=11.00 used=3.00' to 'value=8.00 used=3.00' for avail=8/used=3) -- both now correctly assert the raw total, not the double-counted sum. The two tests in test_sim_e2e_original_motivation.c asserting 'value=32.00 used=0.00' / 'value=15.00 used=0.00' needed no change (used=0 makes the old and new formulas identical). Full scheduler + controller suite: 61/61 Ok after the fix, zero regressions. Live re-verified against the real captured replay: value now matches maxcpus exactly at every inspection point (mid-run and post-completion).", "tags": [ - "scheduler", - "repl", + "confirmed-live", "display-bug", - "resource-accounting", - "resInUse", - "resvals", - "unfixed", + "fixed", "found-live", + "not-caused-by-task-4.6", "pre-existing", - "not-caused-by-task-4.6" + "repl", + "resInUse", + "resource-accounting", + "resvals", + "scheduler", + "unfixed" ], "related_bugs": [ "bug-1568", "bug-1590" ], - "occurrences": 1, - "last_seen": "2026-08-28T10:25:14Z" + "occurrences": 2, + "last_seen": "2026-08-30T22:00:00Z" }, { "id": "bug-1728", @@ -20092,6 +20091,79 @@ ], "occurrences": 1, "last_seen": "2026-08-30T08:35:00" + }, + { + "id": "bug-1737", + "timestamp": "2026-08-30T22:05:00Z", + "error_message": "User-reported (live 3-node HA cluster + worker, 50-element array job `sleep 100 && hostname`, xce_scheduler -i -s vs controller joblist): job 0-8-1788143749-0[38] shows EXIT in the scheduler's replay (`info jobs`) but DONE in the controller's joblist -- confirmed a REAL state divergence (JOB_STAT_EXIT=0x04 and JOB_STAT_DONE=0x08 are genuinely different bits, src/include/xce/types.h), not cosmetic.", + "file": "src/controller/sched.c (sched_job_exit_fun, renamed sched_job_finish_fun), src/scheduler/src/handler.c (sched_handle_notify's NotifyData_data_schedExitJob case), src/schema/controller.capnp (schedExitJob field), src/include/typemap.h (xce_notify_data_t's sched_exit_job union member), src/lib/helper.c (xce_notify_data_ptr)", + "root_cause": "CONFIRMED via direct code reading (both static and, indirectly, live -- the fixed behavior was verified against a real captured replay; the pre-fix defect itself was not separately re-reproduced live in this session since fixing it was done in the same pass). HOOK_DETAIL_JOB_EXIT fires for EVERY job finish, both success and failure -- job.c's record_job_finish_fact()/apply_job_finish_transition() decide DONE (exit_code==0) vs EXIT (exit_code!=0) BEFORE firing this exact hook detail either way (mirrors persist.c's own WAL_JOB_FINISH -> HOOK_DETAIL_JOB_EXIT mapping, `case HOOK_DETAIL_JOB_EXIT: return WAL_JOB_FINISH;`). sched.c's sched_job_exit_fun() (the HOOK_DETAIL_JOB_EXIT subscriber that notifies the scheduler) receives xce_jobfinish_t* info (which HAS an exit_code field) but never read it -- it unconditionally sent a bare jobid via NotifyData_data_schedExitJob (controller.capnp's schedExitJob was a plain UInt64, no exit_code at all on the wire). scheduler/src/handler.c's sched_handle_notify() then unconditionally mapped ANY schedExitJob to JOB_STAT_EXIT, with no way to ever land on JOB_STAT_DONE via this live path. Under STABLE connectivity this was normally self-correcting: the SAME WAL apply also fires HOOK_DETAIL_JOB_UPDATE moments later (persist.c:4854-4855, immediately after the HOOK_DETAIL_JOB_EXIT fire, same lock scope), which carries the job's REAL, already-final job->job.state via schedUpdateJob -> XCE_CORE_EVENT_JOB_UPDATE's `job->state = updated->state;` (core_events.c), overwriting the wrongly-forced EXIT with the correct DONE within the same notify batch. But this is TWO SEPARATE notify() calls, not atomic -- if the scheduler's connection blipped between them (the same reconnect-flakiness bug-1731/bug-1734 already documented live under this exact 50-element-array load), the correcting schedUpdateJob could be dropped (c->sched.ep NULL at fire time) while the earlier, wrong schedExitJob(EXIT) had already landed -- leaving the scheduler permanently stuck at EXIT for a job the controller correctly recorded as DONE. This exactly explains why only ONE array element (out of 50) showed the divergence: only that job's particular pair of notifies happened to straddle a reconnect gap.", + "fix": "FIXED (2026-08-30). Reused the EXISTING JobFinishInfo wire shape (jobid + code) apiserver_job_exit_fun() (apiserver.c) already sends for this identical hook, rather than inventing a new capnp struct: controller.capnp's schedExitJob field changed from `UInt64` to `JobFinishInfo`; typemap.h's xce_notify_data_t.sched_exit_job union member changed from `uint64_t` to `xce_jobfinish_t*`; sched.c's sched_job_exit_fun() (renamed sched_job_finish_fun() for accuracy -- it covers both DONE and EXIT outcomes, not just EXIT) now sends `.sched_exit_job = info` (the whole struct, mirroring apiserver_job_exit_fun's `.finishinfo = info` pattern) instead of `info->jobid`; scheduler/src/handler.c's sched_handle_notify() now reads finish->exit_code and mirrors job.c's own decision exactly: exit_code==0 -> JOB_STAT_DONE, else -> JOB_STAT_EXIT, instead of unconditionally assuming EXIT. helper.c's xce_notify_data_ptr() updated to match the new pointer type (dropped a now-redundant void* cast). TDD: added test_handle_notify_job_exit_maps_exit_code_to_done_or_exit (test_handlers.c) -- exit_code==0 -> DONE, exit_code!=0 -> EXIT, NULL payload -> -EINVAL (no crash). Full lib+controller+scheduler+worker build and test suite (both a dedicated full build via xce-build.sh and an incremental rebuild+retest after further edits): 61/61 Ok for controller+scheduler (66/67 overall including lib, the 1 failure a pre-existing unrelated ASAN-leak fixture bug already logged separately, not caused by this diff), xceadmin 288/288. Live-verified: deployed a fresh 3-node HA cluster + worker with the fixed binaries, submitted a 51-job workload (50-element array + 1 standalone job, all exiting 0), let everything run to completion -- the scheduler's replay showed DONE for every single job, matching the controller's joblist exactly, with zero EXIT/DONE divergence.", + "tags": [ + "scheduler", + "controller", + "wal", + "notify", + "capnp", + "job-state", + "exit-code", + "done-vs-exit", + "fixed", + "confirmed-live" + ], + "related_bugs": [ + "bug-1731", + "bug-1734", + "bug-1738" + ], + "occurrences": 1, + "last_seen": "2026-08-30T22:05:00Z" + }, + { + "id": "bug-1738", + "timestamp": "2026-08-30T22:10:00Z", + "error_message": "Found investigating Symptom 4 (EXIT vs DONE divergence) alongside bug-1737: a SEPARATE, genuinely different mechanism that can ALSO clobber a correct terminal job state on the scheduler side, independent of the schedExitJob exit_code gap. Not separately live-reproduced this session (no post_exec-stage job failure was exercised against the live cluster) -- confirmed by direct code reading with an exact, unambiguous mechanism.", + "file": "src/scheduler/src/core_events.c (XCE_CORE_EVENT_JOB_STATE_CHANGE case, and the JOBS_PUSH duplicate-jobid merge bug-1734 added), src/controller/sched.c (sched_job_fail_fun, comment only)", + "root_cause": "CONFIRMED via direct code reading. HOOK_DETAIL_JOB_FAIL is a narrower event than HOOK_DETAIL_JOB_EXIT/finish -- job.c's apply_job_fail_transition() only forces JOB_STAT_EXIT for a genuinely pre-exit failure (the `default:` case, no prior exit info exists yet); for JOB_EXEC_STAGE_POST_EXEC/Q_POST_EXEC (a post-exec script failing on an otherwise-already-decided job) it MERGES a JOB_STAT_PERR flag onto whatever DONE/EXIT the job's own finish already decided -- it never re-decides DONE vs EXIT after the fact. But sched.c's sched_job_fail_fun() (the HOOK_DETAIL_JOB_FAIL subscriber) always sends the SAME bare-jobid schedFailJob notify regardless of which case applied, and scheduler/src/handler.c's sched_handle_notify() unconditionally maps THAT to JOB_STAT_EXIT via XCE_CORE_EVENT_JOB_STATE_CHANGE, which (before this fix) had NO guard against overwriting an already-terminal state: `job->state = new_state;` unconditionally. Net effect: a job that finished successfully (DONE, correctly notified live) and then has an UNRELATED post-exec script fail afterward would have the scheduler's view of it forcibly clobbered from DONE back to EXIT -- a real, distinct correctness bug from bug-1737's exit_code gap. SEPARATELY, this session's own bug-1734 fix (landed earlier the same session, src/scheduler/src/core_events.c, XCE_CORE_EVENT_JOBS_PUSH's duplicate-jobid merge path) has the IDENTICAL class of gap: on a resync redelivery carrying a DIFFERENT state than the existing tracked job, it merged `existing->state = job->state` unconditionally with no ordering/terminal-permanence check -- a stale or out-of-order resync redelivery claiming EXIT for a job already correctly DONE would silently regress it. Both gaps share one missing invariant: once a job reaches a terminal state (DONE or EXIT) on the scheduler's own tracked copy, that state must be PERMANENT -- mirroring the controller's own job_state_is_terminal() doctrine (job.c: apply_job_finish_transition() no-ops a duplicate FINISH once terminal) -- and no single-job notify or resync redelivery should ever be able to change it to something DIFFERENT.", + "fix": "FIXED (2026-08-30). Added one shared static helper, job_state_regresses_terminal(current_state, new_state) (core_events.c, just above xce_core_push_events()): true iff current_state is already DONE or EXIT AND new_state is different. Applied it at BOTH vulnerable call sites: (1) XCE_CORE_EVENT_JOB_STATE_CHANGE's case -- rejects (WARN-logged, no-op) a new_state that would regress an already-terminal job, before the existing accounts/allocs-cleanup + state-assignment logic runs; (2) the JOBS_PUSH duplicate-jobid merge path (bug-1734) -- same guard, applied before deciding how to merge. Also added a clarifying comment to sched.c's sched_job_fail_fun() documenting the POST_EXEC-vs-default distinction and why this core-side guard (not a sched.c-side fix) is the right place to close the gap, since the scheduler has no JOB_STAT_PERR-equivalent concept of its own to merge instead -- 'never regress a terminal state' is simpler and sufficient. TDD: added test_job_state_change_does_not_regress_terminal_state (drives a job to DONE via JOB_STATE_CHANGE, then a second JOB_STATE_CHANGE claiming EXIT must be ignored) and test_jobs_push_duplicate_jobid_does_not_regress_terminal_state (same invariant via the JOBS_PUSH merge path) in test_core_events.c. Full scheduler+controller suite: 61/61 Ok, zero regressions -- the pre-existing bug-1734 test (PEND -> DONE merge, a legitimate forward transition) still passes unchanged, confirming the new guard only blocks a REGRESSION (terminal -> different), not a legitimate non-terminal -> terminal merge.", + "tags": [ + "scheduler", + "job-state", + "terminal-state", + "job-fail", + "regression-guard", + "fixed" + ], + "related_bugs": [ + "bug-1734", + "bug-1737", + "bug-1739" + ], + "occurrences": 1, + "last_seen": "2026-08-30T22:10:00Z" + }, + { + "id": "bug-1739", + "timestamp": "2026-08-30T22:15:00Z", + "error_message": "User-reported (live 3-node HA cluster + worker, 50-element array job): `info summary` showed 30 elements of an array marked RUN in `info jobs`, but `info worker pc13v` only listed 22 'assigned job:' lines (matching the worker's real 22-core capacity) -- 8 elements showed job-level state RUN with NO corresponding worker/slot-assignment record at all, a 'phantom RUN' exceeding real hardware capacity.", + "file": "src/scheduler/src/core_events.c (XCE_CORE_EVENT_JOBS_PUSH duplicate-jobid merge path)", + "root_cause": "CONFIRMED via direct code reading (this exact mechanism was identified and fixed before a dedicated live reproduction of the PRE-fix phantom-RUN state was attempted; the FIX itself was verified live -- a real 50-element array job run against the fixed binary showed zero phantom RUN jobs at any inspection point). This session's own bug-1734 fix (landed earlier the same session) added a merge for XCE_CORE_EVENT_JOBS_PUSH's duplicate-jobid (EEXIST) case: on a resync redelivery carrying a DIFFERENT state than the existing tracked job, if the new state was RUN, it set `existing->state = job->state` (RUN) directly -- but did NOT transfer any allocation data. core_build_job() (this same file, called earlier in the SAME event to construct the redelivered `job` clone from the wire xce_job_t) already adopts the wire payload's `allocs` field into a fresh xce_sched_job_t exactly the same way a brand-new RUN job's JOBS_PUSH would (`job->accounts = make_job_account(job->allocs)` when `j->allocs != NULL`) -- i.e. the redelivered clone DOES carry real allocation data when the controller's resync wire payload includes it (xcesched_push_jobs(), sched.c, collects the controller's live job_t structs directly, whose ->job.allocs is the real dispatch record for a running job). But bug-1734's merge branch discarded this clone entirely (FREEUP(job) at the end of the EEXIST handler, with allocs/accounts explicitly left out of scope in that fix's own comment) without ever copying job->allocs/job->accounts onto `existing` -- leaving `existing->state == RUN` with `existing->allocs == NULL`: a job the scheduler's own resource/slot bookkeeping (`info worker`'s 'assigned job:' scan, which walks core->jobs' allocations) has no record of at all, exactly the reported phenotype.", + "fix": "FIXED (2026-08-30), same edit pass as bug-1738's core_events.c guard (both touch the same JOBS_PUSH EEXIST branch). When the merge's terminal-permanence guard (bug-1738) allows the merge to proceed and the redelivered state is RUN: if the redelivered clone carries real allocation data (job->accounts != NULL && job->allocs != NULL), TRANSFER it onto `existing` (free whatever stale accounts/allocs `existing` had, then move the pointers over -- `existing->accounts = job->accounts; existing->allocs = job->allocs; job->accounts = NULL; job->allocs = NULL;` so the later FREEUP(job) doesn't double-free them) instead of leaving them untouched/discarded. If the redelivery claims RUN but carries NO allocation data (a defensive case -- an older/degraded controller payload, or a race where the dispatch record wasn't attached yet), the merge into RUN is REFUSED (WARN-logged, existing state kept unchanged) rather than manufacturing a phantom RUN from a different cause. TDD: added test_jobs_push_duplicate_jobid_run_state_transfers_allocation (RUN + real allocs -> existing->state==RUN AND existing->allocs/accounts non-NULL, transferred not discarded) and test_jobs_push_duplicate_jobid_run_state_without_allocation_is_refused (RUN + no allocs -> existing stays at its prior safe state) in test_core_events.c. Full scheduler+controller suite: 61/61 Ok, zero regressions -- bug-1734's own original test (PEND -> DONE merge, no allocation involved) still passes unchanged. LIVE RE-VERIFICATION: rebuilt, redeployed a fresh 3-node HA cluster + 22-core worker, submitted a 50-element overlapping-runtime array job (sleep 60 && hostname) plus one standalone job against the 22-slot capacity, captured a mid-run scheduler recording (19 jobs genuinely RUN, matching the worker's real capacity minus a few still-queued elements) and inspected `info worker`/`info jobs`: RUN-state job count matched 'assigned job:' count exactly at every inspection point (23 assigned = 19 RUN + 4 jobs with an in-flight allocation reservation not yet finalized to RUN, a benign timing artifact of catching mid-dispatch state, not a phantom RUN) -- no job ever showed RUN with a missing worker assignment. Could not force the SAME reconnect-storm conditions that originally exposed bug-1734's gap (this deployment's controller/scheduler connection stayed stable throughout), so the EEXIST/resync branch itself was exercised only via the unit tests above, not a live resync redelivery -- high confidence from code + unit tests, not a live end-to-end repro of the exact original trigger.", + "tags": [ + "scheduler", + "job-state", + "phantom-run", + "allocation", + "resync", + "fixed" + ], + "related_bugs": [ + "bug-1734", + "bug-1738", + "bug-1737" + ], + "occurrences": 1, + "last_seen": "2026-08-30T22:15:00Z" } ] } diff --git a/.wolf/memory.md b/.wolf/memory.md index d9795860..27327338 100644 --- a/.wolf/memory.md +++ b/.wolf/memory.md @@ -3213,3 +3213,30 @@ | 08:46 | Edited src/controller/testsuite/test_p2_integration.c | 5→9 lines | ~108 | | 08:46 | Edited src/controller/testsuite/test_p2_integration.c | 4→8 lines | ~88 | | 08:51 | Edited src/scheduler/src/core_events.c | modified 1734() | ~242 | +| 20:14 | Edited src/scheduler/src/core_events.c | modified job_state_regresses_terminal() | ~459 | +| 20:15 | Edited src/scheduler/src/core_events.c | 5→6 lines | ~30 | +| 20:16 | Edited src/scheduler/src/core_events.c | added 1 condition(s) | ~651 | +| 20:16 | Edited src/scheduler/src/core_events.c | added 5 condition(s) | ~1624 | +| 20:17 | Edited src/controller/sched.c | modified previously() | ~605 | +| 20:17 | Edited src/controller/sched.c | sched_job_exit_fun() → sched_job_finish_fun() | ~26 | +| 20:18 | Edited src/controller/sched.c | modified still() | ~315 | +| 20:18 | Edited src/schema/controller.capnp | expanded (+6 lines) | ~169 | +| 20:18 | Edited src/include/typemap.h | 3→5 lines | ~70 | +| 20:18 | Edited src/lib/helper.c | 2→4 lines | ~55 | +| 20:19 | Edited src/scheduler/src/handler.c | added 1 condition(s) | ~315 | +| 20:19 | Edited src/scheduler/testsuite/test_handlers.c | modified test_handle_notify_job_exit_maps_exit_code_to_done_or_exit() | ~479 | +| 20:19 | Edited src/scheduler/testsuite/test_handlers.c | 2→3 lines | ~46 | +| 20:21 | Edited src/scheduler/testsuite/test_core_events.c | modified 1739() | ~2454 | +| 20:22 | Edited src/scheduler/testsuite/test_core_events.c | 1→5 lines | ~105 | +| 20:40 | Edited .kiro/specs/scheduler-dispatch-commit/tasks.md | inline fix | ~27 | +| 20:41 | Edited .kiro/specs/scheduler-dispatch-commit/tasks.md | inline fix | ~23 | +| 20:41 | Edited .kiro/specs/scheduler-dispatch-commit/tasks.md | inline fix | ~34 | +| 20:41 | Edited .kiro/specs/scheduler-dispatch-commit/tasks.md | inline fix | ~21 | +| 20:41 | Edited .kiro/specs/scheduler-dispatch-commit/tasks.md | inline fix | ~15 | +| 20:49 | Edited src/scheduler/src/repl_info.c | modified unsatisfy_() | ~526 | +| 20:51 | Edited src/scheduler/src/repl_info.c | expanded (+7 lines) | ~259 | +| 20:53 | Edited src/scheduler/src/repl_info.c | modified 1740() | ~626 | +| 20:53 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | modified requirement() | ~190 | +| 20:53 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | 6→6 lines | ~79 | +| 20:53 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | modified requirement() | ~127 | +| 20:54 | Edited src/scheduler/testsuite/test_repl_breakpoints_inspection.c | 6→7 lines | ~87 |