---
id: "bug-1731"
status: "fixed"
status_updated: "2026-09-24"
status_note: ""
component: "controller"
severity: "unknown"
timestamp: "2026-08-28T13:39:36Z"
last_seen: "2026-09-19T09:00:00Z"
occurrences: 2
files: ["src/controller/persist.c (apply_committed_entry", "WAL_JOB_FINISH/START/DISPATCH shared case)", "src/controller/sched.c (sched_job_update_fun)"]
tags: ["scheduler", "controller", "job-state", "notification-loss", "unresolved", "unreproduced", "found-live", "possible-crash", "possible-stall", "session-sibling-of-bug-1730"]
related: ["bug-1714", "bug-1730"]
legacy: true
---

# bug-1731: STILL OPEN half of the bug-1730 investigation: the user's originally-reported symptom itself -- a…

## Description
STILL OPEN half of the bug-1730 investigation: the user's originally-reported symptom itself -- a finished job's job->state staying stuck as RUN in the scheduler's own view (live and in a .replay snapshot) despite the controller and the worker both having genuinely completed it -- was NOT conclusively reproduced live despite extensive targeted testing, so its exact trigger mechanism remains unconfirmed.

## Environment
_Not recorded (migrated from buglog.json)._

## Reproduction
_Not recorded (migrated from buglog.json)._

