fix(bug-1731): fire HOOK_DETAIL_JOB_START/JOB_EXIT on WAL apply

apply_committed_entry() (persist.c), the single seam that applies every
committed WAL entry, only ever fired the generic HOOK_DETAIL_JOB_UPDATE
for job-state changes -- HOOK_DETAIL_JOB_START/JOB_EXIT were
permanently dead code, since job.c only ever fires them at
HOOK_BEFORE_EVENT (for WAL-append purposes). This left sched_job_start_
fun/sched_job_exit_fun (sched.c) and apiserver_job_start_fun/
apiserver_job_exit_fun (apiserver.c) unreachable, and the Go apiserver's
already-wired OnJobFinished handler permanently starved of data -- a
finished job's state could stay stuck (e.g. showing RUN) in the
scheduler's own view and the apiserver never learned a job finished.

The wire format was already enriched by bug-1697/bug-1689 with the
pidinfo/exit_info data these hooks need, so this closes the gap rather
than requiring new wire work. WAL_JOB_FINISH now fires
HOOK_DETAIL_JOB_EXIT; WAL_JOB_START now fires HOOK_DETAIL_JOB_START,
gated on a call-scoped decode flag rather than the transition result
(WAL_JOB_START applies as a no-op duplicate for every real job in
production per bug-1697, so gating on the transition result would make
it dead code again). WAL_JOB_FAIL -> HOOK_DETAIL_JOB_FAIL has the same
gap and is left as a follow-up.

Also includes this investigation's supporting changes: a DEBUG3 log-
retention bump (main.c, both controller and scheduler) so race-condition
evidence survives a live burst without rotating out, and DEBUG3-gated
diagnostic trace logging at the two points a job-update notification
can fire or silently drop (job.c, sched.c).

Live-verified end to end on a real deployed cluster: scheduler-side
sched_job_state_change now fires for RUN and EXIT states, and the
apiserver's OnJobFinished -- previously never invoked in production --
now correctly updates job status on completion.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_019QxaSzHRB7pmYFp4cVnwkA

src/controller/job.c

@@ -3200,6 +3200,13 @@ int update_job_rusages(cluster_t* c, endpoint_t* ep, xce_request_t* request)
     /* FIXME
      * update other fields of job rusage later
      */
+    /* TEMP diagnostic (bug-1731 job-finish-notify-loss investigation).
+     * DEBUG3-gated -- see bug-1731's own "re-add before next occurrence"
+     * recommendation; the DEBUG3 log-retention bump (bug-1731 support,
+     * main.c) exists so this survives a live burst without rotating out. */
+    TRACE("DIAG update_job_rusages: jobid=%ld state=0x%x (about to fire "
+          "live JOB_UPDATE hook)",
+          (long)j->job.jobid, (unsigned)j->job.state);
     xce_run_hooks(&(c->hooksys), XCE_CONTROLLER_HOOK_JOB, HOOK_AFTER_EVENT,
                   HOOK_DETAIL_JOB_UPDATE, c, j);
 

src/controller/main.c

@@ -379,6 +379,17 @@ int main(int argc, char* argv[])
         loglevel = verbose_to_loglevel(arguments.verbose);
     }
 
