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

fix(scheduler): activate virtual-clock logging for sim/REPL sessions (Req 5 AC 3)

Browse source 
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).
This commit is contained in:
Rongsong Shen 2026-08-19 11:00:33 +00:00
parent 25e962309f
commit b450a6806b
No known key found for this signature in database
GPG key ID: 5BCDAAE0123E9FE2
4 changed files with 164 additions and 2 deletions
Download patch file Download diff file Expand all files Collapse all files

18
src/scheduler/src/sim.c
View file

@ -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

25
src/scheduler/src/sim_loop.c
View file

@ -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;
}

80
src/scheduler/testsuite/test_sim_event_loop.c
View file

@ -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);

43
src/scheduler/testsuite/test_sim_startup.c
View file

@ -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);