From ebe691c3ed543b16052c7bbc50ca06fe677db8d8 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Sat, 29 Aug 2026 11:29:10 +0000 Subject: [PATCH] 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 Claude-Session: https://claude.ai/code/session_019QxaSzHRB7pmYFp4cVnwkA --- src/controller/job.c | 7 + src/controller/main.c | 11 + src/controller/persist.c | 91 +++++++- src/controller/sched.c | 18 ++ .../test_apply_reapply_idempotency.c | 16 +- .../testsuite/test_wal_job_finish_fact.c | 182 +++++++++++++++- .../testsuite/test_wal_job_start_fact.c | 194 +++++++++++++++++- src/frontend/apiserver/backend/handler.go | 13 ++ src/scheduler/src/main.c | 11 + 9 files changed, 521 insertions(+), 22 deletions(-) diff --git a/src/controller/job.c b/src/controller/job.c index e460b608..30177b45 100644 --- a/src/controller/job.c +++ b/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); diff --git a/src/controller/main.c b/src/controller/main.c index 82e4aec9..1fb1d81c 100644 --- a/src/controller/main.c +++ b/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) { diff --git a/src/controller/persist.c b/src/controller/persist.c index 6fea4124..9e3076d4 100644 --- a/src/controller/persist.c +++ b/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) - return 0; /* rejected-backward / no-op-duplicate — no hook */ + /* bug-1731: this gate used to be a flat `result != APPLIED` early + * 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; } diff --git a/src/controller/sched.c b/src/controller/sched.c index 36a916be..efe37cda 100644 --- a/src/controller/sched.c +++ b/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)); diff --git a/src/controller/testsuite/test_apply_reapply_idempotency.c b/src/controller/testsuite/test_apply_reapply_idempotency.c index af7a2f76..9878879b 100644 --- a/src/controller/testsuite/test_apply_reapply_idempotency.c +++ b/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, - "FINISH must fire exactly one notification (SUBMIT's + FINISH's = " - "2 total so far)"); + TEST_ASSERT_EQUAL_INT_MESSAGE(3, g_tari_hook_fires, + "bug-1731: a genuine forward WAL_JOB_FINISH transition now fires " + "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, - "the stale, guard-rejected START must fire NO notification — the " - "count must stay exactly where FINISH left it"); + TEST_ASSERT_EQUAL_INT_MESSAGE(3, g_tari_hook_fires, + "the stale, guard-rejected START must fire NO notification -- no " + "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_" diff --git a/src/controller/testsuite/test_wal_job_finish_fact.c b/src/controller/testsuite/test_wal_job_finish_fact.c index 50c41450..f7c663dd 100644 --- a/src/controller/testsuite/test_wal_job_finish_fact.c +++ b/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, - "a forward WAL_JOB_FINISH transition must still fire exactly one " - "notification"); + TEST_ASSERT_EQUAL_INT_MESSAGE(2, g_wjf_hook_fires, + "bug-1731: a forward WAL_JOB_FINISH transition now fires TWO " + "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); diff --git a/src/controller/testsuite/test_wal_job_start_fact.c b/src/controller/testsuite/test_wal_job_start_fact.c index 55aba60b..023e2284 100644 --- a/src/controller/testsuite/test_wal_job_start_fact.c +++ b/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, - "a forward WAL_JOB_START transition must still fire exactly one " - "notification"); + TEST_ASSERT_EQUAL_INT_MESSAGE(2, g_wjs_hook_fires, + "bug-1731: a forward WAL_JOB_START transition with trailing pidinfo " + "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, - "this transition is a confirmed NOOP_DUPLICATE (state already RUN " - "from dispatch) -- no forward-transition hook fires, exactly like " - "every other job reaching WAL_JOB_START in production today"); + TEST_ASSERT_EQUAL_INT_MESSAGE(1, g_wjs_hook_fires, + "bug-1731: this transition is a confirmed NOOP_DUPLICATE (state " + "already RUN from dispatch), so HOOK_DETAIL_JOB_UPDATE does NOT " + "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); diff --git a/src/frontend/apiserver/backend/handler.go b/src/frontend/apiserver/backend/handler.go index 713f18c2..0fcec604 100644 --- a/src/frontend/apiserver/backend/handler.go +++ b/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) { diff --git a/src/scheduler/src/main.c b/src/scheduler/src/main.c index af677404..d9f68f62 100644 --- a/src/scheduler/src/main.c +++ b/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. */