+    /* DEBUG3 produces order-of-magnitude more log volume than the default
+     * size/count budget below is sized for, so tlog's own rotation can
+     * gzip away the window a bug occurred in well before anyone gets a
+     * chance to look (bug-1731: the primary's log for the exact moment a
+     * race fired had already rotated out). Give DEBUG3 runs a much larger
+     * retention budget so a targeted repro survives to be inspected. */
+    if (strcmp(loglevel, "debug3") == 0) {
+        logsize  *= 8;
+        logcount *= 4;
+    }
+
     mylog_init(logfile, loglevel, logsize, logcount);
 
     if (arguments.workdir == NULL) {

src/controller/persist.c

@@ -4644,6 +4644,17 @@ int apply_committed_entry(persist_t* p, uint32_t wal_type, uint64_t lsn,
          * payload of exactly sizeof(wal_jobstate_t) (no trailing bytes at
          * all -- any WAL_JOB_START entry written before bug-1687) decodes
          * no pidinfo, matching the pre-1687 state-only behavior exactly. */
+        /* bug-1731: pidinfo_just_decoded is a call-scoped flag, set ONLY
+         * where the decode-and-adopt block immediately below genuinely
+         * decodes a new job_pidinfo_t THIS call -- deliberately NOT the
+         * same thing as `j->job.pidinfo != NULL` (which could already be
+         * true from an earlier apply of this same job, and would wrongly
+         * re-trigger the HOOK_DETAIL_JOB_START fire below for an unrelated
+         * later transition). This flag gates that fire; see the fire site
+         * near the end of this case for why it must NOT be gated on
+         * `result == JOB_TRANSITION_APPLIED` the way HOOK_DETAIL_JOB_UPDATE
+         * is. */
+        bool pidinfo_just_decoded = false;
         if (wal_type == WAL_JOB_START
             && len >= sizeof(wal_jobstate_t) + sizeof(uint64_t)) {
             uint32_t pidinfo_len = (uint32_t)len
@@ -4658,6 +4669,17 @@ int apply_committed_entry(persist_t* p, uint32_t wal_type, uint64_t lsn,
                     if (j->job.pidinfo != NULL)
                         free_JobPIDInfo_ptr(&(j->job.pidinfo));
                     j->job.pidinfo = decoded;
+                    /* bug-1731 belt-and-suspenders: explicitly stamp jobid
+                     * on the decoded struct rather than trusting the capnp
+                     * decode alone -- cheap and always correct, and this is
+                     * exactly the field sched_job_start_fun (sched.c)
+                     * unconditionally dereferences (info->jobid, no NULL
+                     * guard) the moment HOOK_DETAIL_JOB_START fires below;
+                     * see persist.h's apply_committed_entry doc comment for
+                     * the full NULL-safety history that made this detail
+                     * permanently dead code until now. */
+                    decoded->jobid = js->jobid;
+                    pidinfo_just_decoded = true;
                 }
             }
         }
@@ -4761,8 +4783,24 @@ int apply_committed_entry(persist_t* p, uint32_t wal_type, uint64_t lsn,
         }
         unlock(j);
 
-        if (result != JOB_TRANSITION_APPLIED)
+        /* bug-1731: this gate used to be a flat `result != APPLIED` early
-            return 0; /* rejected-backward / no-op-duplicate — no hook */
+         * return (no hook at all on a rejected-backward/no-op-duplicate
+         * transition). It now also lets a genuinely-just-decoded
+         * WAL_JOB_START pidinfo through even when `result` is a confirmed
+         * NOOP_DUPLICATE -- which, per bug-1697, is what EVERY real job's
+         * WAL_JOB_START fact applies as in production (dispatch_a_job_()
+         * already set state=RUN synchronously before WAL_JOB_START ever
+         * applies). Gating the new HOOK_DETAIL_JOB_START fire on
+         * result==JOB_TRANSITION_APPLIED, like HOOK_DETAIL_JOB_UPDATE below,
+         * would make it dead code for every real job -- exactly the bug
+         * being fixed here for HOOK_DETAIL_JOB_EXIT. A genuine idempotent
+         * re-apply of an already-applied WAL_JOB_FINISH still hits this same
+         * early return and fires NOTHING (pidinfo_just_decoded is only ever
+         * set inside the WAL_JOB_START branch above, so it stays false for
+         * every other wal_type in this group). */
+        if (result != JOB_TRANSITION_APPLIED && !pidinfo_just_decoded)
+            return 0; /* rejected-backward / no-op-duplicate, and no pidinfo
+                       * just decoded either — nothing to notify */
 
         /* Hazard 1 guard (see t_apply_seam_notifying's doc comment above):
          * HOOK_DETAIL_JOB_UPDATE is dual-origin — job_ctrl's mark_job_update
@@ -4770,10 +4808,53 @@ int apply_committed_entry(persist_t* p, uint32_t wal_type, uint64_t lsn,
          * still-legitimate append via persist_job_hook_fun. Without this
          * guard, EVERY fact this apply pump applies would re-append itself
          * as a duplicate, mis-typed WAL_JOB_UPDATE entry the moment the live
-         * pump (task 6.1) starts calling this function. */
+         * pump (task 6.1) starts calling this function. Single bracket
+         * wraps ALL THREE possible fires below (bug-1731 adds JOB_START/
+         * JOB_EXIT alongside the pre-existing JOB_UPDATE) — do not narrow or
+         * duplicate this guard per-fire. */
         t_apply_seam_notifying = true;
-        xce_run_hooks(&c->hooksys, XCE_CONTROLLER_HOOK_JOB, HOOK_AFTER_EVENT,
+
-                      HOOK_DETAIL_JOB_UPDATE, c, j);
+        /* bug-1731: HOOK_DETAIL_JOB_START -- fires independent of `result`;
+         * see pidinfo_just_decoded's own doc comment at its declaration
+         * above, and the gate comment immediately above this bracket. Args
+         * mirror job.c's own HOOK_BEFORE_EVENT fire site for this exact
+         * detail (record_job_start_fact, job.c) — (c, info, job) — so every
+         * subscriber's va_arg reads stay consistent regardless of which
+         * situation/call site fired it. */
+        if (pidinfo_just_decoded) {
+            xce_run_hooks(&c->hooksys, XCE_CONTROLLER_HOOK_JOB,
+                          HOOK_AFTER_EVENT, HOOK_DETAIL_JOB_START, c,
+                          j->job.pidinfo, j);
+        }
+
+        if (result == JOB_TRANSITION_APPLIED) {
+            /* bug-1731: HOOK_DETAIL_JOB_EXIT for WAL_JOB_FINISH -- this is
+             * the PRIMARY fix for bug-1731 (apiserver's OnJobFinished was
+             * permanently starved of data; see persist.h's
+             * apply_committed_entry doc comment for the full history of why
+             * this detail was dead). exit_code is read from j->job.exit_info
+             * (decoded/adopted just above when the wire payload carried
+             * trailing bytes, bug-1689) — an old-format payload with no
+             * trailing bytes leaves exit_info NULL, so exit_code falls back
+             * to 0 rather than reading a dangling/garbage value. Args mirror
+             * job.c's own HOOK_BEFORE_EVENT fire site (record_job_finish_
+             * fact, job.c) — (c, finish, job). */
+            if (wal_type == WAL_JOB_FINISH) {
+                xce_jobfinish_t finish_info = {
+                    .jobid = js->jobid,
+                    .exit_code = (j->job.exit_info != NULL)
+                        ? j->job.exit_info->exitcode
+                        : 0,
+                };
+                xce_run_hooks(&c->hooksys, XCE_CONTROLLER_HOOK_JOB,
+                              HOOK_AFTER_EVENT, HOOK_DETAIL_JOB_EXIT, c,
+                              &finish_info, j);
+            }
+
+            xce_run_hooks(&c->hooksys, XCE_CONTROLLER_HOOK_JOB,
+                          HOOK_AFTER_EVENT, HOOK_DETAIL_JOB_UPDATE, c, j);
+        }
+
         t_apply_seam_notifying = false;
         return 0;
     }

