fix(scheduler): record events before the core applies them (bug-1852)

The recorder encoded each controller event batch after
xce_core_push_events() had applied it, and applying moves payload fields
out of the events: a WORKERS_PUSH's resvals (core_apply_worker_resvals
MOVE_PTR), a JOBS_PUSH's allocs, a JOB_RUSAGE's rusages, and a
CONFIG_PUSH's shared resvals (sched_apply_pending_config recorded after
sched_init_config). Recordings silently lost exactly those fields -- a
worker's resval names were written with NULL values, so --sim-verify
replayed "no slots" and turned 3 live DISPATCHes into PENDs.

driver.c now records the batch before the push; the periodic in-stream
SnapshotEntry moves out of sched_record_write_events() into new
sched_record_checkpoint_after_apply(), called after the push so a
checkpoint still reflects the events written ahead of it. The config
push is likewise recorded before sched_init_config().

Regression test: test_recorded_workers_push_keeps_resval_values (RED:
recorded value NULL; GREEN after). Periodic-checkpoint tests updated to
the write-then-checkpoint contract. meson test 109/109; 25 live soak
recordings replay with 0 mismatches.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Rongsong Shen 2026-09-24 08:41:55 +00:00
parent ca4db13a79
commit 9c02184fb4
No known key found for this signature in database
GPG key ID: 5BCDAAE0123E9FE2
10 changed files with 258 additions and 33 deletions

View file

@ -25187,6 +25187,23 @@
"resvals",
"xstring"
]
},
{
"id": "bug-1852",
"timestamp": "2026-09-24T08:10:00Z",
"error_message": "Scheduler replay-parity soak gate (run-ha-soak.sh --sequential 6, post bug-1851): 1 of 7 clean recordings failed --sim-verify with 3 MISMATCHes, all in its first decision round: live 'DISPATCH jobid=... nhosts=1' vs sim 'PEND ... main_reason=0' (sim: unsatisfy_ unmet resource 0 (slots) shortfall 1). Sim trace: snapshot at record start restored the worker with 0/0 resvals; the recording's only WORKERS_PUSH 'carries 10 resval(s)' but core_apply_worker_resvals 'applied 0' -- every recorded NameValue.val was NULL.",
"file": "src/scheduler/src/driver.c",
"root_cause": "The recorder encoded each event batch AFTER applying it: driver.c's xce_sched_driver_translate_pending_events() called xce_core_push_events() and only then sched_record_write_events() on the same xce_core_event_t payloads. Applying is destructive -- core_apply_worker_resvals() MOVE_PTRs each resval (nv->val -> worker->resvals), core_build_job MOVE_PTRs a JOBS_PUSH's allocs, JOB_RUSAGE transfers rusages, and core_apply_config_resvals() MOVE_PTRs a CONFIG_PUSH's shared resvals (bug-1847's new config-push recording also recorded after sched_init_config). So recordings silently lost exactly those fields: a worker's resval names were written with NULL values. Masked whenever the worker's values were already in the record-start snapshot; exposed when a recording opened after a scheduler restart, before the worker's first value push. Field-completeness violation (persistence.md). bug-1688's 'a repeat WORKERS_PUSH carries 20 resval names with nv->val==NULL' was traced from a replay file and was very likely this same stripping, not something the controller sends.",
"fix": "FIXED (2026-09-24, TDD). driver.c records the batch BEFORE xce_core_push_events(); the periodic SnapshotEntry checkpoint was split out of sched_record_write_events() into new sched_record_checkpoint_after_apply() (recording.h/recording_events.c), called AFTER the push so a checkpoint still reflects the events ahead of it in the stream. sched_apply_pending_config() (scheduler.c) likewise records the CONFIG_PUSH before sched_init_config() and checkpoints after. Stubs added to the 4 driver test units that stub the recorder. Regression test test_record_lifecycle.c::test_recorded_workers_push_keeps_resval_values (RESOURCES_PUSH 'slots' + WORKERS_PUSH hostA slots=22 through the real driver with recording on; decodes the recorded WORKERS_PUSH) -- RED (recorded val NULL), GREEN after; 3 periodic-checkpoint tests updated to the write-then-checkpoint contract. Full meson test 109/109 OK.",
"tags": [
"scheduler",
"recording",
"replay",
"sim-verify",
"field-completeness",
"MOVE_PTR",
"driver"
]
}
]
}

View file