## Root cause
NOT ISOLATED. Investigation trail: traced the full controller-to-scheduler-to-replay-recording pipeline for a job finish end-to-end via static code reading (every hop -- live apply, hook fire, record-encode in recording_events.c, replay-decode in sim_loop.c, replay-apply -- checked individually and found correctly wired for the ordinary case) and found no defect that would explain a PERMANENT loss by itself. Added temporary diagnostic WARN logging at apply_committed_entry()'s two previously-100%-silent early-return points (job not found in jobmgr; apply_job_update_transition() returning REJECTED_BACKWARD/NOOP_DUPLICATE) and reproduced a burst-array-job workload (matching the user's original scenario -- a 30+ element array of near-instant jobs) against both a single-node and a real 3-node HA deploy of this exact worktree's build. Findings from live reproduction: (a) WAL_JOB_FINISH consistently showed result=APPLIED (hook fires) in every observed instance -- did not catch a live silent-drop for FINISH specifically; (b) DID catch WAL_JOB_START correctly no-op'ing as a harmless duplicate when WAL_JOB_DISPATCH already set RUN moments earlier in the same batch (expected, not a bug); (c) a genuinely concerning, SEPARATE, NOT-YET-DIAGNOSED finding: under a very heavy burst (4 concurrent 50-element arrays on a live 3-node cluster), the xce_scheduler process itself DIED entirely mid-run with zero error/fatal/assert output in its own log -- no backtrace captured yet (a subsequent gdb-attached rerun of a similarly-sized burst did not reproduce the crash within the session's remaining time budget); (d) a separate apparent scheduling-throughput stall under a large PEND backlog (200+ near-instant jobs against a 22-slot worker progressing far slower than expected) -- not distinguished from ordinary fork/exec overhead of spawning hundreds of real OS processes on one worker, so not confirmed as a genuine scheduler defect either. Any of (c)/(d) could plausibly be entangled with, or be a completely independent symptom alongside, the original state-staying-wrong report -- not established either way.

UPDATE (2026-08-29, live gdb-wrapped burst repro): two concrete new findings, neither yet closing this bug's original symptom (job state itself stuck at RUN).
(1) LIVE-CAPTURED NOTIFY-DROP, SELF-HEALING IN THE OBSERVED CASE: the DEBUG3 diagnostic trace added earlier this session (sched_job_update_fun, sched.c) fired for real under this burst -- e.g. `DIAG sched_job_update_fun: jobid=4618064451492872238 state=0x2 -- c->sched.ep is NULL, notify SKIPPED` during a ~2s scheduler reconnect blip (handle_scheduler_leave then a rejoin then a second, fatal leave at the crash). Across the run: 173 RUN notifies attempted, 178 DONE notifies delivered, 53 SKIPPED (dropped because c->sched.ep was NULL at fire time). The one traced job above still received its terminal DONE notify ~300ms later and self-healed -- but this is a live, reproducible demonstration of the exact drop mechanism this bug has theorized: if a job's TERMINAL notify (not just an intermediate RUN one) were ever dropped in the same way, with no subsequent notify to self-heal it, the scheduler's view would stay stuck at whatever state it last received -- matching the original reported symptom exactly. Not yet caught happening to a terminal notify specifically, so still not a full reproduction, but the mechanism is now demonstrated live rather than theoretical.
(2) THE SCHEDULER CRASH (open finding (c) above) WAS FINALLY CAPTURED WITH A FULL BACKTRACE -- see bug-1714 for the complete crash detail (SIGSEGV in sched_get_project via a corrupted job_submit_data_t->project_name pointer, core_events.c:221). Tracked as bug-1714 rather than duplicated here since it's a distinct symptom (crash vs. stuck-state) that may or may not share a root cause with this bug's own open half -- both occur under the same heavy concurrent-array-batching conditions, so they remain plausibly entangled, not yet proven either way.
(3) NO THROUGHPUT STALL observed this run (open finding (d) above) -- DIAG counts climbed steadily and continuously right up to the crash; of 300 submitted array elements only 178 reached DONE before the scheduler died at T+150s, but that is a crash artifact (elements cut off mid-flight), not evidence of an independent stall. Finding (d) remains unconfirmed either way, not further investigated this run.

## Fix
FIXED (2026-08-29). Root cause (confirmed, not the same theory this entry's prior root_cause investigation was chasing -- see note at the end): apply_committed_entry() (src/controller/persist.c, the shared WAL_JOB_START/FINISH/STOP/RESUME/RUSAGE/CKPT/PREASON/DISPATCH case) fired exactly ONE generic HOOK_DETAIL_JOB_UPDATE at HOOK_AFTER_EVENT for every job-state fact -- correct and still relied on by sched_job_update_fun/apiserver_job_update_fun -- but NEVER the type-specific HOOK_DETAIL_JOB_START/HOOK_DETAIL_JOB_EXIT, even though live handler pairs for both (sched_job_start_fun/sched_job_exit_fun in sched.c, apiserver_job_start_fun/apiserver_job_exit_fun in apiserver.c, all wired via xce_add_hook) have existed the whole time, subscribed at HOOK_AFTER_EVENT. Those handlers were permanently dead code: job.c only ever fires HOOK_DETAIL_JOB_START/JOB_EXIT/JOB_FAIL at HOOK_BEFORE_EVENT (receipt-time, for WAL-append purposes), never AFTER_EVENT -- see persist.h's apply_committed_entry doc comment, 'Deviation from a literal per-type hook fan-out', for the original documented rationale (the old wal_jobstate_t {jobid, state} wire format could not supply the richer job_pidinfo_t/xce_jobfinish_t payloads those handlers require). That blocker is now stale for START and FINISH specifically: bug-1697 (WAL_JOB_START) and bug-1689 (WAL_JOB_FINISH) already enriched this exact wire format with trailing job_pidinfo_t / job_exitinfo_t+finish_time bytes, decoded every apply into j->job.pidinfo / j->job.exit_info -- just never forwarded to the dead handlers. On the apiserver side this meant DefaultHandler.OnJobFinished (src/frontend/apiserver/backend/handler.go) -- itself correct and fully wired via handleNotifyData's NotifyData_data_jobFinishInfo case (clib.go) -- was permanently starved of data: a job could finish for real (worker and controller both correct) and the apiserver's store.Jobs entry would simply never transition off its pre-finish status.

FIX (src/controller/persist.c, apply_committed_entry's shared job-state-fact case): (1) WAL_JOB_FINISH -- inside the existing `result == JOB_TRANSITION_APPLIED` block (the same guard HOOK_DETAIL_JOB_UPDATE already used), also fire HOOK_DETAIL_JOB_EXIT with a stack-local xce_jobfinish_t{jobid=js->jobid, exit_code=(j->job.exit_info ? j->job.exit_info->exitcode : 0)} -- this is the PRIMARY fix. (2) WAL_JOB_START -- a new call-scoped `bool pidinfo_just_decoded` flag, set ONLY where the pre-existing pidinfo decode-and-adopt block (bug-1697) actually decodes a NEW job_pidinfo_t this call (deliberately NOT `j->job.pidinfo != NULL`, which could already be true from an earlier apply and would misfire on an unrelated later transition for the same job); also belt-and-suspenders stamps `decoded->jobid = js->jobid` explicitly right where it is adopted. HOOK_DETAIL_JOB_START now fires whenever pidinfo_just_decoded is true, INDEPENDENT of `result` -- required because bug-1697 already established that every real job's WAL_JOB_START fact applies as a confirmed NOOP_DUPLICATE in production (dispatch_a_job_() sets state=RUN synchronously before WAL_JOB_START ever applies), so gating on result==APPLIED the way JOB_UPDATE is gated would make the new fire dead code forever, live, exactly the class of bug being fixed. The early-return gate right after unlock(j) was widened from a flat `if (result != JOB_TRANSITION_APPLIED) return 0;` to `if (result != JOB_TRANSITION_APPLIED && !pidinfo_just_decoded) return 0;` so a genuinely-just-decoded START pidinfo still reaches the single t_apply_seam_notifying-guarded hook-fire bracket even on a NOOP_DUPLICATE transition; all three fires (new JOB_START, new JOB_EXIT, pre-existing JOB_UPDATE) stay inside that ONE bracket, not duplicated or narrowed. NULL-safety: sched_job_start_fun/sched_job_exit_fun (sched.c) dereference info->jobid unconditionally with no NULL guard (confirmed via codegraph read of both) -- pidinfo_just_decoded's call-scoped design and the belt-and-suspenders jobid stamp exist specifically to make firing with a NULL/stale payload structurally impossible. Confirmed via codegraph/grep that persist_job_hook_fun (the third XCE_CONTROLLER_HOOK_JOB subscriber, registered via ha_register_persist_hooks) does have live HOOK_DETAIL_JOB_START/EXIT cases (unlike the doc comment's characterization of it as 'HOOK_BEFORE_EVENT only for these details') -- but it early-returns immediately on `t_apply_seam_notifying` (Hazard-1 guard, already true for every fire inside apply_committed_entry's bracket) before ever reaching those cases, so no unintended WAL re-append happens; this nuance is a buglog correction to the doc-comment's own framing, not a defect.

TDD evidence: added test_wjf_apply_committed_entry_fires_job_exit_hook_exactly_once and test_wjf_apply_committed_entry_reapply_finish_fires_no_hook (test_wal_job_finish_fact.c), test_wjs_apply_committed_entry_fires_job_start_hook_with_pidinfo and test_wjs_apply_committed_entry_old_format_no_job_start_hook (test_wal_job_start_fact.c), using a new detail-aware spy hook per file (distinguishes HOOK_DETAIL_JOB_EXIT/JOB_START from JOB_UPDATE and captures the fired payload, unlike the existing blunt 'any AFTER_EVENT' counters already in those files). RED confirmed on unfixed code (persist.c edits temporarily reverted, test files kept): exactly the 2 new primary-path assertions failed (test_wjs_..._fires_job_start_hook_with_pidinfo: Expected 1 Was 0; test_wjf_..._fires_job_exit_hook_exactly_once: Expected 1 Was 0), plus the pre-existing bug-1561 test_config_repl.c flake pair -- 4 failures total, matching expectations exactly. The two negative-guard tests (old-format-no-pidinfo, reapply-fires-no-hook) already passed RED (correctly -- pre-fix code never fires these hooks at all, so 'must not fire' trivially holds), confirming they are genuine regression guards, not accidentally-tautological.

GREEN evidence: after restoring the fix, four PRE-EXISTING tests broke because their assertions hard-coded the old 'exactly one notification' invariant that this fix deliberately changes (more hooks now fire, by design) -- all four updated in place with corrected expected counts plus an explanatory bug-1731 comment (not weakened, not deleted): test_wjs_apply_committed_entry_sets_pidinfo_but_not_start_time (1 -> 2: JOB_UPDATE + new JOB_START both fire on this genuine PEND->RUN transition with pidinfo), test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_dispatch (0 -> 1: this IS bug-1697's exact NOOP_DUPLICATE production scenario -- the new JOB_START fire is the whole point of the fix here, so asserting 0 would mean re-breaking the bug), test_wjf_apply_committed_entry_sets_finish_time_and_exit_info (1 -> 2: JOB_UPDATE + new JOB_EXIT), test_tari_finish_then_stale_start_preserves_terminal_state_via_dispatch in test_apply_reapply_idempotency.c (2 -> 3 after FINISH, stays 3 after the stale-START no-op -- confirms idempotency: the stale START carries no pidinfo trailing bytes, so pidinfo_just_decoded stays false and the already-guard-rejected transition fires nothing new). Full controller regression after all fixes: 1217 tests, 2 failures -- exactly the known, pre-existing, unrelated bug-1561 flake pair (test_conf_trim_keeps_only_n_versions, test_conf_get_saved_tag_no_config) and nothing else. scheduler/worker/xceadmin builds also completed clean (scheduler build surfaced one unrelated, pre-existing test failure -- test_recordstart_symlink_escape_replies_error, in record-file-path validation, zero relation to job-state hooks or any file this fix touched -- not investigated further, out of scope).

LIVE VERIFICATION (single-node cluster, src/tools/deploy-ha.sh to /tmp/xce-deploy-1731, controller+worker+scheduler+apiserver all built from this fix and started via start-all.sh; two real jobs submitted via xce_test jobsub -u root -q normal -c /bin/true, both ran to completion):
  Scheduler side -- scheduler.log shows, for jobid 0-7-1787994329-448775 (and identically for a second job, 0-14-1787994109-0): `event = schedStartJob` immediately followed by `sched_job_state_change 0-7-1787994329-448775 state 2` (handler.c:388, inside sched_job_state_change, handler.c:381 -- state 2 = JOB_STAT_RUN, the NEW HOOK_DETAIL_JOB_START fire), then later `event = schedExitJob` followed by `sched_job_state_change 0-7-1787994329-448775 state 4` (state 4 = JOB_STAT_EXIT, the NEW HOOK_DETAIL_JOB_EXIT fire) -- with `sched_handle_sched_update_job ... updated` (the pre-existing JOB_UPDATE path) still firing on both sides of it, confirming the new fires are additive, not a replacement. Final `joblist` output confirms the job's state in the scheduler-driven view reached DONE, not stuck at RUN.
  Apiserver side (the part specifically asked to be verified) -- added permanent Info-level logging to DefaultHandler.OnJobFinished (handler.go, mirroring this file's existing zap-field logging convention) since it had none before; rebuilt /tmp/apiserver, restarted it against the live cluster, submitted a fresh job. apiserver.log recorded: `OnJobFinished: job status updated {\"jobid\": 33400045333567751, \"exit_code\": 0, \"job_status\": 8}` -- job_status 8 = models.JOBSTAT[\"DONE\"], exit_code 0 matching /bin/true's real exit code, jobid matching the submitted job -- direct proof OnJobFinished, previously never invoked in production, now fires correctly end-to-end. All 4 processes (controller, worker, scheduler, apiserver) remained healthy throughout with zero ASAN/crash output in any log.

Kept out of scope, as directed: WAL_JOB_FAIL's own dead HOOK_DETAIL_JOB_FAIL handler pair (apiserver_job_fail_fun -> jobFailInfo -> OnJobFinished too) was NOT touched -- it lives in a separate, more complex `case` (dispatches on js->_pad, apply_job_fail_transition vs. apply_job_update_transition) a bit further down persist.c's apply_committed_entry, and is a distinct follow-up fix, not covered here.

Files touched: src/controller/persist.c (the fix), src/controller/testsuite/test_wal_job_finish_fact.c and test_wal_job_start_fact.c (new regression tests + corrected pre-existing assertions), src/controller/testsuite/test_apply_reapply_idempotency.c (corrected one pre-existing assertion), src/frontend/apiserver/backend/handler.go (permanent OnJobFinished logging, kept -- not reverted, judged a reasonable permanent addition matching this file's existing logging conventions).

Correction to this entry's own prior root_cause note: the earlier investigation (2026-08-28/29 updates above) was chasing a DIFFERENT theory -- a transient sched.ep==NULL notify-drop window in sched_job_update_fun -- as the suspected mechanism for the original stuck-at-RUN symptom, and left bug-1714 (a scheduler crash found during that chase) as a possibly-entangled open thread. This fix does not address that notify-drop theory or bug-1714 at all; it closes a DIFFERENT, independently confirmed defect (the dead JOB_START/JOB_EXIT hook pair) that was diagnosed and fixed in this session. Both could in principle contribute to real-world stuck-job reports; this entry now tracks the JOB_START/JOB_EXIT hook fix as FIXED, with bug-1714's scheduler-crash thread and any residual sched.ep notify-drop risk left open elsewhere (bug-1714's own entry) rather than reopening speculation here.

FOLLOW-UP (2026-08-29, same session): the WAL_JOB_FAIL HOOK_DETAIL_JOB_FAIL gap explicitly left out of scope above ("Kept out of scope, as directed") is now ALSO fixed. HOOK_DETAIL_JOB_FAIL was fired only at HOOK_BEFORE_EVENT (job.c's mark_job_fail and record_job_fail_fact, at receipt time, for WAL-append purposes) -- never at HOOK_AFTER_EVENT -- leaving two already-written, already-correct handlers permanently dead: sched_job_fail_fun (sched.c, routes to the scheduler via NotifyData_data_schedFailJob) and apiserver_job_fail_fun (apiserver.c, routes to the Go apiserver's NotifyData_data_jobFailInfo case in clib.go -> DefaultHandler.OnJobFinished). A job that FAILED (as opposed to finished cleanly, which this bug's primary fix already covers via WAL_JOB_FINISH/HOOK_DETAIL_JOB_EXIT) never updated the apiserver's job store.

FIX (src/controller/persist.c, apply_committed_entry's `case WAL_JOB_FAIL:` block): hoisted the case-local `job_failinfo_t failinfo` to case scope (it needs to survive past `unlock(j)`) with a new `bool have_failinfo` flag, set true only in the `js->_pad & WAL_JOB_FAIL_STAGE_FLAG` branch (the only branch that constructs a real job_failinfo_t -- the legacy `_pad == 0` absolute-overwrite branch, job_ctrl's synchronous mark_job_fail path, has no fail-specific data to report and must NOT fabricate one, exactly mirroring how this bug's own WAL_JOB_START fix only fires HOOK_DETAIL_JOB_START when pidinfo was genuinely decoded). Inside the existing `t_apply_seam_notifying`-guarded bracket, added `if (have_failinfo) xce_run_hooks(..., HOOK_AFTER_EVENT, HOOK_DETAIL_JOB_FAIL, c, &failinfo, j);` immediately before the pre-existing HOOK_DETAIL_JOB_UPDATE fire -- both fires stay inside the SAME bracket, additive not replacing. Confirmed via reading apply_job_fail_transition() (job.c) that unlike WAL_JOB_START's dispatch-time-optimization no-op'ing, this transition has no internal guard at all -- it unconditionally mutates and returns JOB_TRANSITION_APPLIED for every stage -- so the existing `if (result != JOB_TRANSITION_APPLIED) return 0;` early-return gate did NOT need widening the way WAL_JOB_START's did; a rejectable/no-op outcome for this case can only come from the legacy _pad==0 branch's apply_job_update_transition() guard (job_state_is_backward / duplicate-state checks), which was already correctly gated before this follow-up.

TDD evidence: added 3 tests to test_apply_committed_entry.c -- test_ace_job_fail_stage_flag_fires_faildetail_and_update (seeds job 605 RUN|EXIT, applies WAL_JOB_FAIL with _pad=WAL_JOB_FAIL_STAGE_FLAG|JOB_EXEC_STAGE_POST_EXEC, asserts JOB_STAT_PERR merged AND both hooks fire with the correct jobid in the captured job_failinfo_t), test_ace_job_fail_legacy_pad_zero_fires_update_only (regression guard: _pad==0 branch fires JOB_UPDATE only, never fabricates JOB_FAIL), test_ace_job_fail_guard_rejected_fires_no_hook (a backward transition via the legacy branch, mirroring test_ace_job_state_transition_rejects_backward_suppresses_notify, fires NEITHER hook). New detail-aware spy hook tace_faildetail_spy_hook added (modeled on the file's existing tace_array_spy_hook), with va_arg order (cluster_t*, job_failinfo_t*, job_t*) matching job.c's own HOOK_BEFORE_EVENT fire sites for this detail; g_tace_last_fail_jobid reset to -1 in tace_setup() alongside the existing g_tace_hook_fires reset.

RED confirmed on unfixed code (persist.c fix temporarily git-stashed, test file kept): exactly test_ace_job_fail_stage_flag_fires_faildetail_and_update failed (Expected 2 Was 1 -- HOOK_DETAIL_JOB_FAIL did not fire), plus the pre-existing bug-1561 test_config_repl.c flake pair (2 failures) -- 3 failures total, matching expectations (the other two new tests are regression guards that correctly already passed pre-fix, since the unfixed code never fires HOOK_DETAIL_JOB_FAIL at all).

GREEN confirmed after restoring the fix: all 3 new tests pass. Full controller regression: 1220 tests, 2 failures -- exactly the known, pre-existing, unrelated bug-1561 flake pair (test_conf_trim_keeps_only_n_versions, test_conf_get_saved_tag_no_config) and nothing else.

LIVE VERIFICATION: attempted against a fresh single-node deploy (controller+worker(xcecd_virtual)+scheduler+apiserver, src/tools/deploy-ha.sh to /tmp/xce-deploy, all built from this fix). Confirmed via code reading (xcecd_job_finished, worker/src/controller_connector.c) that a worker-side nonzero exit code routes through xcecd_notify_job_fail (WAL_JOB_FAIL with STAGE_FLAG), never WAL_JOB_FINISH -- so a genuinely-failed job is the right live trigger. Submitted a `sleep 60` job (chosen so the virtual worker's simulated run-time, parsed from the literal command string in VIRTUAL_CLUSTER builds, stays RUN long enough to signal) and sent jobkill -s 9 while it was RUNNING; the controller/worker IPC path correctly delivered the signal and set worker->killed_signal=9 (confirmed in xcecd-worker-1.log). However this sandbox has no D-Bus system bus (no systemd manager reachable), and xcecd_dbus_manager.c's dbus_workers_update() -- unchanged by this fix, in src/worker/, not src/controller/ -- calls get_systemd_job_exit_code() every poll even under VIRTUAL_CLUSTER; that call fails to connect to D-Bus and returns -1, which routes into the `exit_code < 0` (dbus-unreachable) branch of the VIRTUAL_CLUSTER dispatch -- a branch which, on inspection, only checks check_worker_sleep_time_elapsed() and never checks worker->killed_signal (that check exists only in the sibling `exit_code == 0` branch, unreachable in this sandbox since dbus never succeeds). Net effect: in THIS sandboxed environment specifically, xcecd_virtual can only ever report a job as succeeding (exit_code=0) once its simulated sleep time elapses, or hang indefinitely if killed before then -- a genuine nonzero-exit/killed-job WAL_JOB_FAIL could not be produced live here. This is a pre-existing environment/worker-code limitation unrelated to and untouched by this fix (no file outside the fix's own scope was modified to work around it, per this task's constraints) -- an honestly-reported limitation, not a gap in the fix itself. The unit-test coverage above (RED->GREEN on the exact apply-time dispatch code) is the primary proof of correctness; the same live-verification shape this bug's primary fix already used successfully for WAL_JOB_FINISH/WAL_JOB_START (a real dbus-independent xce_test jobsub) does not exist for a genuine WAL_JOB_FAIL trigger in this environment.

Files touched by this follow-up: src/controller/persist.c (the fix), src/controller/testsuite/test_apply_committed_entry.c (3 new tests + 1 new spy hook + 1 new reset line).

## Verification
_Not recorded (migrated from buglog.json)._

## References
- Related: bug-1714, bug-1730