From b450a6806b6754d0aa15fc75f05b32abe55ba7e8 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Wed, 19 Aug 2026 11:00:33 +0000 Subject: [PATCH] fix(scheduler): activate virtual-clock logging for sim/REPL sessions (Req 5 AC 3) sched_sim_driver_start() now registers the core's tlog format function and marks its core active for logging right after the virtual clock is seeded (xce_core_register_tlog_format()/xce_core_set_active_for_logging()) -- every log line for the rest of the run shows frozen/scaled replay time instead of real wall-clock time, matching what an operator debugging against a replay's own timeline needs. sched_sim_driver_run() deactivates on all 7 of its return paths, since there's no sim-driver teardown function and g_active_core_for_logging would otherwise dangle past the caller's stack frame. Also fixes a genuine pre-existing ASAN stack-use-after-return (bug-1598) the new deactivation test exposed: sim_picker_thread_fn is spawned but, by design, never joined/cancelled, so a stack-local `xce_sched_sim_driver_t sim` in test_sim_event_loop.c was always a latent UAF once its owning test function returned -- just not previously triggered by any prior test ordering. Switched the three affected fixtures in that file to `static` storage (safe: sched_sim_driver_start() memsets the whole struct on entry, and none of the three call sites are re-entrant). --- src/scheduler/src/sim.c | 18 +++++ src/scheduler/src/sim_loop.c | 25 ++++++ src/scheduler/testsuite/test_sim_event_loop.c | 80 ++++++++++++++++++- src/scheduler/testsuite/test_sim_startup.c | 43 ++++++++++ 4 files changed, 164 insertions(+), 2 deletions(-) diff --git a/src/scheduler/src/sim.c b/src/scheduler/src/sim.c index eba8e58f..3e3ae6ca 100644 --- a/src/scheduler/src/sim.c +++ b/src/scheduler/src/sim.c @@ -393,6 +393,24 @@ int sched_sim_driver_start(xce_sched_sim_driver_t* sim, sim_set_virtual_clock(sim, snapshot_ts, args->sim_speed); + /* Req 5 AC 3 (design review follow-up, 2026-08-19): activate the + * virtualized clock for tlog logging now that it's seeded -- every + * ERROR/WARN/INFO/TRACE line emitted for the rest of this run shows + * xce_core_now(&sim->core) (frozen/scaled replay time) instead of real + * wall-clock time, matching what an operator debugging against a + * replay's own timeline actually needs. xce_core_register_tlog_format() + * registers the format function globally (idempotent -- safe to call + * again if a caller runs multiple sim sessions in one process, e.g. + * this file's own test suite); xce_core_set_active_for_logging() is the + * per-run pointer swap. sched_sim_driver_run() (sim_loop.c) deactivates + * (sets NULL) on every one of its own return paths -- see that + * function's own comments -- since sim->core is this caller's local/ + * stack-owned struct and a dangling g_active_core_for_logging past + * that point would be a use-after-return the instant this driver's + * caller frame is gone. */ + xce_core_register_tlog_format(); + xce_core_set_active_for_logging(&(sim->core)); + /* Stashed verbatim (task 11.5, Req 5 AC 19) -- see sim.h's own doc * comment on this field for why sim_loop.c's later --sim-output header/ * snapshot write must use THIS captured value, not a fresh diff --git a/src/scheduler/src/sim_loop.c b/src/scheduler/src/sim_loop.c index 23b35730..d910e2e8 100644 --- a/src/scheduler/src/sim_loop.c +++ b/src/scheduler/src/sim_loop.c @@ -470,6 +470,23 @@ static void* sim_picker_thread_fn(void* arg) return NULL; } +/* + * sched_sim_driver_run() -- Req 5 AC 3 (design review follow-up, + * 2026-08-19): sched_sim_driver_start() (sim.c) activates tlog virtual- + * clock logging (g_active_core_for_logging = &sim->core) once the virtual + * clock is seeded. Every return path below deactivates it + * (xce_core_set_active_for_logging(NULL)) unconditionally, even the very + * first one (right after sched_sim_driver_start() itself) -- activation + * happens partway through that call (after the clock seed, before its own + * final two fallible steps: opening --sim-alt-events/--sim-output), so a + * `rc < 0` here does not guarantee activation never happened. There is no + * sim-driver fini()/teardown function to hang this on (this file's own + * header comment notes the same gap for other resources), and `sim` is + * this function's OWN caller's local/stack-owned struct -- left active + * past return, the next tlog call anywhere in the process (including a + * later, unrelated sim run in the same test binary) would read a + * dangling/reused pointer. + */ int sched_sim_driver_run(xce_sched_sim_driver_t* sim, const sched_sim_args_t* args) { @@ -481,6 +498,7 @@ int sched_sim_driver_run(xce_sched_sim_driver_t* sim, rc = sched_sim_driver_start(sim, args); if (rc < 0) { + xce_core_set_active_for_logging(NULL); return rc; } @@ -501,6 +519,7 @@ int sched_sim_driver_run(xce_sched_sim_driver_t* sim, __func__, rc); fclose(sim->record_file); sim->record_file = NULL; + xce_core_set_active_for_logging(NULL); return rc; } } @@ -509,6 +528,7 @@ int sched_sim_driver_run(xce_sched_sim_driver_t* sim, if (rc != 0) { ERROR("%s failed to start the simulation picker thread: %s", __func__, strerror(rc)); + xce_core_set_active_for_logging(NULL); return -rc; } @@ -548,6 +568,7 @@ int sched_sim_driver_run(xce_sched_sim_driver_t* sim, sim->record_file = NULL; } free(buf_events); + xce_core_set_active_for_logging(NULL); return record_rc; } @@ -568,6 +589,7 @@ int sched_sim_driver_run(xce_sched_sim_driver_t* sim, "event batch (buf_n=%d)", __func__, buf_n); free(buf_events); + xce_core_set_active_for_logging(NULL); return -ENOMEM; } @@ -723,6 +745,7 @@ int sched_sim_driver_run(xce_sched_sim_driver_t* sim, fclose(sim->record_file); sim->record_file = NULL; free(buf_events); + xce_core_set_active_for_logging(NULL); return record_rc; } } @@ -766,5 +789,7 @@ int sched_sim_driver_run(xce_sched_sim_driver_t* sim, free(buf_events); + xce_core_set_active_for_logging(NULL); + return 0; } diff --git a/src/scheduler/testsuite/test_sim_event_loop.c b/src/scheduler/testsuite/test_sim_event_loop.c index a453e8d8..ef928e51 100644 --- a/src/scheduler/testsuite/test_sim_event_loop.c +++ b/src/scheduler/testsuite/test_sim_event_loop.c @@ -509,7 +509,23 @@ test_run_processes_multiple_sessions_in_order_and_no_longer_returns_enosys(void) char path[PATH_MAX]; FILE* f; sched_sim_args_t args; - xce_sched_sim_driver_t sim; + /* static, not stack-local (2026-08-19 ASAN finding): sched_sim_driver_ + * run() spawns sim_picker_thread_fn (sim_loop.c) on a real pthread that + * is, by this codebase's own documented design, "never joined or + * cancelled: no sim-driver teardown/fini function exists yet" (that + * function's own header comment) -- it loops forever on + * cbuf_get(&sim.core.wbuf, ...), reading `sim` for the lifetime of the + * process. A stack-local `sim` here would make that a genuine stack- + * use-after-return the instant this test function returns (a later + * test's own stack frame reusing the same address triggers ASAN's + * detector -- reproduced live when a new test was added between this + * one and its neighbor). `static` storage sidesteps it cheaply: the + * zombie thread keeps reading valid (if stale) memory instead of a + * freed stack frame. This does not fix the underlying thread-lifecycle + * gap (a real fix needs an actual sim-driver teardown function, out of + * scope here) -- it only makes this test suite safe to run under ASAN + * regardless of test ordering/stack layout. */ + static xce_sched_sim_driver_t sim; int rc; f = write_header_and_snapshot(path, sizeof(path), "_run"); @@ -553,6 +569,62 @@ test_run_processes_multiple_sessions_in_order_and_no_longer_returns_enosys(void) "returns_enosys: PASS\n"); } +/* ---------------------------------------------------------------------- */ +/* Test 2b (design review follow-up, Req 5 AC 3): sched_sim_driver_run() */ +/* must deactivate tlog's virtual-clock logging on completion -- it has no */ +/* fini()/teardown function, and sched_sim_driver_start() (called */ +/* internally) activates logging via g_active_core_for_logging = &sim.core */ +/* (core_clock.c's module-static, white-box #included above). Left active */ +/* past this call, `sim` (this test's own local/stack struct) would be a */ +/* dangling reference the moment this function returns -- and in a real */ +/* process running MULTIPLE sim sessions back to back (or, in this test */ +/* binary, any later test calling tlog after this one returns), every */ +/* subsequent log line would read a stale/dangling core pointer. Seed a */ +/* bogus non-NULL sentinel first (simulating "a prior run left this set") */ +/* so the assertion genuinely proves deactivation happened, not just that */ +/* nothing ever touched it. */ +/* ---------------------------------------------------------------------- */ + +static void +test_run_deactivates_tlog_virtual_clock_logging_on_completion(void) +{ + char path[PATH_MAX]; + FILE* f; + sched_sim_args_t args; + /* static -- see test_run_processes_multiple_sessions_in_order_and_no_ + * longer_returns_enosys()'s own comment on this same pattern above: the + * picker thread sched_sim_driver_run() spawns is never joined, so a + * stack-local `sim` here is a stack-use-after-return once this + * function returns (this is in fact the exact test whose addition + * first surfaced that ASAN finding live). */ + static xce_sched_sim_driver_t sim; + int rc; + + f = write_header_and_snapshot(path, sizeof(path), "_tlogdeactivate"); + TEST_ASSERT_NOT_NULL(f); + append_end_of_stream_marker(f); + fclose(f); + + memset(&args, 0, sizeof(args)); + args.replay_path = path; + args.sim_start_ts = SCHED_SIM_START_TS_LATEST; + args.sim_speed = 0; + + xce_core_set_active_for_logging((xce_sched_core_t*)0x1); /* bogus sentinel */ + + rc = sched_sim_driver_run(&sim, &args); + TEST_ASSERT_EQUAL_INT(0, rc); + + TEST_ASSERT_NULL_MESSAGE( + g_active_core_for_logging, + "sched_sim_driver_run() must deactivate tlog virtual-clock logging " + "before returning -- otherwise later log calls dereference this " + "now-out-of-scope sim.core"); + + printf("test_run_deactivates_tlog_virtual_clock_logging_on_completion:" + " PASS\n"); +} + /* ---------------------------------------------------------------------- */ /* Test 3 (bug-1567 regression): a job/queue already present in the */ /* INITIAL snapshot -- as opposed to arriving later via a ReplayEvent -- */ @@ -631,7 +703,10 @@ static FILE* write_header_and_snapshot_with_pending_job(char* out_path, static char* run_sim_and_capture_stdout(const char* path, int* out_rc) { sched_sim_args_t args; - xce_sched_sim_driver_t sim; + /* static -- same never-joined-picker-thread hazard documented on + * test_run_processes_multiple_sessions_in_order_and_no_longer_returns_ + * enosys()'s own `sim` declaration above. */ + static xce_sched_sim_driver_t sim; char tmp[] = "/tmp/xce_simloop_run_XXXXXX"; int fd = mkstemp(tmp); int saved_stdout; @@ -742,6 +817,7 @@ int main(void) test_process_replay_event_advances_virtual_clock_to_exact_event_ts_in_file_order); RUN_TEST( test_run_processes_multiple_sessions_in_order_and_no_longer_returns_enosys); + RUN_TEST(test_run_deactivates_tlog_virtual_clock_logging_on_completion); RUN_TEST( test_job_present_only_in_initial_snapshot_still_reaches_the_picker); diff --git a/src/scheduler/testsuite/test_sim_startup.c b/src/scheduler/testsuite/test_sim_startup.c index cd58a9e7..1e2dfcfc 100644 --- a/src/scheduler/testsuite/test_sim_startup.c +++ b/src/scheduler/testsuite/test_sim_startup.c @@ -378,6 +378,48 @@ test_valid_fixture_reaches_ready_state_with_frozen_virtual_clock(void) " PASS\n"); } +/* ---------------------------------------------------------------------- */ +/* Test 1b (design review follow-up, Req 5 AC 3): sched_sim_driver_start() */ +/* must activate the core's virtual clock for tlog logging -- otherwise */ +/* every log line emitted during a --sim/--interactive run shows real */ +/* wall-clock time instead of the frozen/virtual replay timestamp, */ +/* defeating the whole point of debugging against a replay's own timeline. */ +/* g_active_core_for_logging is core_clock.c's module-static (white-box */ +/* #include above puts it in this TU) -- direct inspection is simpler and */ +/* more precise than round-tripping through tlog's own formatter, which */ +/* test_clock.c already covers at the unit level. */ +/* ---------------------------------------------------------------------- */ + +static void test_valid_fixture_activates_virtual_clock_for_tlog_logging(void) +{ + char path[PATH_MAX]; + uint64_t snapshot_ts = 0; + sched_sim_args_t args; + xce_sched_sim_driver_t sim; + int rc; + + /* Defensive reset -- other tests in this same process may have left + * g_active_core_for_logging pointing at a since-destroyed core. */ + xce_core_set_active_for_logging(NULL); + + write_valid_fixture(path, sizeof(path), &snapshot_ts, "_tlogactivate"); + + memset(&args, 0, sizeof(args)); + args.replay_path = path; + args.sim_start_ts = SCHED_SIM_START_TS_LATEST; + args.sim_speed = 0; + + rc = sched_sim_driver_start(&sim, &args); + TEST_ASSERT_EQUAL_INT(0, rc); + + TEST_ASSERT_EQUAL_PTR(&(sim.core), g_active_core_for_logging); + + xce_core_set_active_for_logging(NULL); /* leave clean for later tests */ + + printf("test_valid_fixture_activates_virtual_clock_for_tlog_logging:" + " PASS\n"); +} + /* ---------------------------------------------------------------------- */ /* Test 2: starting against a file missing its initial snapshot entry */ /* fails with a clear error before any event is processed -- this task's */ @@ -496,6 +538,7 @@ int main(void) UNITY_BEGIN(); RUN_TEST(test_valid_fixture_reaches_ready_state_with_frozen_virtual_clock); + RUN_TEST(test_valid_fixture_activates_virtual_clock_for_tlog_logging); RUN_TEST(test_missing_initial_snapshot_entry_fails_cleanly); RUN_TEST(test_first_message_not_replayheader_fails_cleanly); RUN_TEST(test_missing_replay_file_fails_cleanly);