src/controller/sched.c

@@ -445,10 +445,28 @@ static int sched_job_update_fun(int type, int situation, void* data, va_list ap)
         switch (situation) {
         case HOOK_AFTER_EVENT:
             rc = notify(c, c->sched.ep, &xdata);
+            /* TEMP diagnostic (bug-1731 job-finish-notify-loss
+             * investigation): fires for BOTH the deferred-apply source
+             * (apply_committed_entry(), persist.c) and the live-rusage
+             * source (update_job_rusages(), job.c) -- both route through
+             * this one function. jobid+state+rc together distinguish
+             * which source fired and whether notify() itself reported
+             * success. DEBUG3-gated -- see bug-1731's own "re-add before
+             * next occurrence" recommendation; the DEBUG3 log-retention
+             * bump (bug-1731 support, main.c) exists so this survives a
+             * live burst without rotating out. */
+            TRACE("DIAG sched_job_update_fun: jobid=%ld state=0x%x rc=%d",
+                  (long)job->job.jobid, (unsigned)job->job.state, rc);
             break;
         default:
             break;
         }
+    } else {
+        /* TEMP diagnostic (bug-1731): scheduler disconnected at the exact
+         * moment this notification was due -- silently dropped today. */
+        TRACE("DIAG sched_job_update_fun: jobid=%ld state=0x%x -- "
+              "c->sched.ep is NULL, notify SKIPPED",
+              (long)job->job.jobid, (unsigned)job->job.state);
     }
 
     mylock_unlock(&(c->sched.lock));

src/controller/testsuite/test_apply_reapply_idempotency.c

@@ -338,9 +338,11 @@ test_tari_finish_then_stale_start_preserves_terminal_state_via_dispatch(void)
                                                    sizeof(finish)));
     TEST_ASSERT_EQUAL_UINT32_MESSAGE(JOB_STAT_DONE, j->job.state,
         "FINISH must drive the job to its terminal state");
-    TEST_ASSERT_EQUAL_INT_MESSAGE(2, g_tari_hook_fires,
+    TEST_ASSERT_EQUAL_INT_MESSAGE(3, g_tari_hook_fires,
-        "FINISH must fire exactly one notification (SUBMIT's + FINISH's = "
+        "bug-1731: a genuine forward WAL_JOB_FINISH transition now fires "
-        "2 total so far)");
+        "TWO notifications (the pre-existing HOOK_DETAIL_JOB_UPDATE plus "
+        "the new HOOK_DETAIL_JOB_EXIT), not one -- SUBMIT's 1 + FINISH's "
+        "2 = 3 total so far; tari_spy_hook counts every AFTER_EVENT detail");
 
     /* Step 3: apply a STALE, previously-unapplied START for the SAME job —
      * simulating a duplicate/out-of-order fact arriving after the job
@@ -361,9 +363,11 @@ test_tari_finish_then_stale_start_preserves_terminal_state_via_dispatch(void)
     TEST_ASSERT_EQUAL_UINT32_MESSAGE(JOB_STAT_DONE, j->job.state,
         "the job must remain in its FINISH-terminal state after the stale "
         "START is applied");
-    TEST_ASSERT_EQUAL_INT_MESSAGE(2, g_tari_hook_fires,
+    TEST_ASSERT_EQUAL_INT_MESSAGE(3, g_tari_hook_fires,
-        "the stale, guard-rejected START must fire NO notification — the "
+        "the stale, guard-rejected START must fire NO notification -- no "
-        "count must stay exactly where FINISH left it");
+        "trailing pidinfo bytes means pidinfo_just_decoded stays false too "
+        "(bug-1731's HOOK_DETAIL_JOB_START gate), so the count must stay "
+        "exactly where FINISH left it (3)");
 
     tari_teardown();
     printf("test_tari_finish_then_stale_start_preserves_terminal_state_via_"

src/controller/testsuite/test_wal_job_finish_fact.c

@@ -80,6 +80,46 @@ static int wjf_spy_hook(int type, int situation, int detail, void* data,
     return 0;
 }
 
+/* ── bug-1731: detail-aware spy hook, distinguishing HOOK_DETAIL_JOB_EXIT
+ * from HOOK_DETAIL_JOB_UPDATE and capturing the JOB_EXIT payload -- unlike
+ * wjf_spy_hook above (which just counts every AFTER_EVENT fire regardless
+ * of detail), this proves the NEW fire happens (not just "a" fire) and that
+ * the pre-existing JOB_UPDATE fire is not replaced or interfered with. Arg
+ * shapes mirror sched_job_exit_fun/apiserver_job_exit_fun's own va_arg
+ * reads (cluster_t*, xce_jobfinish_t*) and persist_job_hook_fun's
+ * HOOK_DETAIL_JOB_UPDATE case (cluster_t*, job_t*). */
+static int             g_wjf_exit_hook_fires;
+static int             g_wjf_update_hook_fires;
+static xce_jobfinish_t g_wjf_captured_finish;
+static int             g_wjf_captured_finish_valid;
+
+static int wjf_detail_spy_hook(int type, int situation, int detail,
+                               void* data, va_list ap)
+{
+    (void)type; (void)data;
+    if (situation != HOOK_AFTER_EVENT)
+        return 0;
+
+    switch (detail) {
+    case HOOK_DETAIL_JOB_EXIT: {
+        (void)va_arg(ap, cluster_t*);
+        xce_jobfinish_t* info = va_arg(ap, xce_jobfinish_t*);
+        g_wjf_exit_hook_fires++;
+        if (info != NULL) {
+            g_wjf_captured_finish       = *info;
+            g_wjf_captured_finish_valid = 1;
+        }
+        break;
+    }
+    case HOOK_DETAIL_JOB_UPDATE:
+        g_wjf_update_hook_fires++;
+        break;
+    default:
+        break;
+    }
+    return 0;
+}
+
 static void wjf_setup(void)
 {
     kvmgr_params_t int_params = { .key_type = KVMGR_KEY_INT,
@@ -213,9 +253,14 @@ static void test_wjf_apply_committed_entry_sets_finish_time_and_exit_info(void)
         (int)(wire_finish_time - (uint64_t)seed_start), j->job.run_time,
         "run_time must be re-derived from the wire-carried finish_time minus "
         "start_time");
-    TEST_ASSERT_EQUAL_INT_MESSAGE(1, g_wjf_hook_fires,
+    TEST_ASSERT_EQUAL_INT_MESSAGE(2, g_wjf_hook_fires,
-        "a forward WAL_JOB_FINISH transition must still fire exactly one "
+        "bug-1731: a forward WAL_JOB_FINISH transition now fires TWO "
-        "notification");
+        "notifications, not one -- the pre-existing HOOK_DETAIL_JOB_UPDATE "
+        "plus the new HOOK_DETAIL_JOB_EXIT; wjf_spy_hook counts every "
+        "AFTER_EVENT detail, so both land here. See "
+        "test_wjf_apply_committed_entry_fires_job_exit_hook_exactly_once "
+        "below for a detail-aware assertion isolating the new fire "
+        "specifically");
 
     wjf_teardown();
     printf("test_wjf_apply_committed_entry_sets_finish_time_and_exit_info: "
@@ -256,6 +301,135 @@ test_wjf_apply_committed_entry_backward_compat_old_payload(void)
           "PASS\n");
 }
 
