fix(scheduler): sim_print_decision() bypassed tlog, producing inconsistent PEND/DISPATCH/PREEMPT output

xce_scheduler link-wraps printf (-Wl,--wrap=printf, src/meson.build's
wrap_link_args) to route every plain printf() call through tlog, stamping
the full "[timestamp] [pid] [LEVEL] [xce_vprintf]" prefix. sim_print_decision()
(sim_loop.c) used plain printf() for its DISPATCH/PEND/PREEMPT lines, so
those lines carried that prefix while every sibling "[sim] ..." line in
the same REPL/sim output (event echoes, breakpoint hits, banners, info
command output -- all fprintf(stdout, ...)) stayed prefix-free. Found via
a live deployment log. Switched to fprintf(stdout, ...), matching the
established convention everywhere else in this codebase.

Invisible to the entire prior test suite for a structural reason: only
the real xce_scheduler executable links with wrap_link_args, not the
white-box unit-test binaries, so printf() and fprintf(stdout, ...) were
indistinguishable inside any unit test. Added a mechanical regression
guard instead of a runtime test: test_no_bare_printf.c source-scans every
src/scheduler/src/*.c and src/scheduler/src/plugins/*.c file for a bare
printf( call (same source-text-scan genre as test_core_isolation.c).
This commit is contained in:
Rongsong Shen 2026-08-20 03:02:48 +00:00
parent 9f6d9294df
commit 8cb304d29a
No known key found for this signature in database
GPG key ID: 5BCDAAE0123E9FE2
3 changed files with 222 additions and 3 deletions

View file

@ -371,6 +371,19 @@ extern void sim_bootstrap_picker(xce_sched_sim_driver_t* sim);
* (sim->record_file) and the --sim-verify comparison branch (sim->verify)
* are sibling tasks 11.5/11.4's own jobs, deliberately not built here (see
* this file's own header comment).
*
* Uses fprintf(stdout, ...), never a bare call to the plain printf symbol
* (2026-08-20 fix): this project link-wraps printf (--wrap=printf,
* src/lib/wrap.c's __wrap_printf() -> xce_vprintf()) to route every such
* bare call through tlog, which stamps the full "[timestamp] [pid] [LEVEL]
* [xce_vprintf]" prefix -- a real, deployment-observed inconsistency where
* PEND/DISPATCH/PREEMPT lines carried that prefix while every sibling
* "[sim] ..." line in this same REPL/sim family (event echoes in
* repl_break.c, breakpoint hits and banners in repl.c, state-inspection
* output in repl_info.c -- all fprintf(stdout, ...)) stayed prefix-free.
* fprintf(stdout, ...) is not `printf` at the symbol level, so the linker
* wrap never intercepts it -- matching the established convention every
* other REPL/sim print call site in this codebase already follows.
*/
static void sim_print_decision(const xce_decision_t* d)
{
@ -382,15 +395,15 @@ static void sim_print_decision(const xce_decision_t* d)
switch (d->op) {
case XCE_DECISION_DISPATCH:
fmt_jobid(jobidStr, sizeof(jobidStr), d->u.alloc->jobid);
printf("[sim] DISPATCH jobid=%s\n", jobidStr);
fprintf(stdout, "[sim] DISPATCH jobid=%s\n", jobidStr);
break;
case XCE_DECISION_PEND:
fmt_jobid(jobidStr, sizeof(jobidStr), d->u.reason->jobid);
printf("[sim] PEND jobid=%s\n", jobidStr);
fprintf(stdout, "[sim] PEND jobid=%s\n", jobidStr);
break;
case XCE_DECISION_PREEMPT:
fmt_jobid(jobidStr, sizeof(jobidStr), d->u.preempt->jobid);
printf("[sim] PREEMPT jobid=%s\n", jobidStr);
fprintf(stdout, "[sim] PREEMPT jobid=%s\n", jobidStr);
break;
default:
break;

View file

@ -219,6 +219,25 @@ sched_core_isolation_test = executable(
+ '"'],
install: false)
# Regression guard (2026-08-20) for the "PEND/DISPATCH/PREEMPT lines carried
# an unexpected tlog prefix" bug -- see test_no_bare_printf.c's own header
# comment for the full rationale (xce_scheduler link-wraps printf via
# wrap_link_args above; fprintf(stdout, ...) is the required convention).
# Directory-path defines (not one per file, like XCE_CORE_C_PATH above) so
# a future new .c file in either directory is automatically covered.
sched_no_bare_printf_test = executable(
'sched_no_bare_printf_test',
['test_no_bare_printf.c'],
include_directories:[incdir],
dependencies: [scheduler_test_deps],
c_args: ['-DXCE_SCHEDULER_SRC_DIR="'
+ (meson.current_source_dir() / '..' / 'src')
+ '"',
'-DXCE_SCHEDULER_PLUGINS_DIR="'
+ (meson.current_source_dir() / '..' / 'src' / 'plugins')
+ '"'],
install: false)
# Regression guard for task 4.2's jbuf-capacity half (scheduler-core spec,
# Req 5 AC 7): "cbuf capacity=1 serialization ... this capacity is a
# determinism invariant, not a tuning knob." Same white-box #include
@ -947,6 +966,9 @@ test('scheduler pendreason factory audit test',
test('scheduler core isolation test',
sched_core_isolation_test, suite: 'scheduler',
env: ['ASAN_OPTIONS=detect_leaks=0'])
test('scheduler no bare printf test',
sched_no_bare_printf_test, suite: 'scheduler',
env: ['ASAN_OPTIONS=detect_leaks=0'])
test('scheduler core jbuf capacity pin test',
sched_core_jbuf_capacity_pin_test, suite: 'scheduler',
env: ['ASAN_OPTIONS=detect_leaks=0'])

View file

@ -0,0 +1,184 @@
/*
* test_no_bare_printf.c - regression guard for the "PEND/DISPATCH/PREEMPT
* lines carried an unwanted tlog prefix" bug (2026-08-20, live-deployment
* finding): `xce_scheduler` (unlike the scheduler's white-box test
* binaries) links with `-Wl,--wrap=printf` (src/meson.build's
* `wrap_link_args`, applied via `link_args` in scheduler/meson.build) --
* every plain `printf(...)` call is silently intercepted at link time and
* rerouted through `xce_vprintf()`/tlog (`src/lib/wrap.c`'s
* `__wrap_printf()`), stamping the full "[timestamp] [pid] [LEVEL]
* [xce_vprintf]" prefix. `fprintf(stdout, ...)` is a different symbol at
* the linker level, so the wrap never intercepts it -- and every REPL/sim
* print call site in this codebase (event echoes, breakpoint hits,
* banners, state-inspection output) already uses `fprintf(stdout, ...)`.
* `sim_loop.c`'s `sim_print_decision()` was the one holdout still using
* plain `printf()`, producing PEND/DISPATCH/PREEMPT lines visually
* inconsistent with every sibling "[sim] ..." line in the same session's
* output -- invisible to this codebase's entire existing test suite,
* because none of the white-box unit-test binaries link with
* `wrap_link_args` at all (only the real `xce_scheduler` executable
* does), so `printf()` and `fprintf(stdout, ...)` are indistinguishable
* inside a unit test. A live full-binary smoke test could catch it, but
* only if it happens to display a PEND/DISPATCH line -- fragile. This
* test instead mechanically enforces the underlying rule project-wide:
* a plain source-text scan (same genre as test_core_isolation.c's
* forbidden-symbol scan) of every `src/scheduler/src/*.c` and
* `src/scheduler/src/plugins/*.c` file, failing on any bare `printf(`
* call (`fprintf`/`snprintf`/`vprintf`/`vfprintf`/`sprintf` are all
* excluded by requiring the character immediately before `printf(` to be
* neither a letter, digit, nor underscore).
*/
#include <dirent.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unity/unity.h>
#ifndef XCE_SCHEDULER_SRC_DIR
#error \
"XCE_SCHEDULER_SRC_DIR must be defined by meson.build to src/scheduler/src's absolute path"
#endif
#ifndef XCE_SCHEDULER_PLUGINS_DIR
#error \
"XCE_SCHEDULER_PLUGINS_DIR must be defined by meson.build to src/scheduler/src/plugins's absolute path"
#endif
void setUp(void) { return; }
void tearDown(void) { return; }
static char* read_whole_file(const char* path)
{
FILE* f = fopen(path, "rb");
long len;
char* buf;
size_t nread;
if (f == NULL) {
return NULL;
}
if (fseek(f, 0, SEEK_END) != 0) {
fclose(f);
return NULL;
}
len = ftell(f);
if (len < 0) {
fclose(f);
return NULL;
}
rewind(f);
buf = (char*)malloc((size_t)len + 1);
if (buf == NULL) {
fclose(f);
return NULL;
}
nread = fread(buf, 1, (size_t)len, f);
fclose(f);
buf[nread] = '\0';
return buf;
}
/* True iff `text` contains a call to the bare `printf` symbol -- i.e. a
* "printf(" substring whose immediately preceding character is neither a
* letter, digit, nor underscore (so "fprintf("/"snprintf("/"vprintf("/
* "vfprintf("/"sprintf(" are all correctly excluded). No comment/string-
* literal awareness, matching test_core_isolation.c's own established
* precedent for this text-scan genre in this codebase. */
static int contains_bare_printf_call(const char* text)
{
const char* p = text;
for (;;) {
p = strstr(p, "printf(");
if (p == NULL) {
return 0;
}
if (p == text) {
return 1; /* "printf(" at the very start of the file */
}
{
char prev = *(p - 1);
if (!(((prev >= 'a') && (prev <= 'z'))
|| ((prev >= 'A') && (prev <= 'Z'))
|| ((prev >= '0') && (prev <= '9')) || (prev == '_'))) {
return 1;
}
}
p += strlen("printf(");
}
}
/* Scans every "*.c" file directly inside `dir` (non-recursive) for a bare
* printf( call, failing the test with the offending file's name if found.
* Also asserts at least one "*.c" file was actually scanned -- a wrong/
* empty directory path would otherwise make this test vacuously pass. */
static void scan_dir_for_bare_printf(const char* dir)
{
DIR* dp;
struct dirent* entry;
int n_scanned = 0;
dp = opendir(dir);
TEST_ASSERT_NOT_NULL_MESSAGE(dp, dir);
while ((entry = readdir(dp)) != NULL) {
size_t namelen = strlen(entry->d_name);
char path[4096];
char* text;
if ((namelen < 3)
|| (strcmp(entry->d_name + namelen - 2, ".c") != 0)) {
continue;
}
snprintf(path, sizeof(path), "%s/%s", dir, entry->d_name);
text = read_whole_file(path);
TEST_ASSERT_NOT_NULL_MESSAGE(text, path);
n_scanned++;
if (contains_bare_printf_call(text)) {
char msg[4096];
snprintf(msg, sizeof(msg),
"%s calls bare printf() -- xce_scheduler link-wraps "
"printf (-Wl,--wrap=printf) so this would silently "
"gain a tlog prefix real output doesn't have; use "
"fprintf(stdout, ...) instead, matching every other "
"REPL/sim print call site in this codebase",
path);
free(text);
closedir(dp);
TEST_FAIL_MESSAGE(msg);
}
free(text);
}
closedir(dp);
TEST_ASSERT_TRUE_MESSAGE(
n_scanned > 0,
"zero .c files found -- the directory path is likely wrong (this "
"test would otherwise pass vacuously)");
}
static void test_scheduler_src_has_no_bare_printf_calls(void)
{
scan_dir_for_bare_printf(XCE_SCHEDULER_SRC_DIR);
}
static void test_scheduler_plugins_has_no_bare_printf_calls(void)
{
scan_dir_for_bare_printf(XCE_SCHEDULER_PLUGINS_DIR);
}
int main(void)
{
UNITY_BEGIN();
RUN_TEST(test_scheduler_src_has_no_bare_printf_calls);
RUN_TEST(test_scheduler_plugins_has_no_bare_printf_calls);
return UNITY_END();
}