@ -225,19 +225,14 @@ extern int sched_record_stop(xce_scheduler_t* sched);
* returned; the caller (driver.c) does not need to react further -- normal
* scheduling continues either way (Req 5 AC 10, "Error handling").
*
* Periodic checkpoint (Req 5 AC 11, task 9.3): after the whole batch's
* events are written, if `sched->record_snapshot_interval > 0` and the
* (cumulative, since recording started) `sched->record_event_count` has
* just landed exactly on a multiple of it, a fresh `SnapshotEntry` message
* is appended (via recording.c's shared write_snapshot_entry(), the SAME
* builder sched_record_start() uses for the initial one -- DRY, never
* duplicated). `record_snapshot_interval == 0` disables this entirely.
* Checked ONCE per call against the post-batch count, not once per
* multiple crossed within one large batch -- see recording_events.c's own
* comment on sched_record_write_events() for the full boundary-semantics
* rationale. A checkpoint write failure disables recording via
* sched_record_abort_on_error(), the exact same path as any other
* recording write failure -- never special-cased.
* Call BEFORE the batch is applied to the core (bug-1852): applying moves
* payload fields out of the events (core_apply_worker_resvals()'s
* MOVE_PTR of each resval, a JOBS_PUSH's allocs, a JOB_RUSAGE's rusages,
* a CONFIG_PUSH's shared resvals), so an event encoded afterwards is
* missing exactly those fields and replays differently. The periodic
* checkpoint is a separate step, sched_record_checkpoint_after_apply()
* below, because a SnapshotEntry must reflect the events written ahead
* of it.
*
* Concurrency (task 9.4 fix round): the per-event increment of
* `sched->record_event_count` takes `sched->record_lock` (scheduler.h's
@ -249,6 +244,25 @@ extern int sched_record_stop(xce_scheduler_t* sched);
extern int sched_record_write_events(xce_scheduler_t* sched,
xce_core_event_t* events, int n);
/*
* sched_record_checkpoint_after_apply - periodic checkpoint (Req 5 AC 11,
* task 9.3), called AFTER the batch just recorded by
* sched_record_write_events() has been applied to the core. If
* `sched->record_snapshot_interval > 0` and the (cumulative, since
* recording started) `sched->record_event_count` has just landed exactly
* on a multiple of it, a fresh `SnapshotEntry` message is appended (via
* recording.c's shared write_snapshot_entry(), the SAME builder
* sched_record_start() uses for the initial one). `record_snapshot_interval
* == 0` disables this entirely. Checked ONCE per call against the
* post-batch count, not once per multiple crossed within one large batch
* -- see recording_events.c's own comment for the full boundary-semantics
* rationale. A checkpoint write failure disables recording via
* sched_record_abort_on_error(), the exact same path as any other
* recording write failure. Same zero-cost no-op gate as
* sched_record_write_events().
*/
extern int sched_record_checkpoint_after_apply(xce_scheduler_t* sched);
/*
* sched_record_session_ctx_t - opaque per-round accumulator for the
* decisions a recording session collects between

View file

@ -800,8 +800,6 @@ int xce_sched_driver_translate_pending_events(xce_sched_core_t* core,
return 0;
}
push_rc = xce_core_push_events(core, events, n);
/* Req 5 AC 10 (scheduler-core spec, task 9.2): per-event-batch
* recording write. `record_ctx` is an opaque `void*` -- always the
* owning `xce_scheduler_t*` when the caller wants recording, NULL
@ -818,16 +816,26 @@ int xce_sched_driver_translate_pending_events(xce_sched_core_t* core,
* case. xce_sched_driver_run_normal_mode_round() below passes its own
* `sched` parameter (always genuinely `xce_scheduler_t*`) explicitly.
* A NULL `record_ctx` is the single boolean check + zero I/O + zero
* allocation non-recording path (Req 5 AC 10, "Performance"). MUST run
* before the cleanup loop below frees any translated payload --
* sched_record_write_events() needs every `events[i]` pointer still
* live. */
* allocation non-recording path (Req 5 AC 10, "Performance").
*
* bug-1852: written BEFORE xce_core_push_events(), which moves payload
* fields out of the events as it adopts them (a WORKERS_PUSH's resvals,
* a JOBS_PUSH's allocs, a JOB_RUSAGE's rusages). Recording afterwards
* wrote a worker's resval names with NULL values, so a replay never
* learned its capacity. The periodic checkpoint still runs after the
* push, so a SnapshotEntry includes the events written ahead of it. */
{
xce_scheduler_t* rec_sched = (xce_scheduler_t*)record_ctx;
if (rec_sched != NULL) {
sched_record_write_events(rec_sched, events, n);
}
push_rc = xce_core_push_events(core, events, n);
if (rec_sched != NULL) {
sched_record_checkpoint_after_apply(rec_sched);
}
}
for (i = 0; i < n; i++) {

View file

@ -168,8 +168,8 @@ static int write_one_replay_event(FILE* f, xce_core_event_t* ev,
/*
* sched_record_write_events - see recording.h's declaration comment for the
* full contract. This function's tail implements Req 5 AC 11's periodic
* checkpoint: task 9.3.
* full contract. Req 5 AC 11's periodic checkpoint (task 9.3) lives in
* sched_record_checkpoint_after_apply() below, whose semantics follow.
*
* Boundary semantics ("every N events", documented choice): after writing
* this call's whole batch, the check is `record_snapshot_interval > 0 &&
@ -218,6 +218,24 @@ int sched_record_write_events(xce_scheduler_t* sched, xce_core_event_t* events,
}
}
return 0;
}
/*
* sched_record_checkpoint_after_apply - see recording.h's declaration
* comment. Split out of sched_record_write_events() by bug-1852: events
* are now recorded before the core applies (and strips) them, while a
* checkpoint must still capture the state AFTER them.
*/
int sched_record_checkpoint_after_apply(xce_scheduler_t* sched)
{
if (sched == NULL) {
return 0;
}
if (!sched->recording || (sched->record_file == NULL)) {
return 0;
}
if ((sched->record_snapshot_interval > 0) && (sched->record_event_count > 0)
&& ((sched->record_event_count % sched->record_snapshot_interval)
== 0)) {

View file

@ -1006,19 +1006,14 @@ int sched_apply_pending_config(xce_scheduler_t* sched)
return 0;
}
rc = sched_init_config(sched, config);
if (rc < 0) {
ERROR("%s sched_init_config failed rc=%d", __func__, rc);
free_Conf4Sched_ptr(&config);
return rc;
}
/* Applied at a round boundary on the driver thread -- the same place
* xce_sched_driver_translate_pending_events() records the round's
* other controller events, and ahead of them, matching the order they
* take effect. Before bug-1846's deferral this push bypassed the
* pending-update queue and never reached a recording. Borrowed payload
* (core->config owns it); a no-op when not recording. */
* pending-update queue and never reached a recording. Recorded BEFORE
* sched_init_config() (bug-1852): applying it moves the shared resvals
* out of `config` (core_apply_config_resvals()), so recording afterwards
* wrote them as NULL. Borrowed payload; a no-op when not recording. */
{
xce_core_event_t ev;
@ -1029,6 +1024,15 @@ int sched_apply_pending_config(xce_scheduler_t* sched)
sched_record_write_events(sched, &ev, 1);
}
rc = sched_init_config(sched, config);
if (rc < 0) {
ERROR("%s sched_init_config failed rc=%d", __func__, rc);
free_Conf4Sched_ptr(&config);
return rc;
}
sched_record_checkpoint_after_apply(sched);
return 1;
}

View file

@ -228,6 +228,13 @@ int sched_record_write_events(xce_scheduler_t* sched, xce_core_event_t* events,
return 0;
}
/* bug-1852: driver.c now checkpoints separately, after applying a batch. */
int sched_record_checkpoint_after_apply(xce_scheduler_t* sched)
{
(void)sched;
return 0;
}
/* sched_record_start/sched_record_stop (scheduler-core spec, task 9.4) --
* driver.c's handle_deferred_admin_record() (new this task) calls both;
* this file never enqueues an XCE_SCHED_OP_ADMIN_RECORD request, so

View file

@ -280,6 +280,13 @@ int sched_record_write_events(xce_scheduler_t* sched, xce_core_event_t* events,
return 0;
}
/* bug-1852: driver.c now checkpoints separately, after applying a batch. */
int sched_record_checkpoint_after_apply(xce_scheduler_t* sched)
{
(void)sched;
return 0;
}
/* sched_record_start/sched_record_stop (scheduler-core spec, task 9.4) --
* driver.c's handle_deferred_admin_record() (new this task) calls both;
* this file never enqueues an XCE_SCHED_OP_ADMIN_RECORD request, so

View file

@ -157,6 +157,13 @@ int sched_record_write_events(xce_scheduler_t* sched, xce_core_event_t* events,
return 0;
}
/* bug-1852: driver.c now checkpoints separately, after applying a batch. */
int sched_record_checkpoint_after_apply(xce_scheduler_t* sched)
{
(void)sched;
return 0;
}
/* sched_record_start/sched_record_stop (scheduler-core spec, task 9.4) --
* driver.c's handle_deferred_admin_record() (new this task) calls both;
* this file never enqueues an XCE_SCHED_OP_ADMIN_RECORD request, so

View file

@ -662,6 +662,135 @@ test_full_cycle_start_event_session_stop_produces_expected_stream(void)
" PASS\n");
}
/* ---------------------------------------------------------------------- */
/* bug-1852: a recorded event must carry its payload as RECEIVED, not what */
/* is left of it after the core applied it. core_apply_worker_resvals() */
/* MOVE_PTRs each resval out of the WORKERS_PUSH payload; recording after */
/* xce_core_push_events() wrote the worker's resval names with NULL values, */
/* so a replay never learned the worker's capacity (live soak: a recording */
/* opened before the worker's first value push replayed as "no slots" -- */
/* 3 live DISPATCHes became sim PENDs). */
/* ---------------------------------------------------------------------- */
static void skip_header_and_initial_snapshot(FILE* f); /* defined below */
static void test_recorded_workers_push_keeps_resval_values(void)
{
char record_dir[PATH_MAX];
xce_scheduler_t sched;
char path_copy[PATH_MAX];
xce_sched_update_request_t* rr;
xce_sched_update_request_t* rw;
xce_resource_t* wire_res;
xce_resource_t** res_ptrs;
xce_worker_t* wire_w;
xce_worker_t** w_ptrs;
xce_name_val_t* nv;
int rc;
int found = 0;
FILE* f;
struct capn c;
make_tmp_dir(record_dir, sizeof(record_dir), "_1852");
fixture_init(&sched, record_dir);
rc = sched_record_start(&sched, "workers.replay");
TEST_ASSERT_EQUAL_INT(0, rc);
strcpy(path_copy, sched.record_file_path);
/* Heap payloads throughout: release_translated_payload() frees them
* like genuinely wire-decoded ones (test_resval_ownership.c's own
* warning about stack/literal payloads applies verbatim). */
wire_res = (xce_resource_t*)calloc(1, sizeof(*wire_res));
wire_res->name = strdup("slots");
res_ptrs = (xce_resource_t**)calloc(1, sizeof(*res_ptrs));
res_ptrs[0] = wire_res;
nv = (xce_name_val_t*)calloc(1, sizeof(*nv));
nv->name = strdup("slots");
nv->val = (xce_val_t*)calloc(1, sizeof(*nv->val));
nv->val->which = Value_u_fvalue;
nv->val->u.fvalue = 22.0;
wire_w = (xce_worker_t*)calloc(1, sizeof(*wire_w));
wire_w->name = strdup("hostA");
wire_w->nresvals_to_sched = 1;
wire_w->resvals_to_sched = (xce_name_val_t**)calloc(1, sizeof(nv));
wire_w->resvals_to_sched[0] = nv;
w_ptrs = (xce_worker_t**)calloc(1, sizeof(*w_ptrs));
w_ptrs[0] = wire_w;
/* Resource definition first, so the core resolves "slots" and actually
* adopts (moves) the worker's value -- the path that emptied the
* recorded payload. */
rr = (xce_sched_update_request_t*)calloc(1, sizeof(*rr));
rr->op = XCE_SCHED_OP_UPDATE_RESOURCES;
rr->u.resourceupdate.nresources = 1;
rr->u.resourceupdate.resources = res_ptrs;
dataq_enq(sched.core.pend_updates[0], &(rr->link));
rw = (xce_sched_update_request_t*)calloc(1, sizeof(*rw));
rw->op = XCE_SCHED_OP_UPDATE_WORKER;
rw->u.workerupdate.nworkers = 1;
rw->u.workerupdate.workers = w_ptrs;
dataq_enq(sched.core.pend_updates[0], &(rw->link));
rc = xce_sched_driver_translate_pending_events(&(sched.core), &sched);
TEST_ASSERT_EQUAL_INT(2, rc);
/* Precondition: the live core did adopt the value. */
{
xce_sched_worker_t* w = sched_get_worker(&(sched.core), "hostA");
xce_resource_t* r = NULL;
TEST_ASSERT_NOT_NULL(w);
TEST_ASSERT_TRUE(key_find(sched.core.resmgr, "slots", (void**)&r) > 0);
TEST_ASSERT_NOT_NULL(zarray_get(&(w->resvals), r->idx));
}
rc = sched_record_stop(&sched);
TEST_ASSERT_EQUAL_INT(0, rc);
f = fopen(path_copy, "r");
TEST_ASSERT_NOT_NULL(f);
skip_header_and_initial_snapshot(f);
while (capn_init_fp(&c, f, 0) == 0) {
ReplayEvent_ptr p;
struct ReplayEvent wire;
replay_event_t dst;
p.p = capn_getp(capn_root(&c), 0, 1);
read_ReplayEvent(&wire, p);
memset(&dst, 0, sizeof(dst));
decode_ReplayEvent(&dst, &wire);
if (dst.body_which == ReplayEvent_body_workersPush) {
xce_worker_t* rw0;
xce_name_val_t* rnv;
found = 1;
TEST_ASSERT_NOT_NULL(dst.body.workers_push);
TEST_ASSERT_EQUAL_INT(1, dst.body.workers_push->count);
rw0 = dst.body.workers_push->workers[0];
TEST_ASSERT_EQUAL_STRING("hostA", rw0->name);
TEST_ASSERT_EQUAL_INT(1, rw0->nresvals_to_sched);
rnv = rw0->resvals_to_sched[0];
TEST_ASSERT_EQUAL_STRING("slots", rnv->name);
TEST_ASSERT_NOT_NULL_MESSAGE(rnv->val,
"the recorded WORKERS_PUSH must keep the resval's value, "
"not the NULL the core's MOVE_PTR left behind (bug-1852)");
TEST_ASSERT_EQUAL_FLOAT(22.0f, (float)rnv->val->u.fvalue);
}
free_ReplayEvent(&dst);
capn_free(&c);
}
fclose(f);
TEST_ASSERT_TRUE_MESSAGE(found, "a WORKERS_PUSH event must be recorded");
printf("test_recorded_workers_push_keeps_resval_values: PASS\n");
}
/* ---------------------------------------------------------------------- */
/* Test 3: when recording is inactive, the driver-loop hooks touch no */
/* file/record state -- zero file I/O (Req 5 AC 10, "Performance"). */
@ -959,7 +1088,10 @@ static void submit_one_jobstate_event(xce_scheduler_t* sched, uint64_t jobid)
ev.type = XCE_CORE_EVENT_JOB_STATE_CHANGE;
ev.u.job_state_change.jobid = jobid;
/* Same two steps driver.c takes per batch (bug-1852): record the
* events, (apply them,) then the periodic checkpoint. */
TEST_ASSERT_EQUAL_INT(0, sched_record_write_events(sched, &ev, 1));
TEST_ASSERT_EQUAL_INT(0, sched_record_checkpoint_after_apply(sched));
}
/* Reads exactly one capnp message off `f` and decodes it as a ReplayEvent,
@ -1171,6 +1303,7 @@ test_periodic_checkpoint_single_batch_crossing_two_boundaries_checkpoints_once(
events[i].u.job_state_change.jobid = (uint64_t)(300 + i);
}
TEST_ASSERT_EQUAL_INT(0, sched_record_write_events(&sched, events, 6));
TEST_ASSERT_EQUAL_INT(0, sched_record_checkpoint_after_apply(&sched));
TEST_ASSERT_EQUAL_UINT64(6ULL, sched.record_event_count);
TEST_ASSERT_TRUE(sched.recording);
@ -1226,9 +1359,11 @@ test_periodic_checkpoint_write_failure_disables_recording_cleanly(void)
ev.type = XCE_CORE_EVENT_JOB_STATE_CHANGE;
ev.u.job_state_change.jobid = 400ULL;
/* The event itself writes fine; the periodic checkpoint that fires
* immediately after it (interval=1) is what fails and aborts. */
TEST_ASSERT_TRUE(sched_record_write_events(&sched, &ev, 1) < 0);
/* The event itself writes fine; the periodic checkpoint that follows
* it (interval=1, bug-1852's separate after-apply step) is what fails
* and aborts. */
TEST_ASSERT_EQUAL_INT(0, sched_record_write_events(&sched, &ev, 1));
TEST_ASSERT_TRUE(sched_record_checkpoint_after_apply(&sched) < 0);
TEST_ASSERT_FALSE(sched.recording);
TEST_ASSERT_NULL(sched.record_file);
@ -1406,6 +1541,7 @@ int main(void)
RUN_TEST(test_start_writes_decodable_header_then_snapshot_entry);
RUN_TEST(test_full_cycle_start_event_session_stop_produces_expected_stream);
RUN_TEST(test_recorded_workers_push_keeps_resval_values);
RUN_TEST(test_recording_inactive_hooks_are_zero_cost_noops);
RUN_TEST(test_double_start_fails_cleanly);
RUN_TEST(test_stop_when_not_recording_fails_cleanly);

View file

@ -177,6 +177,13 @@ int sched_record_write_events(xce_scheduler_t* sched, xce_core_event_t* events,
return 0;
}
/* bug-1852: driver.c now checkpoints separately, after applying a batch. */
int sched_record_checkpoint_after_apply(xce_scheduler_t* sched)
{
(void)sched;
return 0;
}
int sched_record_start(xce_scheduler_t* sched, const char* record_file)
{
(void)sched;