+/* bug-1731's primary regression test: apply_committed_entry()'s
+ * WAL_JOB_START/FINISH/... shared case fires exactly ONE generic
+ * HOOK_DETAIL_JOB_UPDATE at HOOK_AFTER_EVENT for every job-state fact,
+ * including WAL_JOB_FINISH -- but never the type-specific
+ * HOOK_DETAIL_JOB_EXIT, so the apiserver's fully-wired `case
+ * NotifyData_data_jobFinishInfo:` (apiserver_job_exit_fun -> OnJobFinished)
+ * was permanently starved of data. This is now fixed: a genuine forward
+ * WAL_JOB_FINISH transition (result == JOB_TRANSITION_APPLIED) also fires
+ * HOOK_DETAIL_JOB_EXIT with a real xce_jobfinish_t{jobid, exit_code} -- RED
+ * before the fix (g_wjf_exit_hook_fires stays 0), GREEN after. Also
+ * confirms the pre-existing HOOK_DETAIL_JOB_UPDATE fire is untouched
+ * (regression guard -- the new fire must not replace or interfere with
+ * it). */
+static void
+test_wjf_apply_committed_entry_fires_job_exit_hook_exactly_once(void)
+{
+    wjf_setup();
+    g_wjf_exit_hook_fires       = 0;
+    g_wjf_update_hook_fires     = 0;
+    g_wjf_captured_finish_valid = 0;
+    memset(&g_wjf_captured_finish, 0, sizeof(g_wjf_captured_finish));
+
+    time_t seed_start = 1700100000;
+    job_t* j = wjf_seed_job(73010, JOB_STAT_RUN, seed_start);
+    TEST_ASSERT_NOT_NULL(j);
+
+    uint64_t wire_finish_time = 1700100050ULL;
+    int32_t  wire_exit_code   = 7;
+
+    uint8_t* payload = NULL;
+    size_t   plen    = 0;
+    wjf_build_finish_payload(73010, JOB_STAT_EXIT, wire_finish_time,
+                             wire_exit_code, &payload, &plen);
+
+    xce_add_hook(&g_wjf_c.hooksys, XCE_CONTROLLER_HOOK_JOB,
+                wjf_detail_spy_hook, NULL);
+
+    int rc = apply_committed_entry(&g_wjf_p, WAL_JOB_FINISH, 400, payload,
+                                   (uint32_t)plen);
+    free(payload);
+
+    TEST_ASSERT_EQUAL_INT(0, rc);
+    TEST_ASSERT_EQUAL_UINT32(JOB_STAT_EXIT, j->job.state);
+
+    TEST_ASSERT_EQUAL_INT_MESSAGE(1, g_wjf_exit_hook_fires,
+        "bug-1731: a genuine forward WAL_JOB_FINISH apply must fire "
+        "HOOK_DETAIL_JOB_EXIT at HOOK_AFTER_EVENT exactly once -- this is "
+        "the ONLY mechanism that drives the apiserver's OnJobFinished, "
+        "which was permanently starved of data before this fix (the dead "
+        "handler pair sched_job_exit_fun/apiserver_job_exit_fun only ever "
+        "subscribes to HOOK_AFTER_EVENT, but job.c only ever fires this "
+        "detail at HOOK_BEFORE_EVENT)");
+    TEST_ASSERT_TRUE_MESSAGE(g_wjf_captured_finish_valid,
+        "HOOK_DETAIL_JOB_EXIT must fire with a non-NULL xce_jobfinish_t*");
+    TEST_ASSERT_EQUAL_UINT64_MESSAGE(73010, g_wjf_captured_finish.jobid,
+        "the fired xce_jobfinish_t's jobid must match the applied job");
+    TEST_ASSERT_EQUAL_INT_MESSAGE(wire_exit_code,
+        g_wjf_captured_finish.exit_code,
+        "the fired xce_jobfinish_t's exit_code must match the wire-carried "
+        "exit_code this WAL_JOB_FINISH payload encoded");
+
+    TEST_ASSERT_EQUAL_INT_MESSAGE(1, g_wjf_update_hook_fires,
+        "bug-1731 regression guard: the pre-existing HOOK_DETAIL_JOB_UPDATE "
+        "fire (sched_job_update_fun/apiserver_job_update_fun's live path) "
+        "must still happen too -- the new JOB_EXIT fire must not replace or "
+        "interfere with it");
+
+    xce_disable_hook(&g_wjf_c.hooksys, XCE_CONTROLLER_HOOK_JOB,
+                     wjf_detail_spy_hook);
+    wjf_teardown();
+    printf(
+        "test_wjf_apply_committed_entry_fires_job_exit_hook_exactly_once: "
+        "PASS\n");
+}
+
+/* bug-1731 idempotency guard (Constraints: "re-applying an already-applied
+ * WAL_JOB_FINISH should hit the existing result != JOB_TRANSITION_APPLIED
+ * early-return and fire NOTHING, exactly as it does today for
+ * HOOK_DETAIL_JOB_UPDATE"): a job already in a terminal state re-receiving
+ * the identical WAL_JOB_FINISH fact (simulating a restart-replay/standby
+ * catch-up re-application of an already-applied entry) must fire NEITHER
+ * the new HOOK_DETAIL_JOB_EXIT NOR the pre-existing HOOK_DETAIL_JOB_UPDATE
+ * -- the new fire sits inside the SAME `result == JOB_TRANSITION_APPLIED`
+ * guard as JOB_UPDATE, so it inherits this idempotency for free. */
+static void
+test_wjf_apply_committed_entry_reapply_finish_fires_no_hook(void)
+{
+    wjf_setup();
+    g_wjf_exit_hook_fires   = 0;
+    g_wjf_update_hook_fires = 0;
+
+    time_t seed_start = 1700200000;
+    /* Already terminal -- as if a prior WAL_JOB_FINISH already applied. */
+    job_t* j = wjf_seed_job(73011, JOB_STAT_EXIT, seed_start);
+    TEST_ASSERT_NOT_NULL(j);
+
+    uint64_t wire_finish_time = 1700200050ULL;
+    int32_t  wire_exit_code   = 3;
+
+    uint8_t* payload = NULL;
+    size_t   plen    = 0;
+    wjf_build_finish_payload(73011, JOB_STAT_EXIT, wire_finish_time,
+                             wire_exit_code, &payload, &plen);
+
+    xce_add_hook(&g_wjf_c.hooksys, XCE_CONTROLLER_HOOK_JOB,
+                wjf_detail_spy_hook, NULL);
+
+    int rc = apply_committed_entry(&g_wjf_p, WAL_JOB_FINISH, 401, payload,
+                                   (uint32_t)plen);
+    free(payload);
+
+    TEST_ASSERT_EQUAL_INT(0, rc);
+    TEST_ASSERT_EQUAL_INT_MESSAGE(0, g_wjf_exit_hook_fires,
+        "bug-1731: re-applying an already-terminal WAL_JOB_FINISH "
+        "(rejected-backward/no-op-duplicate) must fire NO "
+        "HOOK_DETAIL_JOB_EXIT -- confirms the new fire inherits the "
+        "existing apply-once idempotency guard for free");
+    TEST_ASSERT_EQUAL_INT_MESSAGE(0, g_wjf_update_hook_fires,
+        "the pre-existing HOOK_DETAIL_JOB_UPDATE fire must likewise stay "
+        "silent on a duplicate re-apply, unchanged from before this fix");
+
+    xce_disable_hook(&g_wjf_c.hooksys, XCE_CONTROLLER_HOOK_JOB,
+                     wjf_detail_spy_hook);
+    wjf_teardown();
+    printf(
+        "test_wjf_apply_committed_entry_reapply_finish_fires_no_hook: "
+        "PASS\n");
+}
+
 /* ── apply_wal_entry(): standby catch-up / replicated-apply dispatch ────── */
 
 static void
