From ac033f478381170b44384af0e1ec1d4f7b16b8bd Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Thu, 24 Sep 2026 07:00:07 +0000 Subject: [PATCH] fix(scheduler): record config pushes, free hlimits lists, quiet benign picker WARN (bug-1847/1848/1849) Follow-ups from the bug-1846 investigation. bug-1847: config pushes never reached a .replay recording -- handler.c applied them synchronously, bypassing the pending-update queue the recorder writes from. With bug-1846's deferral they're now applied at a round boundary on the driver thread, so sched_apply_pending_config() writes a CONFIG_PUSH event via the existing sched_record_write_events() (no-op when not recording), ahead of the round's other recorded events. Test: test_config_push_deferred.c's test_applied_config_push_is_recorded (RED: 0 events; GREEN: 1). Fidelity limit, pre-existing: replay applies configPush through core_events.c's CONFIG_PUSH path, which doesn't re-run groupmgr_load_configs()/plugin_config_update(), so a limits/groups change still won't take effect in sim. bug-1848: xce_sched_obj_t.hlimits was created with a NULL zarray killer at all three constructors, so reset_sched_obj() and schedobj teardown leaked the per-worker xlist_t match_job_host_limit_() callocs. New kill_hlimits_list() (schedobj.c) frees the list, never its vres entries (owned by the limit plugin); core_events.c and snapshot_load.c use identical static local copies, since both avoid sharing helpers with schedobj.c and several test binaries link them without it. Test: test_limit_host_dedup.c's test_hlimits_zarray_releases_its_lists (RED: killer NULL; GREEN). bug-1849: every --sim run warned "failed to resolve job picker plugin ... picker rebuild will be skipped". Benign: the snapshot is loaded before the sim registers its picker, and sim_bootstrap_picker() replays the same queue/job walk afterward. Downgraded to TRACE with an explanation. Buglog also records bug-1850 (open): the ~100s reconnect churn behind bug-1846 part 2 -- xcecli_retry_next() rotates/reconnects on every retry (ETIMEDOUT after the 10s reply deadline, E_XCE_NOT_READY, redirects), so a slow reply from a healthy primary forces a rejoin + full re-push. Needs the live scheduler.log and a libxce spec. Full scheduler suite 87/87 (asan). Replay of the captured file: same 184 mismatches, all attributable to the recording's pre-fix binary. Co-Authored-By: Claude Opus 5.5 (1M context) --- .wolf/buglog.json | 59 +++++++++++++++++++ src/scheduler/include/sched/types.h | 3 + src/scheduler/src/core_events.c | 20 ++++++- src/scheduler/src/schedobj.c | 21 ++++++- src/scheduler/src/scheduler.c | 17 ++++++ src/scheduler/src/snapshot_load.c | 37 ++++++++++-- .../testsuite/test_config_push_deferred.c | 50 ++++++++++++++++ .../testsuite/test_limit_host_dedup.c | 29 +++++++++ 8 files changed, 228 insertions(+), 8 deletions(-) diff --git a/.wolf/buglog.json b/.wolf/buglog.json index f8539126..83cd9327 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -25111,6 +25111,65 @@ ], "occurrences": 1, "last_seen": "2026-09-23T10:05:00Z" + }, + { + "id": "bug-1847", + "timestamp": "2026-09-24T05:30:00Z", + "error_message": "bug-1846 follow-up: a scheduler config push (sent by the controller on every scheduler join) was never written to a .replay recording, so a replay spanning a rejoin or a genuine config change never saw it.", + "file": "src/scheduler/src/scheduler.c (sched_apply_pending_config)", + "root_cause": "handler.c applied config pushes synchronously via sched_init_config(), bypassing the pending-update queue that xce_sched_driver_translate_pending_events() records from. bug-1846's deferral moved application to a round boundary on the driver thread (main.c -> sched_apply_pending_config()), making it recordable at the right point.", + "fix": "FIXED (2026-09-24, TDD). sched_apply_pending_config() now writes a CONFIG_PUSH core event via the existing sched_record_write_events() after sched_init_config() succeeds (no-op when not recording), ahead of the round's other recorded events -- matching the order they take effect. Test: test_config_push_deferred.c's test_applied_config_push_is_recorded (RED: record_event_count stayed 0; GREEN: 1 event written, stashing alone writes nothing). Known fidelity limit: replay applies configPush through core_events.c's CONFIG_PUSH path (queues/resources/resvals/configver), which does not re-run groupmgr_load_configs()/plugin_config_update()/sched_init_sharedInst() like sched_init_config() does -- a replayed config CHANGE to limits/groups still won't take effect in sim (pre-existing driver-equivalence gap, not introduced here).", + "tags": [ + "scheduler", + "recording", + "replay", + "config-push", + "driver-equivalence" + ] + }, + { + "id": "bug-1848", + "timestamp": "2026-09-24T05:30:00Z", + "error_message": "Leak: xce_sched_obj_t.hlimits was created with a NULL zarray item killer, so reset_sched_obj() (limit_job_election()'s config-version rebuild) and schedobj teardown leaked the per-worker xlist_t that match_job_host_limit_() callocs, one per worker a job had tried. Visible as part of the large LeakSanitizer report on every --sim replay run.", + "file": "src/scheduler/src/schedobj.c, core_events.c, snapshot_load.c (hlimits zarray_init)", + "root_cause": "zarray_fini() only frees items through the zarray's killer; all three schedobj constructors passed NULL.", + "fix": "FIXED (2026-09-24, TDD). New kill_hlimits_list() (schedobj.c, declared in sched/types.h) frees one per-worker list (xlist_fini + free; never its vres entries, owned by the limit plugin's instance table); installed at all three zarray_init(&(obj->hlimits), ...) sites -- schedobj.c uses kill_hlimits_list(); core_events.c and snapshot_load.c get identical static local copies (core_hlimits_list_killer / snapshot_hlimits_list_killer) because both deliberately don't share helpers with schedobj.c and several test binaries (sched_core_events_test, sched_core_full_cycle_test, sched_snapshot_save_load_test, sched_sim_startup_test) link them without schedobj.c -- a shared symbol broke those links. zarray_fini() preserves the killer, so reset_sched_obj() leaves the zarray reusable. Test: test_limit_host_dedup.c's test_hlimits_zarray_releases_its_lists (RED: killer NULL; GREEN). A direct __lsan_do_recoverable_leak_check() test was tried and rejected -- the fixture's own resreq parsing (parse_select strdup) leaks independently, so the baseline is never leak-free.", + "tags": [ + "scheduler", + "limit", + "hlimits", + "memory-leak" + ] + }, + { + "id": "bug-1849", + "timestamp": "2026-09-24T05:30:00Z", + "error_message": "Every --sim run logged 'WARN xce_sched_core_load_snapshot failed to resolve job picker plugin (rc=-2); picker rebuild will be skipped for this load' -- misleading; flagged as a suspect during the bug-1846 investigation.", + "file": "src/scheduler/src/snapshot_load.c (xce_sched_core_load_snapshot)", + "root_cause": "Benign ordering, not a fault: the only caller (sim.c's sim_locate_and_load_snapshot()) loads the snapshot before any picker is registered; sim_bootstrap_picker() (sim_picker.c, bug-1567) then replays the full on_queue_update + on_job_push walk against the restored core (builtin_fcfs has no on_config, and on_job_push filters non-PEND jobs itself), so the picker ends up fully rebuilt.", + "fix": "FIXED (2026-09-24). Downgraded to TRACE with a comment explaining the deferral; header comment updated. No test (log-level-only change).", + "tags": [ + "scheduler", + "sim", + "snapshot", + "logging" + ] + }, + { + "id": "bug-1850", + "timestamp": "2026-09-24T05:30:00Z", + "error_message": "OPEN, NOT FIXED -- root trigger of bug-1846 part 2's mid-round rejoins: the live scheduler reconnected/re-joined roughly every ~100s in scheduler-replay-20260923-085356.replay (each rejoin = full config/worker/job re-push from on_scheduler_join()).", + "file": "src/lib/client_failover.c (xcecli_retry_next / xce_failover_classify), src/lib/xceapi.c (10s reply deadline)", + "root_cause": "UNCONFIRMED (code reading only; the live scheduler.log for the capture window isn't available here). The controller never closes a scheduler connection proactively (only handle_disconnect() on a socket error sets XCE_CTX_ERR). But xcecli_retry_next() calls xce_failover_rotate() -> xce_ctx_reconnect() on EVERY retry, and xce_failover_classify() treats ETIMEDOUT (any request whose reply takes >10s, cbuf_deadline_10s in xceapi.c), E_XCE_NOT_READY and E_XCE_REDIRECT/STANDBY as retryable. So a slow or 'not ready' reply to a dispatch/pend-reason publish from a HEALTHY primary rotates the scheduler to the next master (typically a standby, which redirects back), and each reconnect fires the rejoin callback -> sched_check_pending_rejoin() -> xcecli_join() -> full re-push, which adds load and can self-reinforce. Also: a reply arriving after its 10s deadline lands in the capacity-1 wbuf and can be consumed by the NEXT request (xcecli_ctx_recover() drains only one stale entry).", + "fix": "NOT FIXED. Next step: grep the live scheduler.log for 'publish retry-budget exhausted', 'xcecli failover', 'pending rejoin succeeded' around each truncated round to identify the triggering rc. Any fix changes libxce HA client failover semantics (e.g. not rotating away from a primary on ETIMEDOUT/NOT_READY) -> spec workflow per CLAUDE.md, not a drive-by.", + "tags": [ + "libxce", + "client", + "failover", + "reconnect", + "ha", + "scheduler" + ] } ] } diff --git a/src/scheduler/include/sched/types.h b/src/scheduler/include/sched/types.h index 72dd9044..25d3f880 100644 --- a/src/scheduler/include/sched/types.h +++ b/src/scheduler/include/sched/types.h @@ -221,5 +221,8 @@ extern int sched_ctx_get_uncomit_shared(xvec_t**, xce_sched_ctx_t*); extern int sched_ctx_get_uncomit_host(xvec_t**, xce_sched_ctx_t*, int); extern int sched_ctx_uncommit_host(xce_sched_ctx_t*, int, xvec_idval_t*); extern void reset_sched_obj(xce_sched_obj_t*); +/* item killer for xce_sched_obj_t.hlimits: frees one per-worker xlist_t + * (never its vres entries, which the limit plugin's instance table owns). */ +extern void kill_hlimits_list(void*); #endif diff --git a/src/scheduler/src/core_events.c b/src/scheduler/src/core_events.c index 214050c6..9c388bb8 100644 --- a/src/scheduler/src/core_events.c +++ b/src/scheduler/src/core_events.c @@ -183,6 +183,24 @@ static void core_build_alter_schedobj(xce_sched_obj_t* obj, } } +/* core_hlimits_list_killer - obj->hlimits item killer (bug-1848): frees one + * per-worker xlist_t (never its vres entries, owned by the limit plugin). + * A local copy of schedobj.c's kill_hlimits_list() rather than a call into + * it -- this file doesn't share helpers with schedobj.c (see the header + * comment), and the core-isolation test binaries link it without + * schedobj.c. zarray_fini() calls whichever killer was installed. */ +static void core_hlimits_list_killer(void* item) +{ + xlist_t* l = (xlist_t*)item; + + if (l == NULL) { + return; + } + + xlist_fini(l); + free(l); +} + static void core_build_schedobj(xce_sched_obj_t* obj, xce_job_t* j, xce_resreq_t* resreq) { @@ -191,7 +209,7 @@ static void core_build_schedobj(xce_sched_obj_t* obj, xce_job_t* j, obj->project = makeString(j->submit->project_name); xlist_init(&(obj->glimits), 8); - zarray_init(&(obj->hlimits), 32, NULL); + zarray_init(&(obj->hlimits), 32, core_hlimits_list_killer); switch (resreq->tag) { case XCE_RESREQ_PRIMARY: diff --git a/src/scheduler/src/schedobj.c b/src/scheduler/src/schedobj.c index bd13f2e9..9abf8857 100644 --- a/src/scheduler/src/schedobj.c +++ b/src/scheduler/src/schedobj.c @@ -123,7 +123,7 @@ static int make_sched_obj(xce_sched_obj_t* obj, xce_scheduler_t* sched, obj->project = makeString(j->submit->project_name); xlist_init(&(obj->glimits), 8); - zarray_init(&(obj->hlimits), 32, NULL); + zarray_init(&(obj->hlimits), 32, kill_hlimits_list); switch (resreq->tag) { case XCE_RESREQ_PRIMARY: @@ -142,6 +142,25 @@ static int make_sched_obj(xce_sched_obj_t* obj, xce_scheduler_t* sched, return 1; } +/* + * kill_hlimits_list - zarray item killer for xce_sched_obj_t.hlimits. Each + * item is a per-worker xlist_t calloc'd by plugins/limit.c's + * match_job_host_limit_(); its entries are xce_vres_t* owned by the limit + * plugin's instance table, so only the list itself is released. Without it + * reset_sched_obj() and schedobj teardown leaked one list per worker tried. + */ +void kill_hlimits_list(void* item) +{ + xlist_t* l = (xlist_t*)item; + + if (l == NULL) { + return; + } + + xlist_fini(l); + free(l); +} + void reset_sched_obj(xce_sched_obj_t* obj) { xlist_fini(&(obj->glimits)); diff --git a/src/scheduler/src/scheduler.c b/src/scheduler/src/scheduler.c index d6b8ff1d..b9f1d18c 100644 --- a/src/scheduler/src/scheduler.c +++ b/src/scheduler/src/scheduler.c @@ -16,6 +16,7 @@ #include "misc.h" #include "plugin.h" #include "preason.h" +#include "recording.h" #include "resobj.h" #include "resreq.h" #include "sched/alloc_cache.h" @@ -1012,6 +1013,22 @@ int sched_apply_pending_config(xce_scheduler_t* sched) 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. */ + { + xce_core_event_t ev; + + memset(&ev, 0, sizeof(ev)); + ev.ts = xce_core_now(&(sched->core)); + ev.type = XCE_CORE_EVENT_CONFIG_PUSH; + ev.u.config_push.config = config; + sched_record_write_events(sched, &ev, 1); + } + return 1; } diff --git a/src/scheduler/src/snapshot_load.c b/src/scheduler/src/snapshot_load.c index 6a59d1c5..faaa91db 100644 --- a/src/scheduler/src/snapshot_load.c +++ b/src/scheduler/src/snapshot_load.c @@ -42,8 +42,9 @@ * queues/jobs without the config/queue double-application problem * snapshot.c's header documents for the `config` field). Picker resolution * (sched_resolve_job_picker()) is attempted once; on failure, hooks are - * skipped for the whole load with a WARN, mirroring xce_core_push_events()'s - * own defensive posture for the same failure mode. + * skipped for the whole load (TRACE only: the sole caller, sim.c, loads + * before any picker is registered, and sim_bootstrap_picker() replays the + * same walk afterward -- see the call site's own comment). */ /* dup_val - implemented in snapshot_wire.c (see snapshot.c's header @@ -161,6 +162,24 @@ static void snapshot_build_alter_schedobj(xce_sched_obj_t* obj, } } +/* snapshot_hlimits_list_killer - obj->hlimits item killer (bug-1848), a + * local copy of schedobj.c's kill_hlimits_list() / core_events.c's + * core_hlimits_list_killer() per this file's "never share builder helpers" + * convention (header comment above) -- several test binaries link it + * without schedobj.c. Frees one per-worker xlist_t, never its vres + * entries (owned by the limit plugin). */ +static void snapshot_hlimits_list_killer(void* item) +{ + xlist_t* l = (xlist_t*)item; + + if (l == NULL) { + return; + } + + xlist_fini(l); + free(l); +} + static void snapshot_build_schedobj(xce_sched_obj_t* obj, xce_job_t* wj, xce_resreq_t* resreq) { @@ -169,7 +188,7 @@ static void snapshot_build_schedobj(xce_sched_obj_t* obj, xce_job_t* wj, obj->project = makeString(wj->submit->project_name); xlist_init(&(obj->glimits), 8); - zarray_init(&(obj->hlimits), 32, NULL); + zarray_init(&(obj->hlimits), 32, snapshot_hlimits_list_killer); switch (resreq->tag) { case XCE_RESREQ_PRIMARY: @@ -205,11 +224,17 @@ int xce_sched_core_load_snapshot(xce_sched_core_t* core, return -EBUSY; } + /* The only caller, sim.c's sim_locate_and_load_snapshot(), runs before + * the simulation registers its picker, so resolution normally fails + * here -- expected, not a fault: sim_bootstrap_picker() (sim_picker.c, + * bug-1567) replays the same queue/job walk against the restored core + * once the picker exists. TRACE rather than WARN so every sim run + * doesn't print a misleading warning. */ rc = sched_resolve_job_picker(core, &picker); if (rc < 0) { - WARN("%s failed to resolve job picker plugin (rc=%d); picker " - "rebuild will be skipped for this load", - __func__, rc); + TRACE("%s no job picker registered yet (rc=%d); picker rebuild " + "deferred to the driver's own bootstrap", + __func__, rc); picker = NULL; } diff --git a/src/scheduler/testsuite/test_config_push_deferred.c b/src/scheduler/testsuite/test_config_push_deferred.c index 026c302b..bcb16c90 100644 --- a/src/scheduler/testsuite/test_config_push_deferred.c +++ b/src/scheduler/testsuite/test_config_push_deferred.c @@ -23,6 +23,8 @@ * driver applies it between rounds. */ #include +#include +#include #include #include #include @@ -200,9 +202,57 @@ static void test_config_push_mid_session_does_not_end_round(void) printf("test_config_push_mid_session_does_not_end_round: PASS\n"); } +/* The same deferral makes the push recordable: it is now applied at a + * round boundary on the driver thread, exactly where the recorder writes + * the round's other controller events. Before, it bypassed the pending- + * update queue entirely and never reached a .replay file, so a replay + * spanning a rejoin (or a genuine config change) never saw it. */ +static xce_scheduler_t g_rec_sched; + +static void test_applied_config_push_is_recorded(void) +{ + xce_queue_t* q = (xce_queue_t*)calloc(1, sizeof(*q)); + xce_queue_t** queues = (xce_queue_t**)calloc(1, sizeof(*queues)); + xce_conf4sched_t* config = (xce_conf4sched_t*)calloc(1, sizeof(*config)); + FILE* f; + int rc; + + memset(&g_rec_sched, 0, sizeof(g_rec_sched)); + rc = xce_sched_core_init(&(g_rec_sched.core)); + TEST_ASSERT_EQUAL_INT(0, rc); + + f = tmpfile(); + TEST_ASSERT_NOT_NULL(f); + g_rec_sched.recording = true; + g_rec_sched.record_file = f; + + q->queue = strdup(QUEUE_NAME); + queues[0] = q; + config->n_queues = 1; + config->queues = queues; + + TEST_ASSERT_EQUAL_INT(0, sched_stash_config(&g_rec_sched, config)); + TEST_ASSERT_EQUAL_UINT64_MESSAGE(0, g_rec_sched.record_event_count, + "stashing alone must not record"); + + TEST_ASSERT_EQUAL_INT(1, sched_apply_pending_config(&g_rec_sched)); + TEST_ASSERT_EQUAL_UINT64_MESSAGE( + 1, g_rec_sched.record_event_count, + "an applied config push must be written to the recording as one " + "configPush event"); + TEST_ASSERT_TRUE(ftell(f) > 0); + + g_rec_sched.recording = false; + g_rec_sched.record_file = NULL; + fclose(f); + + printf("test_applied_config_push_is_recorded: PASS\n"); +} + int main(void) { UNITY_BEGIN(); RUN_TEST(test_config_push_mid_session_does_not_end_round); + RUN_TEST(test_applied_config_push_is_recorded); return UNITY_END(); } diff --git a/src/scheduler/testsuite/test_limit_host_dedup.c b/src/scheduler/testsuite/test_limit_host_dedup.c index 29a3f73a..fa44c951 100644 --- a/src/scheduler/testsuite/test_limit_host_dedup.c +++ b/src/scheduler/testsuite/test_limit_host_dedup.c @@ -252,9 +252,38 @@ static void test_repeated_host_attempts_stage_host_limit_once(void) printf("test_repeated_host_attempts_stage_host_limit_once: PASS\n"); } +/* reset_sched_obj() (limit_job_election()'s config-version rebuild) and + * schedobj teardown release obj->hlimits through zarray_fini(), which only + * frees items when the zarray has an item killer. The per-worker entries + * are xlist_t's calloc'd by match_job_host_limit_(), and the zarray used to + * be created with a NULL killer, so every rebuild/teardown leaked one list + * per worker the job had tried. (The vres entries inside each list are + * owned by the limit plugin's instance table and must not be freed.) A + * direct LeakSanitizer check isn't usable here -- the fixture's own resreq + * parsing leaks independently -- so this pins the construction contract. */ +static void test_hlimits_zarray_releases_its_lists(void) +{ + xce_sched_job_t* job = sched_get_job(&(g_sched.core), JOB_ID); + + TEST_ASSERT_NOT_NULL_MESSAGE(job, "runs after the dedup test's fixture"); + TEST_ASSERT_EQUAL_PTR_MESSAGE( + (void*)kill_hlimits_list, (void*)job->schedobj->hlimits.killer, + "obj->hlimits must be created with kill_hlimits_list so " + "reset_sched_obj()/teardown free the per-worker lists"); + + /* and a reset must leave it reusable with the same killer */ + reset_sched_obj(job->schedobj); + TEST_ASSERT_EQUAL_PTR((void*)kill_hlimits_list, + (void*)job->schedobj->hlimits.killer); + TEST_ASSERT_NULL(zarray_get(&(job->schedobj->hlimits), 0)); + + printf("test_hlimits_zarray_releases_its_lists: PASS\n"); +} + int main(void) { UNITY_BEGIN(); RUN_TEST(test_repeated_host_attempts_stage_host_limit_once); + RUN_TEST(test_hlimits_zarray_releases_its_lists); return UNITY_END(); }