diff --git a/src/controller/job.c b/src/controller/job.c index ba081ec3..e460b608 100644 --- a/src/controller/job.c +++ b/src/controller/job.c @@ -790,9 +790,16 @@ int restore_job_state(cluster_t* c, uint64_t jobid, uint32_t state) * ownership of an optional decoded resource allocation (NULL for a * state-only WAL_JOB_DISPATCH entry, e.g. one written before this fix) so a * promoted standby recovers EXEC_HOST the same way apply_committed_entry's - * WAL_JOB_DISPATCH case already does for the primary's own boot replay. */ + * WAL_JOB_DISPATCH case already does for the primary's own boot replay. + * + * bug-1697: also takes a wire-carried `start_time` (0 meaning "not carried + * -- leave job.start_time untouched", matching every sibling restore_job_* + * function's own "0 == not carried" convention). job.start_time is now + * DISPATCH-owned (see wal_types.h's WAL_JOB_START doc comment for the full + * rationale), so this is the seam that must restore it on a promoted + * standby, not WAL_JOB_START's own restore_job_start_state() below. */ 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) { job_t* j = NULL; lock(c->jobmgr, RTTI_LOCK_READ); @@ -806,6 +813,8 @@ int restore_job_dispatch_state(cluster_t* c, uint64_t jobid, uint32_t state, lock(j, RTTI_LOCK_WRITE); j->job.state = (int)state; + if (start_time != 0) + j->job.start_time = (time_t)start_time; if (alloc != NULL) { if (j->job.allocs != NULL) free_JobAlloc_ptr(&(j->job.allocs)); @@ -819,14 +828,17 @@ int restore_job_dispatch_state(cluster_t* c, uint64_t jobid, uint32_t state, * above (bug-1678), for apply_wal_entry()'s standby catch-up / replicated- * apply seam -- takes ownership of an optional decoded job_pidinfo_t (NULL * for a state-only WAL_JOB_START entry, e.g. one written before this fix) - * and a wire-carried start_time (0 meaning "not carried -- leave - * job.start_time untouched", matching this seam's own pre-fix behavior of - * never stamping it for WAL_JOB_START at all) so a promoted standby - * recovers the worker-confirmed pids/pgids/exdata and the true start_time - * the same way apply_committed_entry's WAL_JOB_START case already does for - * the primary's own boot replay. */ + * so a promoted standby recovers the worker-confirmed pids/pgids/exdata the + * same way apply_committed_entry's WAL_JOB_START case already does for the + * primary's own boot replay. + * + * bug-1697: no longer takes/touches start_time at all -- job.start_time is + * now exclusively DISPATCH-owned (restore_job_dispatch_state() above), so + * this function must leave it alone entirely rather than risk clobbering + * the correct dispatch-time value with a stale worker-ack-time one (see + * wal_types.h's WAL_JOB_START doc comment for the full rationale). */ int restore_job_start_state(cluster_t* c, uint64_t jobid, uint32_t state, - uint64_t start_time, job_pidinfo_t* pidinfo) + job_pidinfo_t* pidinfo) { job_t* j = NULL; lock(c->jobmgr, RTTI_LOCK_READ); @@ -840,8 +852,6 @@ int restore_job_start_state(cluster_t* c, uint64_t jobid, uint32_t state, lock(j, RTTI_LOCK_WRITE); j->job.state = (int)state; - if (start_time != 0) - j->job.start_time = (time_t)start_time; if (pidinfo != NULL) { if (j->job.pidinfo != NULL) free_JobPIDInfo_ptr(&(j->job.pidinfo)); @@ -1685,6 +1695,18 @@ static int dispatch_a_job_(cluster_t* c, endpoint_t* ep, xce_job_alloc_t* alloc) j->job.state = JOB_STAT_RUN; + /* bug-1697: start_time is now stamped HERE, synchronously alongside + * the RUN transition, rather than left to the worker's later + * WAL_JOB_START report. dispatch_a_job_() setting job.state = + * JOB_STAT_RUN synchronously means any WAL_JOB_START fact for this + * job always finds state already == RUN by the time it applies + * (apply_job_update_transition() reports JOB_TRANSITION_NOOP_ + * DUPLICATE), so it can never be the genuine first RUN transition + * and start_time adoption gated on that transition would be + * permanently dead code -- see wal_types.h's WAL_JOB_START doc + * comment for the full rationale. */ + j->job.start_time = time(NULL); + /* Reset the consecutive-retryable-failure counter (task 1.3): a * fresh successful dispatch clears any prior failure history, so a * job that later fails again is evaluated against the bound as if @@ -1700,9 +1722,14 @@ static int dispatch_a_job_(cluster_t* c, endpoint_t* ep, xce_job_alloc_t* alloc) * shutdown. j->job.allocs is read here, still under this same * write lock, as the freshly-constructed canonical struct just * stored above -- not the (now partially moved-from) local - * `alloc`/`allocs` variables. */ + * `alloc`/`allocs` variables. bug-1697: also carries j->job. + * start_time, the same snapshot just stamped above under this same + * write lock, so a restart replay recovers the true dispatch-time + * clock instead of leaving it at 0 forever. */ (void)persist_submit_job_dispatch_fact(&c->persist, alloc->jobid, - JOB_STAT_RUN, j->job.allocs); + JOB_STAT_RUN, + (uint64_t)j->job.start_time, + j->job.allocs); unlock(j); diff --git a/src/controller/persist.c b/src/controller/persist.c index 027ea192..6fea4124 100644 --- a/src/controller/persist.c +++ b/src/controller/persist.c @@ -40,19 +40,25 @@ extern int restore_job_state(cluster_t* c, uint64_t jobid, uint32_t state); * an optional decoded xce_job_alloc_t so the dispatch-time resource * allocation survives standby catch-up / replicated-apply the same way * apply_committed_entry's WAL_JOB_DISPATCH case already restores it on the - * primary's own boot replay. */ + * primary's own boot replay. bug-1697: also takes a wire-carried + * `start_time` (0 means "not carried -- leave job.start_time untouched", + * the pre-fix payload's behavior) -- job.start_time is now DISPATCH-owned + * (see wal_types.h's WAL_JOB_START doc comment for the full rationale), so + * this seam must restore it too, not just state/allocs. */ extern int restore_job_dispatch_state(cluster_t* c, uint64_t jobid, - uint32_t state, xce_job_alloc_t* alloc); + uint32_t state, uint64_t start_time, + xce_job_alloc_t* alloc); /* restore_job_start_state defined in job.c (bug-1687): WAL_JOB_START's own * sibling of restore_job_state() above, additionally taking ownership of an - * optional decoded job_pidinfo_t and a wire-carried start_time (0 means - * "not carried -- leave job.start_time untouched", the pre-fix payload's - * behavior) so the worker-confirmed start survives standby catch-up / - * replicated-apply the same way apply_committed_entry's WAL_JOB_START case - * already restores it on the primary's own boot replay. */ + * optional decoded job_pidinfo_t so the worker-confirmed start survives + * standby catch-up / replicated-apply the same way apply_committed_entry's + * WAL_JOB_START case already restores it on the primary's own boot replay. + * bug-1697: no longer takes/touches start_time -- job.start_time is now + * exclusively DISPATCH-owned (restore_job_dispatch_state() above), so this + * seam must leave it alone entirely rather than risk clobbering the correct + * dispatch-time value with a stale worker-ack-time one. */ extern int restore_job_start_state(cluster_t* c, uint64_t jobid, - uint32_t state, uint64_t start_time, - job_pidinfo_t* pidinfo); + uint32_t state, job_pidinfo_t* pidinfo); /* restore_job_finish_state defined in job.c (bug-1689): WAL_JOB_FINISH's own * sibling of restore_job_state() above, additionally taking ownership of an * optional decoded job_exitinfo_t and a wire-carried finish_time (0 means @@ -4103,32 +4109,35 @@ int apply_wal_entry(persist_t* p, uint32_t type, uint64_t lsn, * start_time PLUS trailing Cap'n Proto JobPIDInfo bytes * (persist_submit_job_start_fact's shape) alongside the {jobid, * state} header, so a promoted standby's catch-up replay recovers - * the worker-confirmed pids/pgids/exdata and the true start_time - * too, not just state. A payload of exactly sizeof(wal_jobstate_t) - * (no trailing bytes -- any WAL_JOB_START entry written before this - * fix) decodes neither, matching the pre-fix state-only behavior - * exactly. */ + * the worker-confirmed pids/pgids/exdata too, not just state. A + * payload of exactly sizeof(wal_jobstate_t) (no trailing bytes -- + * any WAL_JOB_START entry written before this fix) decodes no + * pidinfo, matching the pre-fix state-only behavior exactly. + * + * bug-1697: the wire-carried start_time field is decoded here only + * to locate where the trailing JobPIDInfo bytes start -- it is no + * longer passed to restore_job_start_state() at all. job.start_time + * is now exclusively DISPATCH-owned (restore_job_dispatch_state() + * below); leaving it untouched on this seam too prevents a stale + * worker-ack-time value from ever clobbering the correct + * dispatch-time one (see wal_types.h's WAL_JOB_START doc comment + * for the full rationale). */ if (payload_len >= sizeof(wal_jobstate_t)) { const wal_jobstate_t* js = (const wal_jobstate_t*)payload; - uint64_t start_time = 0; - job_pidinfo_t* pidinfo = NULL; + job_pidinfo_t* pidinfo = NULL; uint32_t extra = payload_len - (uint32_t)sizeof(wal_jobstate_t); - if (extra >= sizeof(start_time)) { - memcpy(&start_time, - (const uint8_t*)payload + sizeof(wal_jobstate_t), - sizeof(start_time)); - - uint32_t pidinfo_len = extra - (uint32_t)sizeof(start_time); + if (extra >= sizeof(uint64_t)) { + uint32_t pidinfo_len = extra - (uint32_t)sizeof(uint64_t); if (pidinfo_len > 0) { pidinfo = decode_pidinfo( (const uint8_t*)payload + sizeof(wal_jobstate_t) - + sizeof(start_time), + + sizeof(uint64_t), pidinfo_len); } } restore_job_start_state(p->cluster, js->jobid, js->state, - start_time, pidinfo); + pidinfo); } break; } @@ -4180,17 +4189,41 @@ int apply_wal_entry(persist_t* p, uint32_t type, uint64_t lsn, * state. A payload of exactly sizeof(wal_jobstate_t) (no trailing * bytes -- any WAL_JOB_DISPATCH entry written before this fix) * decodes no allocation, matching the pre-fix state-only behavior - * exactly. */ + * exactly. + * + * bug-1697: when WAL_JOB_DISPATCH_HAS_START_TIME_FLAG is set in + * js->_pad, a fixed uint64_t start_time immediately follows the + * header, BEFORE the JobAlloc bytes -- decode and pass it through to + * restore_job_dispatch_state() too (job.start_time is now + * DISPATCH-owned, see wal_types.h's WAL_JOB_START doc comment for + * the full rationale). The flag, not payload length, is the + * discriminator -- see that same doc comment for why a length-only + * test is ambiguous against JobAlloc's own variable length. An + * entry with the flag clear (any WAL_JOB_DISPATCH entry written + * before this fix) decodes the trailing bytes as JobAlloc only, + * leaving start_time at its "not carried" sentinel (0) -- full + * backward compatibility. */ if (payload_len >= sizeof(wal_jobstate_t)) { const wal_jobstate_t* js = (const wal_jobstate_t*)payload; xce_job_alloc_t* alloc = NULL; - if (payload_len > sizeof(wal_jobstate_t)) { - alloc = decode_joballoc( - (const uint8_t*)payload + sizeof(wal_jobstate_t), - payload_len - sizeof(wal_jobstate_t)); + uint64_t start_time = 0; + const uint8_t* alloc_ptr = + (const uint8_t*)payload + sizeof(wal_jobstate_t); + uint32_t alloc_len = + payload_len - (uint32_t)sizeof(wal_jobstate_t); + + if ((js->_pad & WAL_JOB_DISPATCH_HAS_START_TIME_FLAG) != 0 + && alloc_len >= sizeof(start_time)) { + memcpy(&start_time, alloc_ptr, sizeof(start_time)); + alloc_ptr += sizeof(start_time); + alloc_len -= (uint32_t)sizeof(start_time); + } + + if (alloc_len > 0) { + alloc = decode_joballoc(alloc_ptr, alloc_len); } restore_job_dispatch_state(p->cluster, js->jobid, js->state, - alloc); + start_time, alloc); } break; } @@ -4591,51 +4624,55 @@ int apply_committed_entry(persist_t* p, uint32_t wal_type, uint64_t lsn, } } + /* bug-1697: WAL_JOB_START's pidinfo (worker-reported pids/pgids/ + * exdata) must be decoded/adopted UNCONDITIONALLY, mirroring + * WAL_JOB_RUSAGE/WAL_JOB_CKPT/WAL_JOB_PREASON immediately above -- + * dispatch_a_job_() now sets job.state = JOB_STAT_RUN synchronously + * at DISPATCH time (scheduler-dispatch-commit task 3.1), so by the + * time this WAL_JOB_START fact applies, apply_job_update_ + * transition() above ALWAYS finds state already == RUN and returns + * JOB_TRANSITION_NOOP_DUPLICATE -- gating pidinfo adoption on + * result==JOB_TRANSITION_APPLIED (as the pre-fix code did, inside + * the block below) made it dead code for EVERY job, live, forever. + * job.start_time is DELIBERATELY not touched here at all any more: + * WAL_JOB_DISPATCH (further below) is now the sole owner of + * start_time, and this fact's own wire-carried start_time field + * (still written by persist_submit_job_start_fact() for wire-layout + * continuity) is intentionally skipped over -- never read, never + * adopted -- so it can never clobber the correct dispatch-time + * value once WAL_JOB_DISPATCH's own entry has already applied. A + * 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. */ + if (wal_type == WAL_JOB_START + && len >= sizeof(wal_jobstate_t) + sizeof(uint64_t)) { + uint32_t pidinfo_len = (uint32_t)len + - (uint32_t)sizeof(wal_jobstate_t) + - (uint32_t)sizeof(uint64_t); + if (pidinfo_len > 0) { + job_pidinfo_t* decoded = decode_pidinfo( + (const uint8_t*)payload + sizeof(wal_jobstate_t) + + sizeof(uint64_t), + pidinfo_len); + if (decoded != NULL) { + if (j->job.pidinfo != NULL) + free_JobPIDInfo_ptr(&(j->job.pidinfo)); + j->job.pidinfo = decoded; + } + } + } + if (result == JOB_TRANSITION_APPLIED) { /* apply_job_update_transition() only carries {jobid, state} on * this wire shape (see the doc comment above) and never touches - * start_time/finish_time/run_time itself — stamp them here, - * keyed on wal_type, mirroring what the richer - * apply_job_start_transition()/apply_job_finish_transition() - * cores do for their own (currently unreachable on this dispatch - * path) callers. */ - if (wal_type == WAL_JOB_START) { - /* bug-1687: a WAL_JOB_START payload can carry a fixed - * start_time plus trailing Cap'n Proto JobPIDInfo bytes - * beyond the wal_jobstate_t header (persist_submit_job_ - * start_fact's shape, mirroring bug-1678's WAL_JOB_DISPATCH - * trailing-JobAlloc-bytes handling below). Decode and adopt - * the wire-carried start_time/pidinfo when present; a - * payload of exactly sizeof(wal_jobstate_t) (no trailing - * bytes -- any WAL_JOB_START entry written before this fix) - * intentionally falls through to the old fabricated- - * time(NULL)/pidinfo-untouched behavior for full backward - * compatibility. */ - if (len >= sizeof(wal_jobstate_t) + sizeof(uint64_t)) { - uint64_t wire_start_time; - memcpy(&wire_start_time, - (const uint8_t*)payload + sizeof(wal_jobstate_t), - sizeof(wire_start_time)); - j->job.start_time = (time_t)wire_start_time; - - uint32_t pidinfo_len = len - - (uint32_t)sizeof(wal_jobstate_t) - - (uint32_t)sizeof(uint64_t); - if (pidinfo_len > 0) { - job_pidinfo_t* decoded = decode_pidinfo( - (const uint8_t*)payload + sizeof(wal_jobstate_t) - + sizeof(uint64_t), - pidinfo_len); - if (decoded != NULL) { - if (j->job.pidinfo != NULL) - free_JobPIDInfo_ptr(&(j->job.pidinfo)); - j->job.pidinfo = decoded; - } - } - } else { - j->job.start_time = time(NULL); - } - } else if (wal_type == WAL_JOB_FINISH) { + * finish_time/run_time itself — stamp them here, keyed on + * wal_type, mirroring what the richer apply_job_finish_ + * transition() core does for its own (currently unreachable on + * this dispatch path) callers. WAL_JOB_START no longer has a + * branch here (bug-1697) -- its only apply-time-relevant field, + * pidinfo, is decoded/adopted unconditionally above; start_time + * is DISPATCH-owned and is never touched by this fact type. */ + if (wal_type == WAL_JOB_FINISH) { /* bug-1689: a WAL_JOB_FINISH payload can carry a fixed * finish_time plus a fixed exit_code beyond the * wal_jobstate_t header (persist_submit_job_finish_fact's @@ -4682,14 +4719,43 @@ int apply_committed_entry(persist_t* p, uint32_t wal_type, uint64_t lsn, * payload of exactly sizeof(wal_jobstate_t) (no trailing * bytes -- e.g. any WAL_JOB_DISPATCH entry written before * this fix) intentionally falls through to the same - * state-only behavior every other type in this group gets. */ - xce_job_alloc_t* decoded = decode_joballoc( - (const uint8_t*)payload + sizeof(wal_jobstate_t), - len - sizeof(wal_jobstate_t)); - if (decoded != NULL) { - if (j->job.allocs != NULL) - free_JobAlloc_ptr(&(j->job.allocs)); - j->job.allocs = decoded; + * state-only behavior every other type in this group gets. + * + * bug-1697: when WAL_JOB_DISPATCH_HAS_START_TIME_FLAG is set + * in js->_pad, a fixed uint64_t start_time immediately + * follows the header, BEFORE the JobAlloc bytes -- decode + * and adopt it here too (job.start_time is now DISPATCH- + * owned, see wal_types.h's WAL_JOB_START doc comment for the + * full rationale). The flag, not payload length, decides + * whether the field is present -- a length-only test cannot + * distinguish an old-format entry with a large alloc from a + * new-format entry with a small one. An entry with the flag + * clear (any WAL_JOB_DISPATCH entry written before this fix) + * skips straight to decoding the trailing bytes as JobAlloc + * only, leaving start_time untouched -- full backward + * compatibility. */ + const uint8_t* alloc_ptr = + (const uint8_t*)payload + sizeof(wal_jobstate_t); + size_t alloc_len = len - sizeof(wal_jobstate_t); + + if ((js->_pad & WAL_JOB_DISPATCH_HAS_START_TIME_FLAG) != 0 + && alloc_len >= sizeof(uint64_t)) { + uint64_t wire_start_time; + memcpy(&wire_start_time, alloc_ptr, + sizeof(wire_start_time)); + j->job.start_time = (time_t)wire_start_time; + alloc_ptr += sizeof(uint64_t); + alloc_len -= sizeof(uint64_t); + } + + if (alloc_len > 0) { + xce_job_alloc_t* decoded = + decode_joballoc(alloc_ptr, alloc_len); + if (decoded != NULL) { + if (j->job.allocs != NULL) + free_JobAlloc_ptr(&(j->job.allocs)); + j->job.allocs = decoded; + } } } } @@ -7655,17 +7721,24 @@ int persist_submit_job_fact_ex(persist_t* p, uint32_t wal_type, * -- the ONLY job-state fact type that needs to carry a resource allocation * alongside {jobid, state}, since it is the sole durable record of the * dispatch-time PEND->RUN transition (design.md "WAL Dispatch Fact"). Payload - * shape: wal_jobstate_t header immediately followed by the Cap'n Proto- - * encoded JobAlloc bytes -- apply_committed_entry()'s and apply_wal_entry()'s - * WAL_JOB_DISPATCH cases decode exactly this shape, and treat a payload of - * exactly sizeof(wal_jobstate_t) (no trailing bytes) as "state-only, leave - * allocs untouched" for backward compatibility with any WAL_JOB_DISPATCH - * entry written before this fix. */ + * shape (bug-1697 update): wal_jobstate_t header, with + * WAL_JOB_DISPATCH_HAS_START_TIME_FLAG set in _pad, immediately followed by + * a fixed uint64_t start_time (the dispatch-time clock, captured ONCE by the + * caller under the job's write lock -- job.start_time is now DISPATCH-owned, + * see wal_types.h's WAL_JOB_START doc comment for the full rationale), + * immediately followed by the Cap'n Proto-encoded JobAlloc bytes. + * apply_committed_entry()'s and apply_wal_entry()'s WAL_JOB_DISPATCH cases + * decode exactly this shape, keyed on the _pad flag (not payload length, + * which is ambiguous against JobAlloc's own variable length) -- an entry + * with the flag clear (any WAL_JOB_DISPATCH entry written before this fix) + * decodes the pre-fix shape (header + JobAlloc bytes only, start_time left + * untouched) for full backward compatibility. */ int persist_submit_job_dispatch_fact(persist_t* p, uint64_t jobid, int state, + uint64_t start_time, const xce_job_alloc_t* alloc) { wal_jobstate_t js = { .jobid = jobid, .state = (uint32_t)state, - ._pad = 0 }; + ._pad = WAL_JOB_DISPATCH_HAS_START_TIME_FLAG }; uint8_t* allocbuf = NULL; size_t alloclen = 0; uint8_t* payload; @@ -7676,11 +7749,12 @@ int persist_submit_job_dispatch_fact(persist_t* p, uint64_t jobid, int state, if (rc != 0) return rc; - total = sizeof(js) + alloclen; + total = sizeof(js) + sizeof(start_time) + alloclen; payload = malloc(total); if (!payload) { free(allocbuf); return -ENOMEM; } memcpy(payload, &js, sizeof(js)); - memcpy(payload + sizeof(js), allocbuf, alloclen); + memcpy(payload + sizeof(js), &start_time, sizeof(start_time)); + memcpy(payload + sizeof(js) + sizeof(start_time), allocbuf, alloclen); free(allocbuf); rc = wal_hook_append_classified(p, WAL_JOB_DISPATCH, WAL_MODE_RETAIN, diff --git a/src/controller/testsuite/test_apply_committed_entry.c b/src/controller/testsuite/test_apply_committed_entry.c index e5a8982c..714137e6 100644 --- a/src/controller/testsuite/test_apply_committed_entry.c +++ b/src/controller/testsuite/test_apply_committed_entry.c @@ -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); diff --git a/src/controller/testsuite/test_dispatch_commit.c b/src/controller/testsuite/test_dispatch_commit.c index c60dc691..00d0d28c 100644 --- a/src/controller/testsuite/test_dispatch_commit.c +++ b/src/controller/testsuite/test_dispatch_commit.c @@ -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); diff --git a/src/controller/testsuite/test_repl_apply.c b/src/controller/testsuite/test_repl_apply.c index 29fd3a77..dfa657c3 100644 --- a/src/controller/testsuite/test_repl_apply.c +++ b/src/controller/testsuite/test_repl_apply.c @@ -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; } diff --git a/src/controller/testsuite/test_wal_job_dispatch_fact.c b/src/controller/testsuite/test_wal_job_dispatch_fact.c index 6c9819db..02ccc208 100644 --- a/src/controller/testsuite/test_wal_job_dispatch_fact.c +++ b/src/controller/testsuite/test_wal_job_dispatch_fact.c @@ -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); diff --git a/src/controller/testsuite/test_wal_job_start_fact.c b/src/controller/testsuite/test_wal_job_start_fact.c index 799b9a86..55aba60b 100644 --- a/src/controller/testsuite/test_wal_job_start_fact.c +++ b/src/controller/testsuite/test_wal_job_start_fact.c @@ -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); } diff --git a/src/include/persist.h b/src/include/persist.h index bfe4c27f..f325015b 100644 --- a/src/include/persist.h +++ b/src/include/persist.h @@ -1447,8 +1447,23 @@ int persist_submit_job_fact_ex(persist_t* p, uint32_t wal_type, * itself was never sufficient for this one fact type. `alloc` must be * non-NULL (the real call site, dispatch_a_job_(), always has one by * construction). Returns the local-append rc, same contract as - * persist_submit_job_fact(). */ + * persist_submit_job_fact(). + * + * bug-1697: additionally takes `start_time` (the dispatch-time clock, + * captured once by the caller under the job's write lock -- the same + * snapshot stamped into job.start_time itself, mirroring how + * persist_submit_job_start_fact() below takes its own receipt-time + * start_time). Encoded between the wal_jobstate_t header and the trailing + * JobAlloc bytes, discriminated by the new WAL_JOB_DISPATCH_HAS_START_TIME_ + * FLAG bit in wal_jobstate_t._pad (wal_types.h) -- NOT a payload-length + * heuristic, since JobAlloc's own variable length makes old-vs-new length + * ambiguous. job.start_time is now DISPATCH-owned: dispatch_a_job_() sets + * job.state = JOB_STAT_RUN synchronously at DISPATCH time, so any LATER + * WAL_JOB_START fact for the same job always finds state already == RUN by + * the time it applies and can never be the genuine first RUN transition -- + * see wal_types.h's WAL_JOB_START doc comment for the full rationale. */ int persist_submit_job_dispatch_fact(persist_t* p, uint64_t jobid, int state, + uint64_t start_time, const xce_job_alloc_t* alloc); /* bug-1687: WAL_JOB_START's own sibling of persist_submit_job_fact(), @@ -1457,12 +1472,18 @@ int persist_submit_job_dispatch_fact(persist_t* p, uint64_t jobid, int state, * worker-reported job_pidinfo_t (real pids/pgids/exdata) AND a receipt-time * start_time into the fact's payload (header {jobid, state} + a fixed * uint64_t start_time + trailing Cap'n Proto JobPIDInfo bytes) so a - * restart/catch-up replay can reconstruct job.pidinfo and the true - * job.start_time instead of leaving pidinfo permanently NULL and - * start_time fabricated fresh (time(NULL)) at every replay. `info` must be + * restart/catch-up replay can reconstruct job.pidinfo. `info` must be * non-NULL (the real call site, record_job_start_fact(), always has one by * construction -- it is the worker's START report itself). Returns the - * local-append rc, same contract as persist_submit_job_fact(). */ + * local-append rc, same contract as persist_submit_job_fact(). + * + * bug-1697: `start_time` is still written here (wire layout unchanged, for + * compatibility with any reader of the on-disk format) but is NO LONGER + * adopted by either apply seam -- job.start_time is now exclusively + * DISPATCH-owned (see persist_submit_job_dispatch_fact() above and + * wal_types.h's WAL_JOB_START doc comment for the full rationale). Kept as + * a caller parameter and wire field purely for layout/diagnostic + * continuity, not because it is still consumed. */ int persist_submit_job_start_fact(persist_t* p, uint64_t jobid, int state, uint64_t start_time, const job_pidinfo_t* info); diff --git a/src/include/wal_types.h b/src/include/wal_types.h index 365ffae1..1096ae6c 100644 --- a/src/include/wal_types.h +++ b/src/include/wal_types.h @@ -54,6 +54,32 @@ typedef struct { * (conditional EXIT backstop + OR JOB_STAT_PDONE) fresh against current * state. Any other nonzero value is reserved/unused today. */ +/* wal_jobstate_t._pad discriminator for WAL_JOB_DISPATCH (bug-1697). + * dispatch_a_job_() (job.c, scheduler-dispatch-commit task 3.1) sets + * job.state = JOB_STAT_RUN synchronously at DISPATCH time, before the + * worker ever reports back — so by the time the LATER WAL_JOB_START fact + * commits and applies, apply_job_update_transition() always finds state + * already == RUN and reports JOB_TRANSITION_NOOP_DUPLICATE, permanently + * disabling any adoption gated on a genuine forward transition for that + * fact type. start_time is therefore moved to be DISPATCH-owned instead: + * WAL_JOB_DISPATCH's payload can now carry a fixed uint64_t start_time + * (the dispatch-time clock, stamped once under the job's write lock) + * between the wal_jobstate_t header and the trailing Cap'n Proto JobAlloc + * bytes (bug-1678). Because JobAlloc's own encoding is variable-length and + * always present in every post-bug-1678 WAL_JOB_DISPATCH entry, a + * length-based "has start_time or not" test would be ambiguous (an + * old-format entry with a large alloc can look identical in length to a + * new-format entry with a small one) — this explicit _pad bit is the + * discriminator instead, mirroring WAL_JOB_FAIL_STAGE_FLAG/WAL_JOB_UPDATE_ + * POSTDONE_MARK's own precedent above. _pad is unconditionally 0 for every + * WAL_JOB_DISPATCH entry written before this fix, so introducing this bit + * is safe: a payload with the flag CLEAR decodes exactly the pre-fix shape + * (header immediately followed by JobAlloc bytes, start_time left + * untouched — the accepted one-time migration-boundary gap for any entry + * written by an older binary); a payload with the flag SET decodes + * [header][uint64_t start_time][JobAlloc bytes]. */ +#define WAL_JOB_DISPATCH_HAS_START_TIME_FLAG 0x1u + /* WAL_QUEUE_CTRL — queue name is a NUL-terminated string immediately after * this header. Total payload = sizeof(wal_queuehdr_t) + strlen(name)+1. */ typedef struct { @@ -106,12 +132,26 @@ typedef enum { * entry written before bug-1687; as of bug-1687 the * real producer (persist_submit_job_start_fact) * appends a fixed uint64_t start_time (receipt-time - * clock, not fabricated at apply time) plus - * trailing Cap'n Proto JobPIDInfo bytes (the - * worker-reported pids/pgids/exdata) -- both apply - * seams treat a payload of exactly + * clock) plus trailing Cap'n Proto JobPIDInfo bytes + * (the worker-reported pids/pgids/exdata) -- both + * apply seams treat a payload of exactly * sizeof(wal_jobstate_t) as the legacy state-only - * shape for full backward compatibility. */ + * shape for full backward compatibility. + * bug-1697: the wire-carried start_time field is + * still WRITTEN (wire layout unchanged, so an + * older reader keeps working) but is no longer + * READ/adopted by either apply seam -- dispatch_a_ + * job_() setting job.state = JOB_STAT_RUN + * synchronously at DISPATCH time means this fact + * always finds state already == RUN by the time + * it applies, so it can never be the genuine + * first RUN transition; WAL_JOB_DISPATCH (below) + * is now the sole owner/source of job.start_time. + * pidinfo adoption is unaffected and remains + * unconditional (not gated on a forward + * transition), since it is now known this fact's + * transition is a permanent, expected no-op, not + * an edge case. */ WAL_JOB_FINISH = 3, /* worker-confirmed job finish. Payload is * wal_jobstate_t{jobid, state=DONE|EXIT, _pad=0} * for any entry written before bug-1689; as of @@ -233,10 +273,30 @@ typedef enum { * running, distinct from (and independent of) * WAL_JOB_START's later worker-confirmed-start * fact. Payload is wal_jobstate_t{jobid, state, - * _pad=0} -- always the legacy absolute-value - * form (no racing same-job fact to defer against, - * since this is the first transition after a job - * leaves PEND). */ + * _pad=0} immediately followed by trailing Cap'n + * Proto JobAlloc bytes for any entry written + * before bug-1697 (state is always the legacy + * absolute-value form -- no racing same-job fact + * to defer against, since this is the first + * transition after a job leaves PEND). As of + * bug-1697, dispatch_a_job_() sets job.start_time + * synchronously alongside job.state at DISPATCH + * time (see WAL_JOB_START's own updated comment + * above for why start_time moved here): when + * _pad has WAL_JOB_DISPATCH_HAS_START_TIME_FLAG + * set, the payload is instead wal_jobstate_t + * header + a fixed uint64_t start_time (the + * dispatch-time clock) + the trailing JobAlloc + * bytes. The flag, not payload length, is the + * discriminator -- see + * WAL_JOB_DISPATCH_HAS_START_TIME_FLAG's own doc + * comment above for why a length heuristic would + * be ambiguous against JobAlloc's own variable + * length. Any WAL_JOB_DISPATCH entry written + * before this fix has _pad==0 (flag clear) and + * falls back to the pre-fix state+allocs-only + * behavior, leaving start_time untouched -- an + * accepted one-time migration-boundary gap. */ WAL_QUEUE_CTRL = 20, WAL_WORKER_CTRL = 30, WAL_NOOP = 40, /* Internal: empty payload, replay no-op; appended only at promotion */