Rongsong Shen
d26ff8870d
The buglog was one 27K-line JSON file whose fields covered only symptom,
root cause and fix, as free text: 2% of entries named the code version a
bug was found on, 12% the build profile, 36% a way to reproduce, and 58% of
the file was OpenWolf hook auto-detections ("Missing guard clause",
"Function not marked async" on .md files).
- .claude/skills/buglog/bug-record.md: the record standard. Eight
sections (Summary as the title, Description, Environment, Reproduction;
Root cause, Fix, Verification, References once fixed), each with the
content it must contain -- e.g. Environment needs the OS, the libc the
failing binary loads (from its ELF interpreter: glibc 2.42 in the nix
shell vs 2.40 on the host), toolchain, build profile and commit.
- .wolf/bugs/<id>.md: 500 records migrated from buglog.json; every field
verified to round-trip. They carry legacy: true and an explicit "not
recorded" where the old log had no such field; component derived from
file paths, severity from keywords (else unknown), fix_commits from
hashes in status_note/fix that git resolves (91 of 463 fixed).
- .wolf/buglog-archive.json: the 710 hook auto-detections, verbatim.
- .wolf/buglog.json is now an index generated from the records, keeping
the fields OpenWolf's hooks and `openwolf bug search` read.
- scripts/buglog.py rewritten: new (template + Environment collected from
the machine and --binary), check, status (refuses a status the record
doesn't support; fixed needs Root cause, Fix, Verification and
--commit hashes git resolves), note, recur, set, show, list, triage,
env, index. 29 unittest cases in scripts/tests/test_buglog.py.
- scripts/git-hooks/pre-commit runs `check --staged`: incomplete staged
records, a legacy record hand-changed to fixed without the fix-time
sections, a new record claiming legacy: true, or a stale index refuse
the commit.
- scripts/gitea-sync.py reads the records: issue body = the record's
sections plus linked fix commits (origin remote, GITEA_COMMIT_REPO to
override), and a body hash so an issue's text is refreshed when the
record changes.
- bug-1866 rewritten to the full standard as the worked example.
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
53 lines
16 KiB
Markdown
53 lines
16 KiB
Markdown
---
|
|
id: "bug-1734"
|
|
status: "fixed"
|
|
status_updated: "2026-09-24"
|
|
status_note: ""
|
|
component: "scheduler"
|
|
severity: "security"
|
|
timestamp: "2026-08-30T10:15:00Z"
|
|
last_seen: "2026-09-19T09:00:00Z"
|
|
occurrences: 3
|
|
files: ["src/scheduler/src/handler.c (sched_on_job_array's dedup-race", "already documented as a known TOCTOU race by commit 38437e57)", "src/scheduler/src/core_events.c (xce_core_push_events", "WARN log site + the JOBS_PUSH duplicate-discard path from commit 38437e57)", "src/scheduler/src/driver.c / src/controller/sched.c / src/controller/persist.c (the job-update notify pipeline this session's bug-1731/bug-1714 investigations already covers)"]
|
|
tags: ["scheduler", "controller", "job-state-sync", "state-desync", "found-live", "array-job", "root-caused", "reconnect-storm", "notify-drop-on-disconnect", "resync-data-loss", "session-sibling-of-bug-1714", "session-sibling-of-bug-1731", "session-sibling-of-bug-1733", "human-readable-jobid-logging-gap-still-open", "xcecli-failover-under-load-needs-followup"]
|
|
related: ["bug-1714", "bug-1731", "bug-1733"]
|
|
fix_commits: ["38437e57"]
|
|
legacy: true
|
|
---
|
|
|
|
# bug-1734: User-reported live deployment: scheduler's view of a job array's state (`[sim] jobs` /…
|
|
|
|
## Description
|
|
User-reported live deployment: scheduler's view of a job array's state (`[sim] jobs` / xce_scheduler -i -s) diverges sharply from the controller's own joblist for the SAME array, well after every element genuinely finished. Array 0-4-1788084587-0 (50 elements, command `hostname`): controller's `joblist` shows ALL 50 elements as DONE with real, monotonically-increasing StartTime/FinishTime timestamps (1788084587..1788084602) -- the array is genuinely, fully complete. The scheduler's own concurrent view of the identical array shows a scrambled mix: [0-4]=RUN, [5-16]=DONE, [17]=EXIT, [18-19]=DONE, [20]=EXIT, [21]=DONE, [22-24]=EXIT, [25]=DONE, [26-29]=EXIT, [30-46]=RUN, [47-49]=PEND. Two things about this pattern are themselves suspicious, not just 'the scheduler is behind': (a) elements [30-46] show RUN and [47-49] show PEND, i.e. the scheduler believes 20 elements haven't even STARTED yet, even though the controller's timestamps show the whole array finished by 1788084602 -- this is not a small lag, the scheduler's view is drastically behind reality for over a third of the array; (b) EXIT appears interspersed with DONE for a uniform array of a single reliably-successful command (`hostname`, not `/bin/false` or anything failure-prone) -- elements 17/20/22-24/26-29 show EXIT while their immediate neighbors show DONE, which is not what a simple 'scheduler hasn't caught up yet' lag would produce (a lagging-but-otherwise-correct view should show a clean PEND/RUN prefix behind a DONE suffix, not DONE and EXIT interleaved for what should be uniform outcomes). CORRELATED evidence from the SAME run: xce_scheduler's own log shows 10 consecutive WARN lines at the very same timeframe -- `xce_core_push_events JOBS_PUSH: sched_add_job failed for jobid <N> (rc=-17), discarding duplicate/orphaned job` for jobid 4631575359520768000 through 4631575359520768009 -- which decode (JobID bit layout: tag/cluster/apiserver/timestamp/array_idx) to EXACTLY array elements 0-4-1788084587-0[0] through [9] of this SAME array. This WARN is emitted by the bug-1714-adjacent fix landed earlier this session (commit 38437e57, 'fix(scheduler): don't hand an orphaned duplicate job to the picker') -- confirms live, in this exact reproduction, that this array's first 10 elements were pushed to the scheduler TWICE (the TOCTOU dedup race in sched_on_job_array()/handler.c that commit documented as theoretically possible is firing for real here), and the second copy is now being correctly discarded rather than corrupting state or crashing (that part of the fix is working as designed). User also separately requested (logged here as part of the same report, lower priority, not a correctness bug): xce_core_push_events's WARN line above prints the raw numeric jobid (`4631575359520768000`) instead of this project's human-readable fmt_jobid() form (`0-4-1788084587-0[0]`) that every other job-related log line in this codebase uses -- a logging-usability gap in that specific WARN, worth a one-line fix.
|
|
|
|
## Environment
|
|
_Not recorded (migrated from buglog.json)._
|
|
|
|
## Reproduction
|
|
_Not recorded (migrated from buglog.json)._
|
|
|
|
## Root cause
|
|
NOT YET ROOT-CAUSED -- logged for follow-up investigation per user request, not investigated live this session (a separate, still-running background investigation was mid-flight on bug-1714's own stale-reader when this was reported). Working hypothesis, NOT confirmed: this looks like more than one mechanism compounding. (1) The already-known, already-partially-mitigated sched_on_job_array() dedup race (see bug-1714's own root_cause history and commit 38437e57's message) is CONFIRMED firing live here (the WARN evidence decodes to exactly this array's first 10 elements) -- but discarding a genuine duplicate PUSH should be harmless on its own (both copies start from identical fresh JOB_STAT_PEND state; sched_add_job()'s key_add() correctly keeps the first copy), so this alone should not explain elements staying stuck at RUN/PEND when the controller confirms DONE. (2) The DONE/EXIT interleaving for a uniform, reliably-successful command (hostname) suggests either an ordering bug in how terminal-state notifications get applied (an older notification overwriting a newer one, or vice versa, for different elements) -- which would tie into bug-1731's own notify-drop/redelivery investigation and its live-captured evidence of scheduler-endpoint-NULL notify drops -- or a distinct bug in how JOB_STATE_CHANGE vs JOB_UPDATE detail routing interacts for array elements specifically (both hook-detail paths were touched this session by bug-1731's fixes; worth checking whether an array element's terminal notification can race between the two). (3) The ~20 elements the scheduler shows as never having started (RUN/PEND for [30-49]) despite controller-confirmed completion by 1788084602 is the most severe and least explained part of this report -- if genuinely not just a stale UI snapshot, this suggests SOME elements' notifications are being lost entirely, not just delayed, distinct from anything bug-1731's fix addressed (bug-1731 fixed the CONTROLLER never firing the right hook; this could be a SEPARATE loss further downstream, e.g. in delivery to the scheduler, or in how the scheduler's REPL/inspect view is rendered from its own internal state). NOT RULED OUT: this could also be nothing more than a snapshot-timing artifact if `[sim] jobs`/`joblist` were captured at genuinely different moments and the scheduler was still catching up -- but the user's own framing ('still have some issues') and the DONE/EXIT interleaving for a uniform command argue against pure timing lag being the whole explanation. Needs live reproduction with synchronized capture (query both views at the same instant, ideally with sequence numbers/timestamps on the query itself) to distinguish 'genuinely stuck' from 'was mid-catch-up when sampled'.
|
|
|
|
ADDITIONAL CONFIRMATION (same report, user follow-up): xce_test itself (the submitting client) also reports every job in this array finished successfully -- i.e. all three independent vantage points agree the work genuinely completed (worker execution, controller's own joblist/WAL state, and the submitting client's own completion tracking). This rules out worker-side execution failure and controller-side completion-tracking failure as explanations, narrowing this specifically to the scheduler-side notification delivery/application path (or, less likely, the scheduler's own REPL/inspect rendering of otherwise-correct internal state) -- consistent with, but not identical to, bug-1731's already-fixed dead-hook gap and its still-open notify-drop-on-disconnect finding.
|
|
|
|
UPDATE (2026-08-30, later same session, FULLY ROOT-CAUSED via live reproduction): Built controller+scheduler+worker+xceadmin fresh into src/xce.build.bug1734 (asan), deployed a real 3-node HA cluster (localhost:19991-19993) + xcecd_virtual worker + xce_scheduler (-vvv), submitted a 50-element `hostname` array job via xce_test, and captured synchronized evidence: controller `joblist` (ground truth, all 50 DONE with monotonic timestamps) vs the SAME scheduler process's own live session recording (`xceadmin scheduler record start/stop`) replayed via `xce_scheduler -i -s <file>` + `continue` (runs the ENTIRE recorded session set to completion, ruling out lag) + `info jobs`. REPRODUCED EXACTLY: final replayed state showed 23 of 50 elements wrong (3 EXIT, 13 RUN, 7 PEND) despite `continue` reaching 'replay complete' -- confirms GENUINE PERMANENT DESYNC, not lag.
|
|
|
|
Full causal chain (all three links independently confirmed in the SAME live run's logs): (1) The scheduler's own OUTBOUND xcecli connection to the primary controller repeatedly failed over and reconnected under the array's load -- scheduler.log shows `xcecli failover: attempt N -> localhost:1999X` bouncing across all 3 candidates, 8 extra times in an ~8s window (exact trigger for THIS layer not further isolated -- plausibly -vvv DEBUG3 log volume + concurrent WAL/replication load causing a client-side request timeout to fire spuriously; flagged as a follow-up, see below). (2) Every one of those 8 reconnects made ctrl-1.log log `handle_scheduler_join` again, which runs on_scheduler_join() (controller/sched.c) -- a FULL resync (xcesched_push_configs + xcesched_push_workers + xcesched_push_jobs) on every join, no incrementality. xcesched_push_jobs()'s XceData_data_schedjobs wire path re-sends EVERY currently-committed job (not just the array), hitting the scheduler's ordinary (non-array) JOBS_PUSH handling with zero pre-existence filtering. Confirmed live: 700 `sched_add_job failed ... discarding duplicate` WARNs across the session (100 distinct jobids x up to 8 resyncs each), vs only ONE `job array push received and expanded` INFO line -- proving these duplicates come from the ordinary resync path, NOT bug-1714's documented sched_on_job_array() TOCTOU race (that race is real but was a red herring for THIS bug's data-loss mechanism -- it only ever double-submits freshly-PEND array elements, which key_add() correctly and harmlessly rejects, exactly as bug-1714/commit 38437e57 already established). (3) During the gap between disconnect and each reconnect, c->sched.ep is NULL, and any real job-finish notify due in that window is SILENTLY SKIPPED -- ctrl-1.log's pre-existing bug-1731-era DEBUG3 diagnostic `DIAG sched_job_update_fun: jobid=... state=... -- c->sched.ep is NULL, notify SKIPPED` fired 36 times in this run, for jobids matching the array. The very next full resync (link 2) is that job's ONLY remaining chance to reach the scheduler -- but XCE_CORE_EVENT_JOBS_PUSH's handling of an already-tracked jobid (core_events.c) discarded the incoming (correct, newer) job object UNCONDITIONALLY on sched_add_job()->key_add() EEXIST, NEVER updating the existing tracked xce_sched_job_t's state -- so a job whose terminal state only ever reached the scheduler via this resync path was permanently frozen at whatever PEND/RUN state it had before, exactly matching the reported DONE/EXIT-interleaved-with-stuck-RUN/PEND symptom. CONFIDENCE: HIGH -- root cause reproduced live, instrumented with the project's own existing diagnostics (no new printf needed), and closed with a RED->GREEN regression test that fails against the pre-fix code and passes after.
|
|
|
|
NOT FIXED / follow-up (deliberately out of scope for this session, logged for a future bug): WHY the scheduler's own outbound xcecli connection to the primary keeps failing over under load (causal link 1 above) is not isolated to a specific timeout value or code site -- worth its own investigation (possibly a too-aggressive client-side request timeout in the shared xcecli/xce_request layer under DEBUG3 logging + concurrent WAL replication load). Reducing that flapping would reduce how often on_scheduler_join()'s full resync fires at all, but this session's fix (below) makes the resync SAFE regardless of how often it fires, which is the more load-bearing property (a resync will always be needed on genuine scheduler restart/rejoin, not just spurious flapping).
|
|
|
|
## Fix
|
|
FIXED (2026-08-30). Root cause: src/scheduler/src/core_events.c's XCE_CORE_EVENT_JOBS_PUSH case treated sched_add_job()'s -EEXIST (job already tracked) as always a harmless no-op duplicate (per bug-1714/commit 38437e57's Bug A fix) and unconditionally freed the incoming xce_job_t without ever touching the existing tracked job. That assumption held for the array-push redelivery bug-1714 covers (both copies start fresh JOB_STAT_PEND) but not for on_scheduler_join()'s full-resync redelivery (controller/sched.c's xcesched_push_jobs(), fired on every scheduler (re)join), which can legitimately carry a job's CURRENT state -- including a terminal state the scheduler never saw because the matching real-time notify was dropped while c->sched.ep was NULL during the disconnect gap (bug-1731's still-open 'notify SKIPPED' diagnostic). Discarding that redelivery unconditionally silently and PERMANENTLY froze the scheduler's own view of the job at its pre-disconnect state, exactly reproducing this entry's reported controller-vs-scheduler divergence live.
|
|
|
|
FIX (src/scheduler/src/core_events.c, XCE_CORE_EVENT_JOBS_PUSH case): on sched_add_job() EEXIST, look up the existing tracked xce_sched_job_t via sched_get_job() and, if its state differs from the redelivered copy's state, apply the SAME terminal-transition accounts/allocs cleanup XCE_CORE_EVENT_JOB_STATE_CHANGE/JOB_UPDATE already perform, update existing->state in place, and fire picker->picker_iface->on_job_state_change() so the picker's own bookkeeping stays consistent -- instead of silently dropping the newer information. The redelivered xce_job_t clone itself is still freed afterward (it was never registered in core->jobs and never will be) -- only its STATE is salvaged into the object future sched_get_job() lookups actually resolve to. Deliberately scoped to state only (not queue/resreq/other fields) -- documented as an explicit scope decision in the fix's own comment, same convention persistence.md's field-completeness guidance uses elsewhere.
|
|
|
|
TDD: new regression test test_jobs_push_duplicate_jobid_with_newer_state_updates_existing_job (src/scheduler/testsuite/test_core_events.c) -- pushes jobid 56 as JOB_STAT_PEND, then redelivers the SAME jobid via a second JOBS_PUSH batch carrying JOB_STAT_DONE (simulating on_scheduler_join()'s resync racing a dropped terminal notify), asserts sched_get_job() still resolves to the SAME xce_sched_job_t (no orphaned duplicate, no key_add() churn) AND that its state is now JOB_STAT_DONE, not frozen at JOB_STAT_PEND. RED confirmed first (`Expected 8 Was 1` -- JOB_STAT_DONE vs JOB_STAT_PEND); GREEN after the fix. Full scheduler suite: 55/55 passing after the fix, zero regressions (bug-1714's own test_jobs_push_duplicate_jobid_does_not_call_on_job_push_or_leak still passes unchanged -- the two duplicate-handling paths, state-differs vs state-identical, are both exercised and both correct).
|
|
|
|
LIVE RE-VERIFICATION: rebuilt xce_scheduler with the fix, restarted it against the SAME live 3-node cluster (still under the same reconnect-storm conditions -- 700 duplicate-discard WARNs still fired, confirming the fix does not suppress or depend on suppressing the underlying reconnect flapping), submitted a second 50-element array job, captured a fresh session recording, and replayed it via `xce_scheduler -i -s <file>` + `continue` + `info jobs`: all 100 jobs across both arrays (the pre-fix array replayed through the fixed binary this time, plus the new array) now show DONE, matching the controller's joblist exactly -- zero divergence, confirming the fix closes the reported gap under the exact live conditions that originally exposed it.
|
|
|
|
## Verification
|
|
_Not recorded (migrated from buglog.json)._
|
|
|
|
## References
|
|
- Related: bug-1714, bug-1731, bug-1733
|