diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 2bbac867..ed8bc922 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -16169,9 +16169,9 @@ }, { "id": "bug-1880", - "status": "investigating", - "status_updated": "2026-09-28", - "status_note": "not reproduced yet: needs the snapshot before 06:50:11; message hides the diff (bug-1881)", + "status": "fixed", + "status_updated": "2026-10-02", + "status_note": "", "component": "scheduler", "severity": "wrong-result", "timestamp": "2026-09-28T07:26:08Z", @@ -16179,8 +16179,8 @@ "occurrences": 1, "error_message": "sim-verify flags every DISPATCH of array job 0-12-1790578108-0 as MISMATCH in a pc13v replay\n\n**Observed:**\n```\n[2026-09-28 06:50:11,909] [93231] [ ERROR] [ sim_log_mismatch] sim_log_mismatch decision verification MISMATCH at begin_round=1790578211909717418 decision_index=0 expected_ts=1790578211910119659 -- expected: DISPATCH jobid=0-12-1790578108-0[7] nhosts=1 -- actual: DISPATCH jobid=0-12-1790578108-0[7] nhosts=1\n... (one per dispatch, elements [7]..[49], through 07:00:21)\n```\n**Expected:** the simulator reproduces the recorded dispatches exactly, as for the other jobs in the capture.\n**Impact:** sim-verify reports every dispatch of this array job as divergent, so the replay cannot be used to check scheduler parity; either the simulator allocates differently from the live scheduler (a real parity bug) or the verifier compares a field that legitimately differs.\n**Found by:** user replaying a pc13v capture with sim-verify, 2026-09-28", "file": "src/scheduler/src/sim_verify.c", - "root_cause": "Unconfirmed: the printed fields (kind, jobid, nhosts) are equal, so the difference is in what sim_decision_eq() (src/scheduler/src/sim_verify.c) compares beyond them -- per host, the allocation's resname, value, duration and reserve (sim_verify_alloc_eq/host_alloc_eq/job_alloc_eq). bug-1881 makes the message show which.", - "fix": "TODO: required for fixed/partial\n\nVerification:\n- Test: TODO: name + file; RED before the fix, GREEN after\n- Suites: TODO: suite results and build profile\n- Live: TODO: soak/deploy run, or n/a and why", + "root_cause": "The capture's snapshot was written by the pc13v scheduler at 4c134127, before bug-1888's fix: snapshot_wire.c saved each job's resreq as format_resreq()'s human-readable dump (\"Primary:\\n Tasks: min = 3, max = 3\\n Rusages: res mem ...\"), not the text the request was parsed from. On load, the scheduler of that time accepted the dump as a primary request with neither select nor rusage, so the simulator allocated this array (3 tasks, rusage[mem]) differently from the live scheduler -- same kind/jobid/nhosts, different per-host allocations: the original report. With today's loader the dump does not parse and bug-1897's guard leaves the job unscheduled, so the same capture now shows \"no live decision\" instead. Only jobs present in the snapshot are affected; jobs submitted after it arrive as events with their real resreq text.", + "fix": "077b1213 (bug-1888, 2026-09-29): snapshots save the job's resreq text (`job->resreq_str`), so the loader rebuilds the same request. No further change: a capture written before 077b1213 cannot be repaired after the fact (its snapshot does not hold the request text) and has to be recorded again with a fixed scheduler.\n\nVerification:\n- Test: `test_snapshot_save_load.c` resreq round trip (added by 077b1213); the old capture as control: 4848 MISMATCH and 50 parse failures with the current binary\n- Suites: scheduler meson suite green at 077b1213 and on the current branch (asan, src/build.jai)\n- Live: 2026-10-01, xce-deploy-ha + xcecli, scheduler started with --record-dir, `xceadmin scheduler record start` while a 20-element array (`-n 3,3 -R 'rusage[mem=400]'`) had 15 elements PEND and 5 RUN (so the jobs are in the snapshot), recording stopped after more dispatches; `xce_scheduler -vvv -s --sim-verify`: 402 simulated decisions, 0 MISMATCH, 0 parse_resreq failures (7956-line log; every simulated decision is compared with the recorded one at the same position and leftovers are reported). A second capture with the jobs submitted after the snapshot: 311 decisions, 0 MISMATCH. Captures: /home/claude/tmp/bug-1880/", "tags": [ "scheduler", "sim", @@ -16193,7 +16193,9 @@ "bug-1844", "bug-1845" ], - "fix_commits": [], + "fix_commits": [ + "077b1213" + ], "record": ".wolf/bugs/bug-1880.md", "gitea_issue": 331, "gitea_synced_status": "investigating" diff --git a/.wolf/bugs/bug-1880.md b/.wolf/bugs/bug-1880.md index 4d187e24..e112dd70 100644 --- a/.wolf/bugs/bug-1880.md +++ b/.wolf/bugs/bug-1880.md @@ -1,8 +1,8 @@ --- id: "bug-1880" -status: "investigating" -status_updated: "2026-09-28" -status_note: "not reproduced yet: needs the snapshot before 06:50:11; message hides the diff (bug-1881)" +status: "fixed" +status_updated: "2026-10-02" +status_note: "" component: "scheduler" severity: "wrong-result" timestamp: "2026-09-28T07:26:08Z" @@ -11,6 +11,7 @@ occurrences: 1 files: ["src/scheduler/src/sim_verify.c"] tags: ["scheduler", "sim", "sim-verify", "replay", "array-job"] related: ["bug-1842", "bug-1844", "bug-1845"] +fix_commits: ["077b1213"] gitea_issue: 331 gitea_synced_status: "investigating" gitea_synced_hash: "9e880f7580eb" @@ -37,20 +38,21 @@ gitea_synced_hash: "9e880f7580eb" - Deployment: pc13v: xce_scheduler in simulation mode (pid 93231) replaying a capture of the live pc13v cluster's scheduler (scheduler-replay-20260928-064842.replay, captured from 06:48:42); exact command line and --sim-start-ts not recorded ## Reproduction -1. `xce_scheduler -s data/scheduler-replay-20260928-064842.replay --sim-verify` starting from a snapshot BEFORE the array job's first dispatch at 06:50:11 (the default start, the replay's most recent snapshot, is after them) -- Frequency: 43/43 dispatches of array job 0-12-1790578108-0 (elements [7]..[49]) in the pc13v run; 0/3 here with the default start (those rounds are never replayed); an arbitrary --sim-start-ts (1790578000000000000) is rejected -- the right snapshot is not known yet -- Evidence: data/scheduler-replay-20260928-064842.replay and data/xce_scheduler.log (ERROR lines only), copied from pc13v 2026-09-28 +1. `xce_scheduler -s data/scheduler-replay-20260928-064842.replay --sim-verify --logfile ` with the default start (the file's only snapshot, taken at capture start 06:48:42, before the array's dispatches -- the earlier note that the default start skips them was wrong). +2. Current code (2026-10-01): the log shows, for every element of 0-12-1790578108-0 at snapshot load, `parse_resreq failed for jobid ...: Primary:\n Tasks: min = 3, max = 3\n Rusages: ...` and `has no scheduling object; it will not be scheduled`, then 4848 `MISMATCH ... expected: PEND|DISPATCH jobid=0-12-1790578108-0[k] ... -- actual: -- diff: no live decision` (4805 PEND, 43 DISPATCH). Mismatches go only to the log file, not the console. +- Frequency: deterministic (2/2 runs, 2026-10-01) +- Evidence: data/scheduler-replay-20260928-064842.replay; /home/claude/tmp/bug-1880/old-capture-parse-failure.txt ## Root cause -Unconfirmed: the printed fields (kind, jobid, nhosts) are equal, so the difference is in what sim_decision_eq() (src/scheduler/src/sim_verify.c) compares beyond them -- per host, the allocation's resname, value, duration and reserve (sim_verify_alloc_eq/host_alloc_eq/job_alloc_eq). bug-1881 makes the message show which. +The capture's snapshot was written by the pc13v scheduler at 4c134127, before bug-1888's fix: snapshot_wire.c saved each job's resreq as format_resreq()'s human-readable dump ("Primary:\n Tasks: min = 3, max = 3\n Rusages: res mem ..."), not the text the request was parsed from. On load, the scheduler of that time accepted the dump as a primary request with neither select nor rusage, so the simulator allocated this array (3 tasks, rusage[mem]) differently from the live scheduler -- same kind/jobid/nhosts, different per-host allocations: the original report. With today's loader the dump does not parse and bug-1897's guard leaves the job unscheduled, so the same capture now shows "no live decision" instead. Only jobs present in the snapshot are affected; jobs submitted after it arrive as events with their real resreq text. ## Fix -TODO: required for fixed/partial +077b1213 (bug-1888, 2026-09-29): snapshots save the job's resreq text (`job->resreq_str`), so the loader rebuilds the same request. No further change: a capture written before 077b1213 cannot be repaired after the fact (its snapshot does not hold the request text) and has to be recorded again with a fixed scheduler. ## Verification -- Test: TODO: name + file; RED before the fix, GREEN after -- Suites: TODO: suite results and build profile -- Live: TODO: soak/deploy run, or n/a and why +- Test: `test_snapshot_save_load.c` resreq round trip (added by 077b1213); the old capture as control: 4848 MISMATCH and 50 parse failures with the current binary +- Suites: scheduler meson suite green at 077b1213 and on the current branch (asan, src/build.jai) +- Live: 2026-10-01, xce-deploy-ha + xcecli, scheduler started with --record-dir, `xceadmin scheduler record start` while a 20-element array (`-n 3,3 -R 'rusage[mem=400]'`) had 15 elements PEND and 5 RUN (so the jobs are in the snapshot), recording stopped after more dispatches; `xce_scheduler -vvv -s --sim-verify`: 402 simulated decisions, 0 MISMATCH, 0 parse_resreq failures (7956-line log; every simulated decision is compared with the recorded one at the same position and leftovers are reported). A second capture with the jobs submitted after the snapshot: 311 decisions, 0 MISMATCH. Captures: /home/claude/tmp/bug-1880/ ## References -- Related: bug-1881 (the message hides the differing field), bug-1842, bug-1844, bug-1845 (earlier --sim-verify false positives) +- Related: bug-1881 (the message hides the differing field), bug-1842, bug-1844, bug-1845 (earlier --sim-verify false positives); bug-1888 (the snapshot writer, the root cause), bug-1897 (the loader guard behind "no live decision")