lei.chen/myxce
1
0
Fork 1
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

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

Browse source 
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
This commit is contained in:
Rongsong Shen 2026-08-29 11:29:10 +00:00
parent 42e1eeaa29
commit ebe691c3ed
No known key found for this signature in database
GPG key ID: 5BCDAAE0123E9FE2
9 changed files with 521 additions and 22 deletions
Download patch file Download diff file Expand all files Collapse all files

7
src/controller/job.c
View file

@ -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);

11
src/controller/main.c
View file

@ -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) {

91
src/controller/persist.c
View file

@ -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;
}

18
src/controller/sched.c
View file

@ -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));

16
src/controller/testsuite/test_apply_reapply_idempotency.c
View file

@ -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_"

182
src/controller/testsuite/test_wal_job_finish_fact.c
View file

@ -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);

194
src/controller/testsuite/test_wal_job_start_fact.c
View file

@ -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);

13
src/frontend/apiserver/backend/handler.go
View file

@ -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) {

11
src/scheduler/src/main.c
View file

@ -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. */