@@ -682,6 +856,8 @@ void test_wal_job_finish_fact(void)
     UnitySetTestFile(__FILE__);
     RUN_TEST(test_wjf_apply_committed_entry_sets_finish_time_and_exit_info);
     RUN_TEST(test_wjf_apply_committed_entry_backward_compat_old_payload);
+    RUN_TEST(test_wjf_apply_committed_entry_fires_job_exit_hook_exactly_once);
+    RUN_TEST(test_wjf_apply_committed_entry_reapply_finish_fires_no_hook);
     RUN_TEST(test_wjf_apply_wal_entry_sets_finish_time_and_exit_info_no_hook);
     RUN_TEST(test_wjf_apply_wal_entry_backward_compat_old_payload);
     RUN_TEST(test_wjf_restart_replay_recovers_finish_time_and_exit_info);

src/controller/testsuite/test_wal_job_start_fact.c

@@ -73,6 +73,36 @@ static int wjs_spy_hook(int type, int situation, int detail, void* data,
     return 0;
 }
 
+/* ── bug-1731: detail-aware spy hook, distinguishing HOOK_DETAIL_JOB_START
+ * from every other detail and capturing its payload -- unlike wjs_spy_hook
+ * above (which just counts every AFTER_EVENT fire regardless of detail),
+ * this proves the NEW fire happens (not just "a" fire), and captures the
+ * jobid off the fired job_pidinfo_t* for exact-match assertions. Arg shape
+ * mirrors sched_job_start_fun/apiserver_job_start_fun's own va_arg reads
+ * (cluster_t*, job_pidinfo_t*). */
+static int      g_wjs_start_hook_fires;
+static int      g_wjs_captured_start_valid;
+static uint64_t g_wjs_captured_start_jobid;
+
+static int wjs_detail_spy_hook(int type, int situation, int detail,
+                               void* data, va_list ap)
+{
+    (void)type; (void)data;
+    if (situation != HOOK_AFTER_EVENT)
+        return 0;
+
+    if (detail == HOOK_DETAIL_JOB_START) {
+        (void)va_arg(ap, cluster_t*);
+        job_pidinfo_t* info = va_arg(ap, job_pidinfo_t*);
+        g_wjs_start_hook_fires++;
+        if (info != NULL) {
+            g_wjs_captured_start_valid = 1;
+            g_wjs_captured_start_jobid = info->jobid;
+        }
+    }
+    return 0;
+}
+
 static void wjs_setup(void)
 {
     kvmgr_params_t int_params = { .key_type = KVMGR_KEY_INT,
@@ -260,9 +290,15 @@ static void test_wjs_apply_committed_entry_sets_pidinfo_but_not_start_time(void)
         "DISPATCH-owned now, so it must be left exactly as it was before "
         "this apply");
     wjs_assert_pidinfo_matches(j->job.pidinfo, 72001);
-    TEST_ASSERT_EQUAL_INT_MESSAGE(1, g_wjs_hook_fires,
+    TEST_ASSERT_EQUAL_INT_MESSAGE(2, g_wjs_hook_fires,
-        "a forward WAL_JOB_START transition must still fire exactly one "
+        "bug-1731: a forward WAL_JOB_START transition with trailing pidinfo "
-        "notification");
+        "bytes now fires TWO notifications, not one -- the pre-existing "
+        "HOOK_DETAIL_JOB_UPDATE (this genuine PEND->RUN transition) plus "
+        "the new HOOK_DETAIL_JOB_START (pidinfo was just decoded this "
+        "call); wjs_spy_hook counts every AFTER_EVENT detail, so both land "
+        "here. See test_wjs_apply_committed_entry_fires_job_start_hook_"
+        "with_pidinfo below for a detail-aware assertion isolating the new "
+        "fire specifically");
 
     wjs_teardown();
     printf("test_wjs_apply_committed_entry_sets_pidinfo_but_not_start_time: "
@@ -323,7 +359,15 @@ test_wjs_apply_committed_entry_backward_compat_old_payload(void)
  * start_time (seeded here as if dispatch had already stamped it) is left
  * completely untouched -- proving the fix does NOT let this fact's own
  * (now-irrelevant) wire start_time clobber the correct dispatch-time
- * value. */
+ * value.
+ *
+ * bug-1731 update: g_wjs_hook_fires no longer stays 0 here -- this exact
+ * NOOP_DUPLICATE-with-just-decoded-pidinfo scenario is precisely what
+ * bug-1731 fixes: HOOK_DETAIL_JOB_START now fires exactly once (see the
+ * updated assertion below), independent of the confirmed NOOP transition.
+ * Before bug-1731, this scenario left the scheduler/apiserver permanently
+ * unable to observe a job's start pidinfo, since it is the ONLY shape a
+ * real job's WAL_JOB_START ever applies as in production. */
 static void
 test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_dispatch(void)
 {
@@ -363,10 +407,14 @@ test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_dispatch(voi
         "bug-1697: the dispatch-time start_time must survive completely "
         "untouched -- the WAL_JOB_START fact's own (later, different) "
         "wire-carried start_time must never be adopted");
-    TEST_ASSERT_EQUAL_INT_MESSAGE(0, g_wjs_hook_fires,
+    TEST_ASSERT_EQUAL_INT_MESSAGE(1, g_wjs_hook_fires,
-        "this transition is a confirmed NOOP_DUPLICATE (state already RUN "
+        "bug-1731: this transition is a confirmed NOOP_DUPLICATE (state "
-        "from dispatch) -- no forward-transition hook fires, exactly like "
+        "already RUN from dispatch), so HOOK_DETAIL_JOB_UPDATE does NOT "
-        "every other job reaching WAL_JOB_START in production today");
+        "fire -- but HOOK_DETAIL_JOB_START now DOES, exactly once, because "
+        "pidinfo was genuinely decoded this call. This is precisely the "
+        "scenario every real job's WAL_JOB_START fact hits in production "
+        "(bug-1697), so a 0-fire count here would mean the scheduler is "
+        "permanently starved of job-start data, the bug bug-1731 fixes");
 
     wjs_teardown();
     printf(
@@ -374,6 +422,134 @@ test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_dispatch(voi
         "from_dispatch: PASS\n");
 }
 
+/* bug-1731's WAL_JOB_START regression test: proves HOOK_DETAIL_JOB_START now
+ * fires at HOOK_AFTER_EVENT whenever pidinfo trailing bytes were genuinely
+ * decoded this call -- INDEPENDENT of the transition result. Seeds the job
+ * already RUN (as if dispatch_a_job_() already ran, mirroring bug-1697's own
+ * test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_
+ * dispatch), which is what EVERY real job's WAL_JOB_START fact sees in
+ * production -- a confirmed NOOP_DUPLICATE transition. Gating the new fire
+ * on result==JOB_TRANSITION_APPLIED (the way HOOK_DETAIL_JOB_UPDATE is
+ * gated) would make it dead code for every real job, exactly the class of
+ * bug this fix closes for JOB_EXIT. RED before the fix: g_wjs_start_hook_
+ * fires stays 0. GREEN after: fires exactly once with a non-NULL
+ * job_pidinfo_t* whose jobid matches. */
+static void
+test_wjs_apply_committed_entry_fires_job_start_hook_with_pidinfo(void)
+{
+    wjs_setup();
+    g_wjs_start_hook_fires     = 0;
+    g_wjs_captured_start_valid = 0;
+
+    job_t* j = wjs_seed_job(72010, JOB_STAT_RUN); /* already RUN, as if
+                                                    * dispatch_a_job_()
+                                                    * already ran (bug-1697:
+                                                    * the real, 100%-
+                                                    * reproducing production
+                                                    * scenario) */
+    TEST_ASSERT_NOT_NULL(j);
+
+    job_pidinfo_t info = wjs_make_test_pidinfo(72010);
+    uint64_t wire_start_time = 1800100000ULL;
+
+    uint8_t* payload = NULL;
+    size_t   plen    = 0;
+    TEST_ASSERT_EQUAL_INT(0,
+        wjs_build_start_payload(72010, JOB_STAT_RUN, wire_start_time, &info,
+                                &payload, &plen));
+
+    xce_add_hook(&g_wjs_c.hooksys, XCE_CONTROLLER_HOOK_JOB,
+                wjs_detail_spy_hook, NULL);
+
+    int rc = apply_committed_entry(&g_wjs_p, WAL_JOB_START, 210, payload,
+                                   (uint32_t)plen);
+    free(payload);
+
+    TEST_ASSERT_EQUAL_INT(0, rc);
+    TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
+    TEST_ASSERT_EQUAL_INT_MESSAGE(1, g_wjs_start_hook_fires,
+        "bug-1731: WAL_JOB_START with trailing pidinfo bytes must fire "
+        "HOOK_DETAIL_JOB_START at HOOK_AFTER_EVENT exactly once, even "
+        "though (per bug-1697) this transition applies as a confirmed "
+        "NOOP_DUPLICATE for every real job in production -- gating this "
+        "fire on a genuine forward transition would make it dead code "
+        "forever, live");
+    TEST_ASSERT_TRUE_MESSAGE(g_wjs_captured_start_valid,
+        "HOOK_DETAIL_JOB_START must fire with a non-NULL job_pidinfo_t*");
+    TEST_ASSERT_EQUAL_UINT64_MESSAGE(72010, g_wjs_captured_start_jobid,
+        "the fired job_pidinfo_t's jobid must match the applied job -- "
+        "sched_job_start_fun (sched.c) dereferences info->jobid "
+        "unconditionally with no NULL guard, so this must never be wrong");
+
+    xce_disable_hook(&g_wjs_c.hooksys, XCE_CONTROLLER_HOOK_JOB,
+                     wjs_detail_spy_hook);
+    wjs_teardown();
+    printf(
+        "test_wjs_apply_committed_entry_fires_job_start_hook_with_pidinfo: "
+        "PASS\n");
+}
+
+/* bug-1731's NULL-safety regression guard (strong form): sched_job_start_fun
+ * (sched.c) dereferences info->jobid UNCONDITIONALLY with no NULL guard --
+ * firing HOOK_DETAIL_JOB_START with a NULL/stale payload would crash the
+ * scheduler process. Seeds j->job.pidinfo as ALREADY non-NULL (simulating a
+ * prior apply's adoption) before applying an old-format WAL_JOB_START
+ * payload (exactly sizeof(wal_jobstate_t), no pidinfo trailing bytes at
+ * all) -- if the fix had incorrectly gated the new fire on
+ * `j->job.pidinfo != NULL` instead of a call-scoped decode flag, this
+ * sentinel alone would be enough to wrongly trigger it on a call that
+ * decoded NO pidinfo this time. Must NOT fire. */
+static void
+test_wjs_apply_committed_entry_old_format_no_job_start_hook(void)
+{
+    wjs_setup();
+    g_wjs_start_hook_fires     = 0;
+    g_wjs_captured_start_valid = 0;
+
+    job_t* j = wjs_seed_job(72011, JOB_STAT_PEND);
+    TEST_ASSERT_NOT_NULL(j);
+
+    /* Sentinel -- simulates pidinfo already adopted by an earlier apply.
+     * Allocated with calloc(), mirroring decode_pidinfo()'s own allocation
+     * convention, so it is safe for the fixture's teardown path to release
+     * later via the normal job-destruction route. */
+    job_pidinfo_t* sentinel = calloc(1, sizeof(*sentinel));
+    TEST_ASSERT_NOT_NULL(sentinel);
+    sentinel->jobid = 72011;
+    j->job.pidinfo  = sentinel;
+
+    wal_jobstate_t js = { .jobid = 72011, .state = JOB_STAT_RUN, ._pad = 0 };
+
+    xce_add_hook(&g_wjs_c.hooksys, XCE_CONTROLLER_HOOK_JOB,
+                wjs_detail_spy_hook, NULL);
+    xce_add_hook(&g_wjs_c.hooksys, XCE_CONTROLLER_HOOK_JOB, wjs_spy_hook,
+                NULL);
+
+    int rc = apply_committed_entry(&g_wjs_p, WAL_JOB_START, 211, &js,
+                                   sizeof(js));
+
+    TEST_ASSERT_EQUAL_INT(0, rc);
+    TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
+    TEST_ASSERT_EQUAL_INT_MESSAGE(0, g_wjs_start_hook_fires,
+        "bug-1731 NULL-safety regression guard: even with j->job.pidinfo "
+        "ALREADY non-NULL from a simulated prior apply, an old-format "
+        "WAL_JOB_START payload that decodes NO pidinfo THIS call must NOT "
+        "fire HOOK_DETAIL_JOB_START -- proves the gate is a call-scoped "
+        "decode flag, not `j->job.pidinfo != NULL` (which would misfire "
+        "here and, in production, crash sched_job_start_fun's unconditional "
+        "info->jobid dereference)");
+    TEST_ASSERT_EQUAL_INT_MESSAGE(1, g_wjs_hook_fires,
+        "the pre-existing HOOK_DETAIL_JOB_UPDATE fire must still happen for "
+        "this genuine forward (PEND -> RUN) transition");
+
+    xce_disable_hook(&g_wjs_c.hooksys, XCE_CONTROLLER_HOOK_JOB,
+                     wjs_detail_spy_hook);
+    wjs_teardown();
+    printf(
+        "test_wjs_apply_committed_entry_old_format_no_job_start_hook: "
+        "PASS\n");
+}
+
 /* ── apply_wal_entry(): standby catch-up / replicated-apply dispatch ────── */
 
 /* bug-1697: renamed from test_wjs_apply_wal_entry_sets_pidinfo_and_start_
@@ -957,6 +1133,8 @@ void test_wal_job_start_fact(void)
     RUN_TEST(test_wjs_apply_committed_entry_backward_compat_old_payload);
     RUN_TEST(
         test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_dispatch);
+    RUN_TEST(test_wjs_apply_committed_entry_fires_job_start_hook_with_pidinfo);
+    RUN_TEST(test_wjs_apply_committed_entry_old_format_no_job_start_hook);
     RUN_TEST(test_wjs_apply_wal_entry_sets_pidinfo_but_not_start_time_no_hook);
     RUN_TEST(test_wjs_apply_wal_entry_backward_compat_old_payload);
     RUN_TEST(test_wjs_restart_replay_recovers_pidinfo_but_not_start_time);

src/frontend/apiserver/backend/handler.go

@@ -84,9 +84,19 @@ func (h *DefaultHandler) OnJobDeleted(jobid uint64) {
 	store.Jobs.Delete(jobid)
 }
 
+// bug-1731: previously permanently starved of data -- apply_committed_entry()
+// (persist.c) never fired the controller-side HOOK_DETAIL_JOB_EXIT this
+// method's C caller (apiserver_job_exit_fun -> NotifyData_data_jobFinishInfo)
+// depends on, so OnJobFinished was live, wired, and correct but never once
+// invoked in production. Logs at Info (mirroring this file's existing
+// "job array push received and expanded" convention) so a finished job's
+// terminal-state push to the apiserver is directly observable in
+// apiserver.log, not just inferable from store state.
 func (h *DefaultHandler) OnJobFinished(jobid uint64, exitCode int) {
 	existing, ok := store.Jobs.Get(jobid)
 	if !ok {
+		logger.Info("OnJobFinished: jobid not found in store, ignoring",
+			zap.Uint64("jobid", jobid), zap.Int("exit_code", exitCode))
 		return
 	}
 	if exitCode == 0 {
@@ -95,6 +105,9 @@ func (h *DefaultHandler) OnJobFinished(jobid uint64, exitCode int) {
 		existing.JobStatus = models.JOBSTAT["EXIT"]
 	}
 	store.Jobs.Put(jobid, existing)
+	logger.Info("OnJobFinished: job status updated",
+		zap.Uint64("jobid", jobid), zap.Int("exit_code", exitCode),
+		zap.Int("job_status", existing.JobStatus))
 }
 
 func (h *DefaultHandler) OnQueueUpdated(queue *models.QueueInfo) {

src/scheduler/src/main.c

@@ -271,6 +271,17 @@ int main(int argc, char* argv[])
         loglevel = verbose_to_loglevel(arguments.verbose);
     }
 
+    /* DEBUG3 produces order-of-magnitude more log volume than the default
+     * size/count budget below is sized for, so tlog's own rotation can
+     * gzip away the window a bug occurred in well before anyone gets a
+     * chance to look (bug-1731: the primary's log for the exact moment a
+     * race fired had already rotated out). Give DEBUG3 runs a much larger
+     * retention budget so a targeted repro survives to be inspected. */
+    if (strcmp(loglevel, "debug3") == 0) {
+        logsize  *= 8;
+        logcount *= 4;
+    }
+
     /* Req 5 AC 10 (scheduler-core spec, task 9.1): --record-dir is the
      * ONLY way record_dir is ever provisioned -- see this flag's
      * options[] entry above and scheduler.h's field comment. */