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

fix(controller): job.start_time never set -- dispatch/WAL_JOB_START RUN-state collision (bug-1697)

Browse source 
dispatch_a_job_() synchronously sets state=JOB_STAT_RUN at dispatch time
(scheduler-dispatch-commit task 3.1's deliberate no-worker-ack-wait
semantic). By the time the worker's later WAL_JOB_START fact commits,
apply_job_update_transition() sees state already == RUN and returns
NOOP_DUPLICATE instead of APPLIED -- so bug-1687's start_time/pidinfo
decode/adopt block, gated on result==APPLIED, could never run for any
job. start_time (and consequently run_time) stayed 0 forever. Same bug
class already fixed for WAL_JOB_RUSAGE/CKPT/PREASON in this identical
apply function; WAL_JOB_START was missed because bug-1687 predated the
dispatch-time RUN semantic change.

Moves start_time to dispatch-owned: dispatch_a_job_() now stamps
job.start_time alongside state=RUN, under the same write lock.
WAL_JOB_DISPATCH gains a flag-gated (WAL_JOB_DISPATCH_HAS_START_TIME_FLAG)
start_time field so it survives replay/restart; both apply seams
(apply_committed_entry, apply_wal_entry) and restore_job_dispatch_state
decode it when present, falling through to the old alloc-only shape
otherwise. WAL_JOB_START's own now-permanently-dead start_time write is
removed; pidinfo adoption made unconditional to match.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01AgYRU3zDTqNGV5Jk8aiKLg
This commit is contained in:
Rongsong Shen 2026-08-27 08:25:40 +00:00
parent faedc6fc49
commit ac1e312e2f
No known key found for this signature in database
GPG key ID: 5BCDAAE0123E9FE2
9 changed files with 859 additions and 184 deletions
Download patch file Download diff file Expand all files Collapse all files

23
src/controller/testsuite/test_apply_committed_entry.c
View file

@ -403,7 +403,15 @@ test_ace_job_state_transition_rejects_backward_suppresses_notify(void)
"notify: PASS\n");
}
static void test_ace_job_start_sets_start_time(void)
/* bug-1697: renamed from test_ace_job_start_sets_start_time -- start_time is
* no longer WAL_JOB_START's to set at all (the old "fabricate time(NULL) at
* apply time" fallback for a bare/old-format payload is removed entirely).
* job.start_time is now exclusively DISPATCH-owned (WAL_JOB_DISPATCH, see
* wal_types.h's WAL_JOB_START doc comment for the full rationale), so this
* test now proves the opposite of what it used to: a WAL_JOB_START apply
* must leave start_time untouched, even for a genuine PEND->RUN forward
* transition. */
static void test_ace_job_start_leaves_start_time_untouched(void)
{
tace_setup();
@ -414,19 +422,18 @@ static void test_ace_job_start_sets_start_time(void)
wal_jobstate_t js = { .jobid = 603, .state = JOB_STAT_RUN };
time_t before = time(NULL);
int rc = apply_committed_entry(&g_tace_p, WAL_JOB_START, 22, &js,
sizeof(js));
time_t after = time(NULL);
TEST_ASSERT_EQUAL_INT(0, rc);
TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
TEST_ASSERT_TRUE_MESSAGE(
(j->job.start_time >= before) && (j->job.start_time <= after),
"WAL_JOB_START must stamp start_time to the apply-time clock");
TEST_ASSERT_EQUAL_UINT64_MESSAGE(0, (uint64_t)j->job.start_time,
"bug-1697: WAL_JOB_START must leave start_time untouched (no more "
"apply-time time(NULL) fabrication) -- dispatch is the only owner "
"of this field now");
tace_teardown();
printf("test_ace_job_start_sets_start_time: PASS\n");
printf("test_ace_job_start_leaves_start_time_untouched: PASS\n");
}
static void test_ace_job_finish_sets_finish_time_and_run_time(void)
@ -1097,7 +1104,7 @@ void test_apply_committed_entry(void)
RUN_TEST(test_ace_job_submit_duplicate_is_noop_no_extra_notify);
RUN_TEST(test_ace_job_state_transition_applies_forward_and_notifies);
RUN_TEST(test_ace_job_state_transition_rejects_backward_suppresses_notify);
RUN_TEST(test_ace_job_start_sets_start_time);
RUN_TEST(test_ace_job_start_leaves_start_time_untouched);
RUN_TEST(test_ace_job_finish_sets_finish_time_and_run_time);
RUN_TEST(test_ace_queue_ctrl_updates_and_notifies);
RUN_TEST(test_ace_worker_ctrl_join_restores_and_notifies);

68
src/controller/testsuite/test_dispatch_commit.c
View file

@ -274,6 +274,60 @@ static void test_dc_success_commits_alloc_state_and_resets_counter(void)
printf("test_dc_success_commits_alloc_state_and_resets_counter: PASS\n");
}
#define DC_JOBID_START_TIME 91005ULL
/* bug-1697's core RED/GREEN proof for the "start_time is dispatch-owned
* now" half of the fix: a successful dispatch must stamp job.start_time
* synchronously, in the SAME lock-held operation that sets job.state =
* JOB_STAT_RUN and commits job.allocs -- no WAL commit/apply round trip
* needed, since this is a plain in-memory write under the job's own write
* lock. RED against the pre-fix code: j->job.start_time stays 0 forever
* (dispatch_a_job_() never touched it, and WAL_JOB_START's own adoption is
* permanently dead per bug-1697's root cause, so nothing else ever sets
* it either). GREEN after the fix: job.start_time is nonzero immediately
* after dispatch_a_job_test() returns. */
static void test_dc_success_stamps_start_time_synchronously(void)
{
job_t* j;
xce_job_alloc_t* alloc;
int rc;
time_t before, after;
dc_setup();
j = dc_seed_ready(DC_JOBID_START_TIME, 0, "dq", "wkr-dc-start-time");
TEST_ASSERT_EQUAL_UINT64_MESSAGE(0, (uint64_t)j->job.start_time,
"fixture must seed a job with start_time still at its zero-"
"initialized default");
alloc = make_job_alloc(DC_JOBID_START_TIME, 1,
make_host_allocs(1,
make_host_alloc((char*)"wkr-dc-start-time", 1,
make_allocs(1,
make_alloc((char*)"slots", NULL, 0, 1.0f, 0)))));
TEST_ASSERT_NOT_NULL(alloc);
before = time(NULL);
rc = dispatch_a_job_test(&g_dc, NULL, alloc);
after = time(NULL);
TEST_ASSERT_TRUE_MESSAGE(rc >= 0,
"a dispatch to a live, no-iomgr worker endpoint must succeed");
TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
TEST_ASSERT_NOT_EQUAL_MESSAGE(0, (uint64_t)j->job.start_time,
"bug-1697: a successful dispatch must stamp job.start_time "
"synchronously -- it must never be left at 0");
TEST_ASSERT_TRUE_MESSAGE(
(j->job.start_time >= before) && (j->job.start_time <= after),
"job.start_time must be the dispatch-time clock, captured within "
"this call's own [before, after] window");
free_JobAlloc_ptr(&alloc);
dc_drain_ep(&g_dc_worker_ep);
dc_teardown();
printf("test_dc_success_stamps_start_time_synchronously: PASS\n");
}
/* bug-1679: spy hook counting HOOK_AFTER_EVENT/HOOK_DETAIL_JOB_UPDATE fires
* specifically -- the exact hook apiserver_job_update_fun (apiserver.c)
* subscribes to in production to push a job's current state to every
@ -506,7 +560,9 @@ static int dc_encode_job(const xce_job_t* j, uint8_t** out, size_t* out_len)
static void test_dc_success_appends_wal_job_dispatch_durably(void)
{
char tmp[256];
char tmp[256];
time_t captured_start_time = 0; /* bug-1697: set in Phase 1, checked
* against Phase 2's recovered value */
strcpy(tmp, "/tmp/xce_dc31_replay_XXXXXX");
TEST_ASSERT_NOT_NULL(mkdtemp(tmp));
@ -637,6 +693,10 @@ static void test_dc_success_appends_wal_job_dispatch_durably(void)
rc = dispatch_a_job_test(&c, NULL, alloc);
TEST_ASSERT_TRUE(rc >= 0);
TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
TEST_ASSERT_NOT_EQUAL_MESSAGE(0, (uint64_t)j->job.start_time,
"bug-1697: a successful dispatch must stamp job.start_time "
"synchronously");
captured_start_time = j->job.start_time;
TEST_ASSERT_EQUAL_INT(0, persist_flush(&c.persist));
@ -683,6 +743,11 @@ static void test_dc_success_appends_wal_job_dispatch_durably(void)
"restart replay must recover the job as RUNNING from the "
"WAL_JOB_DISPATCH fact appended by dispatch_a_job_()'s real "
"success path -- no WAL_JOB_START anywhere in this log");
TEST_ASSERT_EQUAL_UINT64_MESSAGE((uint64_t)captured_start_time,
(uint64_t)j2->job.start_time,
"bug-1697: restart replay must recover the exact dispatch-time "
"start_time stamped by the real dispatch_a_job_() call in "
"Phase 1, from the WAL_JOB_DISPATCH fact's extended payload");
/* bug-1678: restart replay must recover not just STATE but the
* resource allocation itself, or EXEC_HOST is permanently blank for
@ -731,6 +796,7 @@ void test_dispatch_commit(void)
"5.1)\n\n");
RUN_TEST(test_dc_success_commits_alloc_state_and_resets_counter);
RUN_TEST(test_dc_success_stamps_start_time_synchronously);
RUN_TEST(test_dc_success_notifies_job_update_hook_exactly_once);
RUN_TEST(test_dc_worker_not_found_leaves_job_pend_and_alloc_uncommitted);
RUN_TEST(test_dc_success_appends_wal_job_dispatch_durably);

4
src/controller/testsuite/test_repl_apply.c
View file

@ -52,9 +52,9 @@ int restore_job_state(cluster_t* c, uint64_t jobid, uint32_t state)
__attribute__((weak))
int restore_job_dispatch_state(cluster_t* c, uint64_t jobid, uint32_t state,
xce_job_alloc_t* alloc)
uint64_t start_time, xce_job_alloc_t* alloc)
{
(void)c; (void)jobid; (void)state; (void)alloc;
(void)c; (void)jobid; (void)state; (void)start_time; (void)alloc;
return 0;
}

149
src/controller/testsuite/test_wal_job_dispatch_fact.c
View file

@ -162,13 +162,21 @@ static void test_wjd_apply_committed_entry_transitions_pend_to_run(void)
printf("test_wjd_apply_committed_entry_transitions_pend_to_run: PASS\n");
}
/* bug-1678: build a wal_jobstate_t header + trailing Cap'n Proto JobAlloc
* bytes -- persist_submit_job_dispatch_fact()'s payload shape -- mirroring
/* bug-1678 (extended bug-1697): build a wal_jobstate_t header + optional
* fixed uint64_t start_time + trailing Cap'n Proto JobAlloc bytes --
* persist_submit_job_dispatch_fact()'s payload shape -- mirroring
* capnp_encode_joballoc (persist.c, file-static) since job.c/persist.c's own
* static helpers aren't linkable from a test TU. Caller owns *out. */
static int wjd_build_dispatch_payload(uint64_t jobid, uint32_t state,
xce_job_alloc_t* alloc,
uint8_t** out, size_t* out_len)
* static helpers aren't linkable from a test TU. Caller owns *out.
* `has_start_time` sets WAL_JOB_DISPATCH_HAS_START_TIME_FLAG in _pad and
* inserts `start_time` between the header and the JobAlloc bytes (the
* post-bug-1697 shape); when false, `start_time` is ignored and the payload
* is exactly the pre-bug-1697 shape (header immediately followed by
* JobAlloc bytes, _pad=0). */
static int wjd_build_dispatch_payload_ex(uint64_t jobid, uint32_t state,
bool has_start_time,
uint64_t start_time,
xce_job_alloc_t* alloc,
uint8_t** out, size_t* out_len)
{
struct capn c;
struct capn_segment* cs;
@ -176,7 +184,12 @@ static int wjd_build_dispatch_payload(uint64_t jobid, uint32_t state,
JobAlloc_ptr jap;
uint8_t* allocbuf;
size_t alloclen;
wal_jobstate_t js = { .jobid = jobid, .state = state, ._pad = 0 };
size_t start_field = has_start_time ? sizeof(start_time)
: 0;
wal_jobstate_t js = { .jobid = jobid, .state = state,
._pad = has_start_time
? WAL_JOB_DISPATCH_HAS_START_TIME_FLAG
: 0 };
capn_init_malloc(&c);
cs = capn_root(&c).seg;
@ -191,15 +204,27 @@ static int wjd_build_dispatch_payload(uint64_t jobid, uint32_t state,
capn_write_mem(&c, allocbuf, alloclen, 0);
capn_free(&c);
*out_len = sizeof(js) + alloclen;
*out_len = sizeof(js) + start_field + alloclen;
*out = malloc(*out_len);
if (!*out) { free(allocbuf); return -ENOMEM; }
memcpy(*out, &js, sizeof(js));
memcpy(*out + sizeof(js), allocbuf, alloclen);
if (has_start_time)
memcpy(*out + sizeof(js), &start_time, sizeof(start_time));
memcpy(*out + sizeof(js) + start_field, allocbuf, alloclen);
free(allocbuf);
return 0;
}
/* Pre-bug-1697 shape wrapper -- every call site that predates the start_time
* field keeps working unchanged. */
static int wjd_build_dispatch_payload(uint64_t jobid, uint32_t state,
xce_job_alloc_t* alloc,
uint8_t** out, size_t* out_len)
{
return wjd_build_dispatch_payload_ex(jobid, state, false, 0, alloc, out,
out_len);
}
/* One host ("wjd-worker"), one resource ("slots", value 1.0) -- the same
* minimal shape test_dispatch_commit.c's own dispatch tests use. Caller owns
* the result (release via free_JobAlloc_ptr). */
@ -242,12 +267,60 @@ static void test_wjd_apply_committed_entry_transitions_and_sets_allocs(void)
TEST_ASSERT_EQUAL_STRING("wjd-worker", j->job.allocs->allocs[0]->host);
TEST_ASSERT_EQUAL_STRING("slots",
j->job.allocs->allocs[0]->allocs[0]->resname);
TEST_ASSERT_EQUAL_UINT64_MESSAGE(0, (uint64_t)j->job.start_time,
"bug-1697 backward compat: a pre-bug-1697 WAL_JOB_DISPATCH payload "
"(no WAL_JOB_DISPATCH_HAS_START_TIME_FLAG, header+allocs only) must "
"leave job.start_time untouched -- no crash, no misread of absent "
"start_time bytes");
wjd_teardown();
printf("test_wjd_apply_committed_entry_transitions_and_sets_allocs: "
"PASS\n");
}
/* bug-1697: WAL_JOB_DISPATCH_HAS_START_TIME_FLAG set -- the post-fix shape
* carrying a fixed uint64_t start_time between the header and the trailing
* JobAlloc bytes. Proves apply_committed_entry() decodes/adopts it. */
static void test_wjd_apply_committed_entry_sets_start_time_and_allocs(void)
{
wjd_setup();
job_t* j = wjd_seed_job(71007, JOB_STAT_PEND);
TEST_ASSERT_NOT_NULL(j);
xce_job_alloc_t* alloc = wjd_make_test_alloc(71007);
TEST_ASSERT_NOT_NULL(alloc);
uint64_t wire_start_time = 1700000123ULL;
uint8_t* payload = NULL;
size_t plen = 0;
TEST_ASSERT_EQUAL_INT(0,
wjd_build_dispatch_payload_ex(71007, JOB_STAT_RUN, true,
wire_start_time, alloc, &payload,
&plen));
free_JobAlloc_ptr(&alloc);
int rc = apply_committed_entry(&g_wjd_p, WAL_JOB_DISPATCH, 104, 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_UINT64_MESSAGE(wire_start_time,
(uint64_t)j->job.start_time,
"bug-1697: a WAL_JOB_DISPATCH payload with "
"WAL_JOB_DISPATCH_HAS_START_TIME_FLAG set must adopt the "
"wire-carried start_time, not leave it at 0");
TEST_ASSERT_NOT_NULL_MESSAGE(j->job.allocs,
"job.allocs must still be recovered alongside start_time");
TEST_ASSERT_EQUAL_INT(1, j->job.allocs->nhosts);
TEST_ASSERT_EQUAL_STRING("wjd-worker", j->job.allocs->allocs[0]->host);
wjd_teardown();
printf("test_wjd_apply_committed_entry_sets_start_time_and_allocs: "
"PASS\n");
}
/* ── apply_wal_entry(): standby catch-up / replicated-apply dispatch ────── */
static void
@ -309,11 +382,54 @@ static void test_wjd_apply_wal_entry_transitions_and_sets_allocs(void)
"primary's own boot replay");
TEST_ASSERT_EQUAL_INT(1, j->job.allocs->nhosts);
TEST_ASSERT_EQUAL_STRING("wjd-worker", j->job.allocs->allocs[0]->host);
TEST_ASSERT_EQUAL_UINT64_MESSAGE(0, (uint64_t)j->job.start_time,
"bug-1697 backward compat: a pre-bug-1697 WAL_JOB_DISPATCH payload "
"must leave job.start_time untouched on this seam too");
wjd_teardown();
printf("test_wjd_apply_wal_entry_transitions_and_sets_allocs: PASS\n");
}
/* bug-1697: sibling of test_wjd_apply_committed_entry_sets_start_time_and_
* allocs, for apply_wal_entry's standby catch-up / replicated-apply seam. */
static void test_wjd_apply_wal_entry_sets_start_time_and_allocs(void)
{
wjd_setup();
job_t* j = wjd_seed_job(71008, JOB_STAT_PEND);
TEST_ASSERT_NOT_NULL(j);
xce_job_alloc_t* alloc = wjd_make_test_alloc(71008);
TEST_ASSERT_NOT_NULL(alloc);
uint64_t wire_start_time = 1700000456ULL;
uint8_t* payload = NULL;
size_t plen = 0;
TEST_ASSERT_EQUAL_INT(0,
wjd_build_dispatch_payload_ex(71008, JOB_STAT_RUN, true,
wire_start_time, alloc, &payload,
&plen));
free_JobAlloc_ptr(&alloc);
int rc = apply_wal_entry(&g_wjd_p, WAL_JOB_DISPATCH, 105, 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_UINT64_MESSAGE(wire_start_time,
(uint64_t)j->job.start_time,
"bug-1697: apply_wal_entry's catch-up dispatch must also recover "
"the wire-carried start_time when "
"WAL_JOB_DISPATCH_HAS_START_TIME_FLAG is set, required for a "
"promoted standby");
TEST_ASSERT_NOT_NULL(j->job.allocs);
TEST_ASSERT_EQUAL_INT(1, j->job.allocs->nhosts);
wjd_teardown();
printf("test_wjd_apply_wal_entry_sets_start_time_and_allocs: PASS\n");
}
/* ── Restart-replay Observable (this task's completion criterion) ───────── */
static persist_t* wjd_make_fresh_persist(const char* tmpdir)
@ -498,11 +614,15 @@ test_wjd_restart_replay_recovers_running_and_allocs_with_dispatch_fact(void)
xce_job_alloc_t* alloc = wjd_make_test_alloc(71006);
TEST_ASSERT_NOT_NULL(alloc);
/* bug-1697: new-format payload (WAL_JOB_DISPATCH_HAS_START_TIME_
* FLAG set), so this restart-replay test also proves start_time
* -- not just allocs -- survives a real restart. */
uint8_t* dispatch_payload = NULL;
size_t dispatch_plen = 0;
TEST_ASSERT_EQUAL_INT(0,
wjd_build_dispatch_payload(71006, JOB_STAT_RUN, alloc,
&dispatch_payload, &dispatch_plen));
wjd_build_dispatch_payload_ex(71006, JOB_STAT_RUN, true,
71006000ULL, alloc,
&dispatch_payload, &dispatch_plen));
free_JobAlloc_ptr(&alloc);
TEST_ASSERT_EQUAL_INT(0,
@ -537,6 +657,11 @@ test_wjd_restart_replay_recovers_running_and_allocs_with_dispatch_fact(void)
TEST_ASSERT_EQUAL_INT(1, j->job.allocs->nhosts);
TEST_ASSERT_EQUAL_STRING("wjd-worker",
j->job.allocs->allocs[0]->host);
TEST_ASSERT_EQUAL_UINT64_MESSAGE(71006000ULL,
(uint64_t)j->job.start_time,
"bug-1697: restart replay must also recover the dispatch-time "
"start_time from the WAL_JOB_DISPATCH fact's wire-carried "
"field, not leave it at 0");
wjd_teardown();
wjd_teardown_persist(p2);
@ -558,8 +683,10 @@ void test_wal_job_dispatch_fact(void)
UnitySetTestFile(__FILE__);
RUN_TEST(test_wjd_apply_committed_entry_transitions_pend_to_run);
RUN_TEST(test_wjd_apply_committed_entry_transitions_and_sets_allocs);
RUN_TEST(test_wjd_apply_committed_entry_sets_start_time_and_allocs);
RUN_TEST(test_wjd_apply_wal_entry_transitions_pend_to_run_no_hook);
RUN_TEST(test_wjd_apply_wal_entry_transitions_and_sets_allocs);
RUN_TEST(test_wjd_apply_wal_entry_sets_start_time_and_allocs);
RUN_TEST(test_wjd_restart_replay_recovers_running_without_start_fact);
RUN_TEST(
test_wjd_restart_replay_recovers_running_and_allocs_with_dispatch_fact);

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

@ -215,12 +215,25 @@ static void wjs_assert_pidinfo_matches(job_pidinfo_t* got, uint64_t jobid)
/* ── apply_committed_entry(): live-commit apply / boot replay dispatch ──── */
static void test_wjs_apply_committed_entry_sets_pidinfo_and_start_time(void)
/* bug-1697: renamed from test_wjs_apply_committed_entry_sets_pidinfo_and_
* start_time -- start_time is no longer WAL_JOB_START's to set (dispatch
* owns it now, see wal_types.h's WAL_JOB_START doc comment), so this test
* now proves the opposite of what it used to for that one field: pidinfo
* is still adopted, but start_time is left exactly as it was before the
* apply, even though the wire payload carries a (now-ignored)
* wire_start_time. This job is seeded PEND, so apply_job_update_
* transition() still reports a genuine forward transition here (result ==
* JOB_TRANSITION_APPLIED) -- the NOOP-collision scenario (job already RUN
* from a prior dispatch) is covered separately by
* test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_
* dispatch below. */
static void test_wjs_apply_committed_entry_sets_pidinfo_but_not_start_time(void)
{
wjs_setup();
job_t* j = wjs_seed_job(72001, JOB_STAT_PEND);
TEST_ASSERT_NOT_NULL(j);
time_t start_time_before = j->job.start_time;
job_pidinfo_t info = wjs_make_test_pidinfo(72001);
uint64_t wire_start_time = 1700000001ULL;
@ -240,20 +253,29 @@ static void test_wjs_apply_committed_entry_sets_pidinfo_and_start_time(void)
TEST_ASSERT_EQUAL_INT(0, rc);
TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
TEST_ASSERT_EQUAL_UINT64_MESSAGE(wire_start_time,
TEST_ASSERT_EQUAL_UINT64_MESSAGE((uint64_t)start_time_before,
(uint64_t)j->job.start_time,
"WAL_JOB_START must adopt the wire-carried start_time (bug-1687), "
"not fabricate time(NULL) when one is present");
"bug-1697: WAL_JOB_START must NOT adopt its wire-carried "
"start_time any more -- job.start_time is exclusively "
"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");
wjs_teardown();
printf("test_wjs_apply_committed_entry_sets_pidinfo_and_start_time: "
printf("test_wjs_apply_committed_entry_sets_pidinfo_but_not_start_time: "
"PASS\n");
}
/* bug-1697: renamed/updated -- an old-format (exactly sizeof(wal_jobstate_t))
* WAL_JOB_START payload used to fabricate start_time = time(NULL) at apply
* time; that fabrication is removed entirely now (dispatch owns
* start_time), so this backward-compat test instead proves start_time is
* left completely untouched (matching the new-format case's behavior
* above) and pidinfo still decodes safely as NULL for an old-format
* payload with no trailing bytes at all. */
static void
test_wjs_apply_committed_entry_backward_compat_old_payload(void)
{
@ -263,21 +285,20 @@ test_wjs_apply_committed_entry_backward_compat_old_payload(void)
TEST_ASSERT_NOT_NULL(j);
TEST_ASSERT_NULL_MESSAGE(j->job.pidinfo,
"fixture must seed a job with pidinfo still unset");
j->job.start_time = 54321; /* sentinel -- must survive untouched */
wal_jobstate_t js = { .jobid = 72002, .state = JOB_STAT_RUN, ._pad = 0 };
time_t before = time(NULL);
int rc = apply_committed_entry(&g_wjs_p, WAL_JOB_START, 201, &js,
sizeof(js));
time_t after = time(NULL);
TEST_ASSERT_EQUAL_INT(0, rc);
TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
TEST_ASSERT_TRUE_MESSAGE(
(j->job.start_time >= before) && (j->job.start_time <= after),
"an old-format (exactly sizeof(wal_jobstate_t)) WAL_JOB_START "
"payload must still fabricate start_time at apply time, unchanged "
"from before this fix");
TEST_ASSERT_EQUAL_UINT64_MESSAGE(54321, (uint64_t)j->job.start_time,
"bug-1697: an old-format (exactly sizeof(wal_jobstate_t)) "
"WAL_JOB_START payload must leave start_time untouched -- the old "
"fabricate-time(NULL) fallback is removed entirely now that "
"dispatch owns start_time");
TEST_ASSERT_NULL_MESSAGE(j->job.pidinfo,
"an old-format WAL_JOB_START payload must leave pidinfo NULL -- no "
"crash, no misread of absent trailing bytes");
@ -287,15 +308,85 @@ test_wjs_apply_committed_entry_backward_compat_old_payload(void)
"PASS\n");
}
/* bug-1697's CORE regression test: reproduces the exact live, 100%-
* reproducing collision. dispatch_a_job_() (job.c) now sets job.state =
* JOB_STAT_RUN synchronously at DISPATCH time -- so by the time the
* worker's LATER WAL_JOB_START fact applies, the job is ALREADY RUN and
* apply_job_update_transition() reports JOB_TRANSITION_NOOP_DUPLICATE
* (job.c:2795-2799), never JOB_TRANSITION_APPLIED. Before this fix,
* pidinfo adoption was gated on result==JOB_TRANSITION_APPLIED, so it could
* NEVER run for a real job (every real job reaches WAL_JOB_START only
* after DISPATCH already set it RUN) -- RED against the pre-fix code:
* j->job.pidinfo stays NULL and g_wjs_hook_fires stays 0. GREEN after the
* fix: pidinfo decode/adopt is unconditional (mirroring RUSAGE/CKPT/
* PREASON), so it adopts here despite the confirmed NOOP transition, while
* 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. */
static void
test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_dispatch(void)
{
wjs_setup();
job_t* j = wjs_seed_job(72007, JOB_STAT_RUN); /* already RUN, as if
* dispatch_a_job_()
* already ran */
TEST_ASSERT_NOT_NULL(j);
TEST_ASSERT_NULL_MESSAGE(j->job.pidinfo,
"fixture must seed a job with pidinfo still unset");
j->job.start_time = 999000111; /* the dispatch-time value -- must
* survive untouched */
job_pidinfo_t info = wjs_make_test_pidinfo(72007);
uint64_t wire_start_time = 1800000007ULL; /* a LATER, different worker-
* ack time -- must be
* ignored, not adopted */
uint8_t* payload = NULL;
size_t plen = 0;
TEST_ASSERT_EQUAL_INT(0,
wjs_build_start_payload(72007, JOB_STAT_RUN, wire_start_time, &info,
&payload, &plen));
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, 208, payload,
(uint32_t)plen);
free(payload);
TEST_ASSERT_EQUAL_INT(0, rc);
TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
wjs_assert_pidinfo_matches(j->job.pidinfo, 72007);
TEST_ASSERT_EQUAL_UINT64_MESSAGE(999000111, (uint64_t)j->job.start_time,
"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");
wjs_teardown();
printf(
"test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_"
"from_dispatch: PASS\n");
}
/* ── apply_wal_entry(): standby catch-up / replicated-apply dispatch ────── */
/* bug-1697: renamed from test_wjs_apply_wal_entry_sets_pidinfo_and_start_
* time_no_hook -- start_time is no longer WAL_JOB_START's to set on this
* seam either (dispatch owns it now); pidinfo is still recovered. */
static void
test_wjs_apply_wal_entry_sets_pidinfo_and_start_time_no_hook(void)
test_wjs_apply_wal_entry_sets_pidinfo_but_not_start_time_no_hook(void)
{
wjs_setup();
job_t* j = wjs_seed_job(72003, JOB_STAT_PEND);
TEST_ASSERT_NOT_NULL(j);
time_t start_time_before = j->job.start_time;
job_pidinfo_t info = wjs_make_test_pidinfo(72003);
uint64_t wire_start_time = 1700000003ULL;
@ -315,19 +406,20 @@ test_wjs_apply_wal_entry_sets_pidinfo_and_start_time_no_hook(void)
TEST_ASSERT_EQUAL_INT(0, rc);
TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
TEST_ASSERT_EQUAL_UINT64_MESSAGE(wire_start_time,
TEST_ASSERT_EQUAL_UINT64_MESSAGE((uint64_t)start_time_before,
(uint64_t)j->job.start_time,
"apply_wal_entry's catch-up dispatch must also recover the "
"wire-carried start_time (bug-1687), required for a promoted "
"standby");
"bug-1697: apply_wal_entry's catch-up dispatch must NOT adopt "
"WAL_JOB_START's wire-carried start_time any more -- job.start_time "
"is exclusively DISPATCH-owned now");
wjs_assert_pidinfo_matches(j->job.pidinfo, 72003);
TEST_ASSERT_EQUAL_INT_MESSAGE(0, g_wjs_hook_fires,
"apply_wal_entry's catch-up dispatch must never fire a notification "
"hook");
wjs_teardown();
printf("test_wjs_apply_wal_entry_sets_pidinfo_and_start_time_no_hook: "
"PASS\n");
printf(
"test_wjs_apply_wal_entry_sets_pidinfo_but_not_start_time_no_hook: "
"PASS\n");
}
static void test_wjs_apply_wal_entry_backward_compat_old_payload(void)
@ -410,11 +502,23 @@ static int wjs_encode_job(const xce_job_t* j, uint8_t** out, size_t* out_len)
}
/* Direct-payload restart replay: appends WAL_JOB_SUBMIT + a new-format
* WAL_JOB_START (real pidinfo + a fixed start_time) straight onto disk via
* persist_wal_async, then replays via a fresh persist_t's persist_recover()
* (a real restart). Isolates the WAL fact shape from the live caller,
* mirroring test_wal_job_dispatch_fact.c's own restart-replay test. */
static void test_wjs_restart_replay_recovers_pidinfo_and_start_time(void)
* WAL_JOB_START (real pidinfo + a wire-carried, but now-ignored,
* start_time) straight onto disk via persist_wal_async, then replays via a
* fresh persist_t's persist_recover() (a real restart). Isolates the WAL
* fact shape from the live caller, mirroring test_wal_job_dispatch_fact.c's
* own restart-replay test.
*
* bug-1697: renamed from test_wjs_restart_replay_recovers_pidinfo_and_
* start_time -- this log has NO WAL_JOB_DISPATCH entry at all (only
* SUBMIT + START), so start_time is never dispatch-stamped either; the
* test now proves pidinfo survives while start_time stays at the job's
* fresh-submit default (0), NOT the WAL_JOB_START fact's own wire-carried
* value -- start_time is exclusively DISPATCH-owned now. The combined
* dispatch-then-started scenario (both fields recovered together) is
* covered separately by
* test_wjs_restart_replay_recovers_dispatch_start_time_and_started_pidinfo
* below. */
static void test_wjs_restart_replay_recovers_pidinfo_but_not_start_time(void)
{
char tmp[256];
strcpy(tmp, "/tmp/xce_wjs_replay_XXXXXX");
@ -478,10 +582,11 @@ static void test_wjs_restart_replay_recovers_pidinfo_and_start_time(void)
TEST_ASSERT_NOT_NULL_MESSAGE(j,
"restart replay must construct the job via WAL_JOB_SUBMIT");
TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
TEST_ASSERT_EQUAL_UINT64_MESSAGE(wire_start_time,
(uint64_t)j->job.start_time,
"restart replay must recover the exact wire-carried start_time "
"(bug-1687), not a freshly fabricated time(NULL)");
TEST_ASSERT_EQUAL_UINT64_MESSAGE(0, (uint64_t)j->job.start_time,
"bug-1697: with no WAL_JOB_DISPATCH fact anywhere in this log, "
"restart replay must leave start_time at 0, NOT adopt "
"WAL_JOB_START's own wire-carried start_time -- dispatch is "
"the only owner of this field now");
wjs_assert_pidinfo_matches(j->job.pidinfo, 72005);
wjs_teardown();
@ -493,18 +598,202 @@ static void test_wjs_restart_replay_recovers_pidinfo_and_start_time(void)
if (system(cmd) != 0)
fprintf(stderr, "cleanup warning: rm -rf %s failed\n", tmp);
printf("test_wjs_restart_replay_recovers_pidinfo_and_start_time: "
printf("test_wjs_restart_replay_recovers_pidinfo_but_not_start_time: "
"PASS\n");
}
/* One host ("wjs-worker"), one resource ("slots", value 1.0) -- mirrors
* test_wal_job_dispatch_fact.c's wjd_make_test_alloc. Caller owns the
* result (release via free_JobAlloc_ptr). */
static xce_job_alloc_t* wjs_make_test_alloc(uint64_t jobid)
{
return make_job_alloc(jobid, 1,
make_host_allocs(1,
make_host_alloc((char*)"wjs-worker", 1,
make_allocs(1,
make_alloc((char*)"slots", NULL, 0, 1.0f, 0)))));
}
/* Build a wal_jobstate_t header + fixed uint64_t start_time + trailing
* Cap'n Proto JobAlloc bytes, with WAL_JOB_DISPATCH_HAS_START_TIME_FLAG set
* in _pad -- persist_submit_job_dispatch_fact()'s post-bug-1697 payload
* shape -- mirroring test_wal_job_dispatch_fact.c's own wjd_build_dispatch_
* payload_ex (job.c/persist.c's static encode helpers aren't linkable from
* a test TU). Caller owns *out. */
static int wjs_build_dispatch_payload(uint64_t jobid, uint32_t state,
uint64_t start_time,
xce_job_alloc_t* alloc,
uint8_t** out, size_t* out_len)
{
struct capn c;
struct capn_segment* cs;
struct JobAlloc cja;
JobAlloc_ptr jap;
uint8_t* allocbuf;
size_t alloclen;
wal_jobstate_t js = { .jobid = jobid, .state = state,
._pad = WAL_JOB_DISPATCH_HAS_START_TIME_FLAG };
capn_init_malloc(&c);
cs = capn_root(&c).seg;
encode_JobAlloc(cs, &cja, alloc);
jap = new_JobAlloc(cs);
write_JobAlloc(&cja, jap);
capn_setp(capn_root(&c), 0, jap.p);
alloclen = capn_size(&c);
allocbuf = malloc(alloclen);
if (!allocbuf) { capn_free(&c); return -ENOMEM; }
capn_write_mem(&c, allocbuf, alloclen, 0);
capn_free(&c);
*out_len = sizeof(js) + sizeof(start_time) + alloclen;
*out = malloc(*out_len);
if (!*out) { free(allocbuf); return -ENOMEM; }
memcpy(*out, &js, sizeof(js));
memcpy(*out + sizeof(js), &start_time, sizeof(start_time));
memcpy(*out + sizeof(js) + sizeof(start_time), allocbuf, alloclen);
free(allocbuf);
return 0;
}
/* bug-1697's combined restart-replay regression: the FULL real-world
* lifecycle in one WAL -- WAL_JOB_SUBMIT, then a new-format WAL_JOB_DISPATCH
* (dispatch-time start_time + allocs), then a WAL_JOB_START (worker-
* reported pidinfo, whose own wire start_time must be ignored) -- proving a
* restart replay recovers BOTH start_time (from WAL_JOB_DISPATCH) AND
* pidinfo (from WAL_JOB_START) correctly, exactly the scenario every real
* job goes through today (dispatch_a_job_() always runs before the
* worker's start report). Mirrors test_wal_job_dispatch_fact.c's own
* restart-replay fixture pattern. */
static void
test_wjs_restart_replay_recovers_dispatch_start_time_and_started_pidinfo(void)
{
char tmp[256];
strcpy(tmp, "/tmp/xce_wjs_replay2_XXXXXX");
TEST_ASSERT_NOT_NULL(mkdtemp(tmp));
uint64_t dispatch_start_time = 1700020000ULL;
uint64_t start_wire_time = 1700020050ULL; /* later, must be ignored */
/* Phase 1: write the log to real disk. */
{
persist_t* p = wjs_make_fresh_persist(tmp);
TEST_ASSERT_NOT_NULL(p);
job_submit_data_t submit;
memset(&submit, 0, sizeof(submit));
submit.queue = (char*)"q";
submit.user = (char*)"tester";
xce_job_t jdef;
memset(&jdef, 0, sizeof(jdef));
jdef.jobid = 72008;
jdef.state = JOB_STAT_PEND;
jdef.submit = &submit;
uint8_t* job_payload = NULL;
size_t job_plen = 0;
TEST_ASSERT_EQUAL_INT(0,
wjs_encode_job(&jdef, &job_payload, &job_plen));
TEST_ASSERT_EQUAL_INT(0,
persist_wal_async(p, WAL_JOB_SUBMIT, job_payload,
(uint32_t)job_plen));
free(job_payload);
xce_job_alloc_t* alloc = wjs_make_test_alloc(72008);
TEST_ASSERT_NOT_NULL(alloc);
uint8_t* dispatch_payload = NULL;
size_t dispatch_plen = 0;
TEST_ASSERT_EQUAL_INT(0,
wjs_build_dispatch_payload(72008, JOB_STAT_RUN,
dispatch_start_time, alloc,
&dispatch_payload, &dispatch_plen));
free_JobAlloc_ptr(&alloc);
TEST_ASSERT_EQUAL_INT(0,
persist_wal_async(p, WAL_JOB_DISPATCH, dispatch_payload,
(uint32_t)dispatch_plen));
free(dispatch_payload);
job_pidinfo_t info = wjs_make_test_pidinfo(72008);
uint8_t* start_payload = NULL;
size_t start_plen = 0;
TEST_ASSERT_EQUAL_INT(0,
wjs_build_start_payload(72008, JOB_STAT_RUN, start_wire_time,
&info, &start_payload, &start_plen));
TEST_ASSERT_EQUAL_INT(0,
persist_wal_async(p, WAL_JOB_START, start_payload,
(uint32_t)start_plen));
free(start_payload);
TEST_ASSERT_EQUAL_INT(0, persist_flush(p));
wjs_teardown_persist(p);
}
/* Phase 2: fresh persist_t + fresh cluster_t, recover from disk —
* simulates a controller restart. */
{
persist_t* p2 = wjs_make_fresh_persist(tmp);
TEST_ASSERT_NOT_NULL(p2);
wjs_setup();
p2->cluster = &g_wjs_c;
int rc = persist_recover(p2);
TEST_ASSERT_EQUAL_INT(0, rc);
job_t* j = wjs_find_job(72008);
TEST_ASSERT_NOT_NULL_MESSAGE(j,
"restart replay must construct the job via WAL_JOB_SUBMIT");
TEST_ASSERT_EQUAL_UINT32(JOB_STAT_RUN, j->job.state);
TEST_ASSERT_EQUAL_UINT64_MESSAGE(dispatch_start_time,
(uint64_t)j->job.start_time,
"bug-1697: restart replay of a dispatch-then-started job must "
"recover start_time from the WAL_JOB_DISPATCH fact, and must "
"NOT let the later WAL_JOB_START fact's own wire-carried "
"start_time overwrite it despite that fact applying as a "
"confirmed NOOP_DUPLICATE (state already RUN from dispatch)");
wjs_assert_pidinfo_matches(j->job.pidinfo, 72008);
TEST_ASSERT_NOT_NULL_MESSAGE(j->job.allocs,
"restart replay must also recover job.allocs from the "
"WAL_JOB_DISPATCH fact (bug-1678), alongside start_time");
wjs_teardown();
wjs_teardown_persist(p2);
}
char cmd[512];
snprintf(cmd, sizeof(cmd), "rm -rf %s", tmp);
if (system(cmd) != 0)
fprintf(stderr, "cleanup warning: rm -rf %s failed\n", tmp);
printf(
"test_wjs_restart_replay_recovers_dispatch_start_time_and_started_"
"pidinfo: PASS\n");
}
/* bug-1687's primary regression test: drives the REAL production
* on_job_start() path (the actual worker-START receipt handler --
* record_job_start_fact()'s only caller) with a real job_pidinfo_t (real
* pids/pgids/exdata), through a real WAL-write + persist_recover() restart
* cycle -- the exact technique test_dc_success_appends_wal_job_dispatch_
* durably (test_dispatch_commit.c) already established for bug-1678.
* Asserts the job's pidinfo AND start_time survive the restart intact, not
* just state -- the audit's exact confirmed root cause. */
* Asserts the job's pidinfo survives the restart intact, not just state.
*
* bug-1697 update: this fixture's job never goes through dispatch_a_job_()
* (it jumps straight from a fresh WAL_JOB_SUBMIT-seeded PEND job to a
* direct on_job_start() call, with no WAL_JOB_DISPATCH fact ever appended)
* -- a scenario that no longer occurs in real production (every real job
* is dispatched first), but is still worth keeping as an isolated proof
* that on_job_start()'s own real call path decodes/applies safely on its
* own. Since start_time is now exclusively DISPATCH-owned, and this
* fixture has no dispatch fact, start_time is asserted to stay at 0 rather
* than recovering the real on_job_start() call's own receipt time -- the
* combined "dispatch-then-started" scenario (start_time genuinely
* recovered) is covered by
* test_wjs_restart_replay_recovers_dispatch_start_time_and_started_pidinfo
* above. */
static void test_wjs_real_on_job_start_survives_restart(void)
{
char tmp[256];
@ -512,7 +801,6 @@ static void test_wjs_real_on_job_start_survives_restart(void)
TEST_ASSERT_NOT_NULL(mkdtemp(tmp));
const uint64_t jobid = 72006;
time_t before_call, after_call;
/* Phase 1: real cluster + real disk persist. Seed WAL_JOB_SUBMIT
* directly (so replay can reconstruct the job) AND a live in-memory job
@ -590,9 +878,7 @@ static void test_wjs_real_on_job_start_survives_restart(void)
/* The real worker-reported pids/pgids/exdata. */
job_pidinfo_t info = wjs_make_test_pidinfo(jobid);
before_call = time(NULL);
int rc = on_job_start(&c, &info);
after_call = time(NULL);
TEST_ASSERT_EQUAL_INT(0, rc);
TEST_ASSERT_EQUAL_INT(0, persist_flush(&c.persist));
@ -635,16 +921,19 @@ static void test_wjs_real_on_job_start_survives_restart(void)
"WAL_JOB_START fact appended by the real on_job_start() call");
/* bug-1687: restart replay must recover not just STATE but the
* worker-reported pidinfo AND the true start_time -- the audit's
* exact confirmed root cause (mirrors bug-1678's own acceptance
* criterion for WAL_JOB_DISPATCH/job.allocs). */
* worker-reported pidinfo (mirrors bug-1678's own acceptance
* criterion for WAL_JOB_DISPATCH/job.allocs).
*
* bug-1697: start_time is asserted to stay at 0 -- this fixture's
* job never went through dispatch_a_job_(), so there is no
* dispatch-time value to recover, and the real on_job_start()
* call's own receipt-time start_time must NOT be adopted (it is no
* longer WAL_JOB_START's field to set). */
wjs_assert_pidinfo_matches(j2->job.pidinfo, jobid);
TEST_ASSERT_TRUE_MESSAGE(
(j2->job.start_time >= before_call)
&& (j2->job.start_time <= after_call),
"restart replay must recover the true, receipt-time start_time "
"captured by the real on_job_start() call, not a fresh "
"apply-time time(NULL) fabrication");
TEST_ASSERT_EQUAL_UINT64_MESSAGE(0, (uint64_t)j2->job.start_time,
"bug-1697: with no WAL_JOB_DISPATCH fact in this log, restart "
"replay must leave start_time at 0 -- the real on_job_start() "
"call's own receipt-time start_time must not be adopted");
xce_hook_fini(&c2.hooksys);
if (c2.jobmgr) dereference(c2.jobmgr);
@ -664,10 +953,14 @@ static void test_wjs_real_on_job_start_survives_restart(void)
void test_wal_job_start_fact(void)
{
UnitySetTestFile(__FILE__);
RUN_TEST(test_wjs_apply_committed_entry_sets_pidinfo_and_start_time);
RUN_TEST(test_wjs_apply_committed_entry_sets_pidinfo_but_not_start_time);
RUN_TEST(test_wjs_apply_committed_entry_backward_compat_old_payload);
RUN_TEST(test_wjs_apply_wal_entry_sets_pidinfo_and_start_time_no_hook);
RUN_TEST(
test_wjs_apply_committed_entry_adopts_pidinfo_when_already_run_from_dispatch);
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_and_start_time);
RUN_TEST(test_wjs_restart_replay_recovers_pidinfo_but_not_start_time);
RUN_TEST(
test_wjs_restart_replay_recovers_dispatch_start_time_and_started_pidinfo);
RUN_TEST(test_wjs_real_on_job_start_survives_restart);
}