From 5ca48206b29b5bfde5d6df3a2f5be974bc488d84 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Thu, 8 Oct 2026 17:33:26 +0000 Subject: [PATCH] test(scheduler-sim-decision-trace): close validation coverage gaps; sync design.md Feature validation round 1: tests for trace off keeping recall (1.5), no logging from REPL trace sources (8.7), reconstructed records in the trace file (8.1) and first in continue mode (7.3), output after trace off matching an untraced run (10.4), and tracing enabled only from the REPL (11.1). design.md now reflects the REPL-side file split, the added API, the dropped file tag and the test files; duplicate trace declarations removed from repl_internal.h. Co-Authored-By: Claude Opus 5.5 (1M context) --- .../scheduler-sim-decision-trace/design.md | 61 +++- src/scheduler/src/repl_internal.h | 9 +- src/scheduler/testsuite/test_sim_isolation.c | 339 ++++++++++++++++++ .../testsuite/test_sim_trace_driver.c | 239 +++++++++++- 4 files changed, 609 insertions(+), 39 deletions(-) diff --git a/.kiro/specs/scheduler-sim-decision-trace/design.md b/.kiro/specs/scheduler-sim-decision-trace/design.md index 5d8b9a29..5d972512 100644 --- a/.kiro/specs/scheduler-sim-decision-trace/design.md +++ b/.kiro/specs/scheduler-sim-decision-trace/design.md @@ -140,22 +140,42 @@ src/scheduler/ │ │ # reconstructed-dispatch record. No I/O. │ ├── sched_trace_internal.h # Helpers shared by the sched_trace*.c files (task 2.4 split to │ │ # stay under the 800-line cap); not installed. -│ ├── repl_trace.c # `trace on|off|status` parsing (raw line), settings lifecycle -│ │ # (next/cur references), session begin/end hooks, file open/close, -│ │ # dev/inode conflict checks, inline emission, shutdown +│ ├── repl_trace.c # `trace on|off|status` parsing (raw line), refcounted settings +│ │ # (next/cur references), file open/close, dev/inode conflict +│ │ # checks, shutdown +│ ├── repl_trace_emit.c # Session begin/end hooks, inline emission (live, trace-only and +│ │ # reconstructed records), file write-error reporting │ ├── repl_trace_store.c # jobid -> latest record index, capture-order eviction at 64 MiB, │ │ # discarded marks, `info trace` (job, array element, array) -│ └── repl_trace_render.c # Record -> lines on one or two FILE* sinks; units mode; jobid fmt; -│ # hierarchy/indent; summary vs full host section; outcome section +│ ├── repl_trace_render.c # Record -> lines on one or two FILE* sinks; units mode; jobid fmt; +│ │ # hierarchy/indent; summary vs full host section +│ ├── repl_trace_render_outcome.c # Renderer, part 2: outcome section (50-host cap), pend reasons, +│ │ # no-decision and reconstructed endings (800-line split) +│ └── repl_trace_render.h # Helpers shared by the two renderer files; not installed └── testsuite/ ├── test_trace_model.c # sched_trace.c + sched_trace_scan.c unit tests ├── test_trace_capture.c # capture helpers against fixture core/schedobj/workers + ├── test_decision_trace.c # XCE_DECISION_TRACE, make_trace_decision, decision->trace transport ├── test_trace_hooks_gate.c # SCHED_TRACE no-evaluation proof; live/non-interactive never trace + ├── test_trace_hooks_alloc_loop.c # sched_allocator hooks: selection, limits, no-decision records + ├── test_trace_hooks_resreq.c # requirement-branch hooks (single, compound, alternatives) + ├── test_trace_host_hooks.c # host pre-filter, host scan and satisfaction-check row hooks + ├── test_trace_hooks_runner.c # alloc_runner hooks: plans, positions, hosts, rollback, commit ├── test_trace_render.c # renderer output per section, units modes, truncation, outcome cap ├── test_trace_store.c # store replace/evict/discarded marks, info trace variants - ├── test_repl_trace_cmd.c # trace command grammar, errors, status, lifecycle, file rules + ├── test_repl_trace_baseline.c # pre-feature REPL transcript baseline (tracing off, 10.4) + ├── test_repl_trace_cmd.c # trace command grammar, errors, status, lifecycle + ├── test_repl_trace_file.c # trace file rules: open errors, conflicts, replace, shutdown + ├── test_repl_trace_emit.c # session hooks, emission order per mode, file copy, write errors + ├── test_repl_trace_wiring.c # repl.c/repl_info.c/repl_params.c routing, interactive-only gates + ├── test_sim_trace_driver.c # sim driver wiring: trace-only path, breakpoints, reconstructed + │ # records, trace off retention and output (1.5, 10.4), 11.3 ├── test_repl_trace_e2e.c # step/continue/breakpoint integration over replay fixtures + │ # (+ test_repl_trace_e2e_fixture.c, test_repl_trace_e2e.h) + ├── test_trace_error_paths.c # fault injection into the real allocator thread + ├── test_trace_bounds.c # line bound and 64 MiB store bound under large traces └── test_trace_equivalence.c # trace on vs off: decisions, --sim-verify, --sim-output, accounting + # (+ test_trace_equivalence_cmp.c, test_trace_equivalence.h) ``` ### Modified Files @@ -188,8 +208,8 @@ src/scheduler/ - reconstructed-dispatch trace in `sim_reconcile_unaccounted_jobs`' report block; - drain loop: `XCE_DECISION_TRACE` handled first, then `xce_repl_check_trace(sim, d)` after `sim_print_decision_gate`; - `xce_repl_trace_session_end(sim)` after the drain loop. -- `src/scheduler/include/repl.h`: `extern` declarations of the forwarded entry points (`repl_trace_session_begin/end`, `repl_trace_on_decision`, `repl_trace_on_trace_only`), following the existing `xce_repl_on_*` pattern so `repl.h` stays self-contained. It also adds inline gates `xce_repl_trace_session_begin/end`, `xce_repl_check_trace` and `xce_repl_check_trace_only`, all forwarding only when `sim->interactive`. -- `src/scheduler/src/repl_internal.h`: `xce_repl_trace_state_t trace` member in `xce_sched_repl_state_t`; declarations for the `repl_trace*` entry points and moved formatting helpers. +- `src/scheduler/include/repl.h`: `extern` declarations of the forwarded entry points (`repl_trace_session_begin/end`, `repl_trace_on_decision`, `repl_trace_on_trace_only`, `repl_trace_on_reconstructed`), following the existing `xce_repl_on_*` pattern so `repl.h` stays self-contained; this is their only declaration site. It also adds inline gates `xce_repl_trace_session_begin/end`, `xce_repl_check_trace`, `xce_repl_check_trace_only` and `xce_repl_trace_reconstructed`, all forwarding only when `sim->interactive`. +- `src/scheduler/src/repl_internal.h`: `xce_repl_trace_state_t trace` member in `xce_sched_repl_state_t`; declarations for the other `repl_trace*` entry points (command, store, renderer, settings file, conflicts, shutdown) and moved formatting helpers. - `src/scheduler/src/repl.c`: dispatch `trace` (passing the raw line); help gains a trailing "Trace" section and an `info trace` line; `repl_cmd_quit` and EOF call `repl_trace_shutdown`. - `src/scheduler/src/repl_info.c`: `info trace` route (one branch); usage string updated; units helpers moved out. - `src/scheduler/src/repl_fmt.c`: receives `translate_units_mode`, `repl_format_numeric_resource_value`, `repl_format_consumable_value_and_used` and `repl_current_units_mode` (behaviour unchanged, now non-static). @@ -449,6 +469,9 @@ void sched_trace_host_begin(xce_sched_trace_rec_t*, const xce_sched_obj_t* obj, const xce_sched_worker_t* w); /* per-host scope */ void sched_trace_pos_scan_error(xce_sched_trace_rec_t*, int err); /* host scan stopped */ void sched_trace_host_verdict(xce_sched_trace_rec_t*, unsigned verdicts, int err); +/* added in implementation (Implementation Notes 1.5, 2.2): */ +void sched_trace_row(xce_sched_trace_rec_t*, const sched_trace_row_t* row); /* CHECK_ROW or held HOST_ROW */ +void sched_trace_host_limit_hit(xce_sched_trace_rec_t*, const char* limit, const char* scope); /* summary tally */ void sched_trace_rollback_host(xce_sched_trace_rec_t*, const char* host); /* one call per released claim */ void sched_trace_commit(xce_sched_trace_rec_t*); /* committed plan = the last plan_begin */ /* end of sched_alloc_search_: one budgeted line; also updates decision-wide counters */ @@ -582,13 +605,15 @@ When rc > 0 or rc < 0 there is no statement; the commit or internal-error entrie #### SimIntegration (`sim_loop.c`, `repl.h` gates) - `xce_repl_trace_session_begin(sim)` runs after `xce_core_begin_session` has succeeded, which means after its `rc < 0` check (`sim_loop.c:1620-1631`), whose failure branch `continue`s without draining. It runs before reconciliation. A failed session begin therefore publishes nothing and holds no settings reference. It resets `rs->trace.round_traced` and `rs->trace.round_flushed` to false in every mode, so a round that ended in step mode (for example continue → breakpoint → `step`) cannot leak the flag into the next continue-mode round. It then sets `cur = next`, then sets `ctl->session_no = rs->session_count` and `ctl->position = 0`, and publishes `sim->core.trace_ctl = cur ? &cur->ctl : NULL`. -- In the reconstructed-dispatch report block (`sim_loop.c:1309-1329`), when `trace_ctl` wants the job, the block builds a `RECONSTRUCTED` record and sets `d->trace = rec` right after `make_dispatch_decision`. The order is then: record add → `sim_print_decision_gate` → `xce_repl_check_trace(sim, d)` → `xce_repl_check_decision(sim, d)` → `sched_trace_rec_free(d->trace)` → `free(d)`. This is the same order as the drain loop, so 7.5 holds for reconstructed dispatches too (2.5). This runs before `signal_go`, so these traces precede the round's live decisions (7.3). +- In the reconstructed-dispatch report block (`sim_loop.c:1309-1329`), when `trace_ctl` wants the job, the block builds a `RECONSTRUCTED` record and sets `d->trace = rec` right after `make_dispatch_decision`, through the gate `xce_repl_trace_reconstructed(sim, d, job)` (`repl_trace_on_reconstructed` in `repl_trace_emit.c`). The order is then: record add → `sim_print_decision_gate` → `xce_repl_check_trace(sim, d)` → `xce_repl_check_decision(sim, d)` → `sched_trace_rec_free(d->trace)` → `free(d)`. This is the same order as the drain loop, so 7.5 holds for reconstructed dispatches too (2.5). This runs before `signal_go`, so these traces precede the round's live decisions (7.3). - Drain loop: - `if (d->op == XCE_DECISION_TRACE) { xce_repl_check_trace_only(sim, d); sched_trace_rec_free(d->trace); free(d); continue; }` comes first. - `xce_repl_check_trace(sim, d)` sits between `sim_print_decision_gate` and `xce_repl_check_decision`. It is a no-op when `d->trace == NULL`. `sched_trace_rec_free(d->trace)` is called just before the existing `free(d)`. - `xce_repl_trace_session_end(sim)` runs after the drain loop, before `plugin_end_session`. It sets `sim->core.trace_ctl = NULL`, drops `cur` (closing its file if it is no longer `next`), and clears the in-progress flag. -#### ReplTraceControl (`src/repl_trace.c`) +#### ReplTraceControl (`src/repl_trace.c`, `src/repl_trace_emit.c`) + +`repl_trace.c` holds the command, status, settings, file and shutdown code; `repl_trace_emit.c` holds the session hooks and inline emission. **Responsibilities & Constraints** - Parses the raw input line for `trace` (1.9, 1.12): @@ -619,13 +644,18 @@ When rc > 0 or rc < 0 there is no statement; the commit or internal-error entrie **Contracts**: Service [x] / State [x] ```c -bool repl_trace_cmd(xce_sched_sim_driver_t* sim, const char* raw_line); /* returns false: re-prompt */ +/* repl_trace.c (declared in repl_internal.h) */ +bool repl_trace_cmd(xce_sched_sim_driver_t* sim, const char* raw_line); /* returns false: re-prompt */ +FILE* repl_trace_settings_file(const xce_repl_trace_settings_t* s); /* NULL: no file */ +bool repl_trace_file_conflicts(const xce_sched_sim_driver_t* sim, const char* path); +void repl_trace_shutdown(xce_sched_sim_driver_t* sim); /* clears trace_ctl, releases cur/next, store_fini */ +/* repl_trace_emit.c (declared in repl.h, called through its interactive-only gates) */ void repl_trace_session_begin(xce_sched_sim_driver_t* sim); void repl_trace_session_end(xce_sched_sim_driver_t* sim); void repl_trace_on_decision(xce_sched_sim_driver_t* sim, xce_decision_t* d); /* takes d->trace */ void repl_trace_on_trace_only(xce_sched_sim_driver_t* sim, xce_decision_t* d); -bool repl_trace_file_conflicts(const xce_sched_sim_driver_t* sim, const char* path); -void repl_trace_shutdown(xce_sched_sim_driver_t* sim); +void repl_trace_on_reconstructed(xce_sched_sim_driver_t* sim, xce_decision_t* d, + const xce_sched_job_t* job); /* attaches a RECONSTRUCTED record (2.5) */ ``` `trace status` output (1.7) shows a block for `cur` ("in effect", when a session is in progress) or `next` ("next session", otherwise), plus a second "replaces at next session" block when `next` differs from `cur`. Each block has enabled, selection (rendered with `repl_fmt_jobid_range`), level, line bound and file. A final line gives stored-trace memory `used / 64 MiB`. @@ -644,6 +674,7 @@ void repl_trace_shutdown(xce_sched_sim_driver_t* sim); ```c void repl_trace_store_put(xce_repl_trace_state_t* ts, xce_sched_trace_rec_t* rec); size_t repl_trace_store_bytes(const xce_repl_trace_state_t* ts); +void repl_trace_store_fini(xce_repl_trace_state_t* ts); /* frees all records; called by repl_trace_shutdown */ bool repl_cmd_info_trace(xce_sched_sim_driver_t* sim, char tokens[][XCE_REPL_TOKEN_LEN], int ntok); /* repl_internal.h: the state block embedded in xce_sched_repl_state_t */ @@ -660,7 +691,7 @@ typedef struct { } xce_repl_trace_state_t; ``` -#### TraceRenderer (`src/repl_trace_render.c`) +#### TraceRenderer (`src/repl_trace_render.c`, `src/repl_trace_render_outcome.c`, private `src/repl_trace_render.h`) **Responsibilities & Constraints** - `repl_trace_render(const xce_sched_trace_rec_t* rec, xce_repl_units_mode_t units, FILE* out1, FILE* out2 /* nullable */)`. @@ -734,7 +765,7 @@ Summary only; no new boundaries. - **TraceSettings** (REPL-owned, reference-counted): `all`, selectors, level, line bound, file (path + `FILE*` + dev/inode), and the `xce_sched_trace_ctl_t` it publishes. It is referenced by `next` and/or `cur` (see Trace settings lifecycle). - **TraceControlBlock** (`xce_sched_trace_ctl_t`, REPL-owned, published to the core for one session): an immutable copy of the selection, level and bound, plus `session_no`, `policy_name` and the allocator-owned `position`. - **TraceRecord** (aggregate root, one per traced selection): - - **Header**: jobid, kind, level, session_no, position, line_bound, the file tag of the settings it was captured under. + - **Header**: jobid, kind, level, session_no, position, line_bound. (The planned "file tag of the settings it was captured under" was dropped in implementation, Implementation Note 4.2: `info trace` is console-only (8.1) and emission writes through the session's `cur` settings, so a record needs no file reference.) - **Selection block**: policy, queue name and priority, job priority, `queue_time`, cluster-wide limits list. - **Entries**: an ordered list. Each entry has a type, a depth, and a payload of copied strings and floats with resource flags. - **Counters**: `plans_tried`, `plans_discarded`, `reqs_none_generated`, `reqs_all_discarded`, `reqs_none_placed`, `host_evals[6]`, `omitted_lines`. diff --git a/src/scheduler/src/repl_internal.h b/src/scheduler/src/repl_internal.h index 78a22570..b281895f 100644 --- a/src/scheduler/src/repl_internal.h +++ b/src/scheduler/src/repl_internal.h @@ -697,12 +697,9 @@ extern void repl_trace_shutdown(xce_sched_sim_driver_t* sim); * with identical bytes, flushes both, and hands the record to the store, * leaving d->trace NULL. A write error on the file is reported once per * session. No-op when d->trace is NULL. + * + * These four, and repl_trace_on_reconstructed, are declared once, in repl.h + * (included above), next to the interactive-only gates that call them. */ -extern void repl_trace_session_begin(xce_sched_sim_driver_t* sim); -extern void repl_trace_session_end(xce_sched_sim_driver_t* sim); -extern void repl_trace_on_decision(xce_sched_sim_driver_t* sim, - xce_decision_t* d); -extern void repl_trace_on_trace_only(xce_sched_sim_driver_t* sim, - xce_decision_t* d); #endif diff --git a/src/scheduler/testsuite/test_sim_isolation.c b/src/scheduler/testsuite/test_sim_isolation.c index ba906bb1..ae0db4d9 100644 --- a/src/scheduler/testsuite/test_sim_isolation.c +++ b/src/scheduler/testsuite/test_sim_isolation.c @@ -76,9 +76,11 @@ * FORBIDDEN_WALLCLOCK here would incorrectly fail on that legitimate, * documented behavior. */ +#include #include #include #include +#include #include @@ -398,6 +400,209 @@ static void assert_no_forbidden_symbols(const char* stripped, const char* label) } } +/* + * Requirement 8.7 (scheduler-sim-decision-trace): the REPL trace sources + * must never write trace content to the scheduler's regular log. They may + * use stdio (the REPL prints), so this is narrower than + * test_core_isolation.c's trace no-I/O scan: no logging header and no + * logging call. utils.h (which the REPL needs) pulls in tlog.h and defines + * the TRACE/DBG/INFO/WARN/ERROR macros, so the calls are what is checked. + * Names match as a call on identifier boundaries, not as a member call, + * with string literals blanked first. + */ +static const char* const REPL_TRACE_LOG_INCLUDES[] = { + "", "\"tlog.h\"", "\"xcelog.h\"", "", "", +}; +static const char* const REPL_TRACE_LOG_CALLS[] = { + "TRACE", "DEBUG", "DBG", "INFO", + "WARN", "ERROR", "FATAL", "SCHEDULER_LOG", + "CONTROLLER_LOG", "XCECD_LOG", "XCECD_WORKER_LOG", + "syslog", "vsyslog", "openlog", +}; +/* identifier prefixes: any call starting with one is a log call */ +static const char* const REPL_TRACE_LOG_PREFIXES[] = { + "tlog", + "xce_log", + "xce_init_xcecd", +}; + +static int is_ident_char(char c) +{ + return ((c >= 'a') && (c <= 'z')) || ((c >= 'A') && (c <= 'Z')) + || ((c >= '0') && (c <= '9')) || (c == '_'); +} + +/* Blanks the contents of string and char literals in place, except on + * #include lines. */ +static void blank_string_literals(char* t) +{ + size_t i = 0; + int in_include = 0; + + while (t[i] != '\0') { + if ((t[i] == '#') && (strncmp(t + i, "#include", 8) == 0)) { + in_include = 1; + } else if (t[i] == '\n') { + in_include = 0; + } + if (((t[i] == '"') || (t[i] == '\'')) && !in_include) { + char q = t[i++]; + + while ((t[i] != '\0') && (t[i] != q) && (t[i] != '\n')) { + if ((t[i] == '\\') && (t[i + 1] != '\0')) { + t[i++] = ' '; + } + t[i++] = ' '; + } + if (t[i] == q) { + i++; + } + continue; + } + i++; + } +} + +/* Offset of the first call to `name` (or, when `prefix`, to any + * identifier starting with `name`) in `t`, or -1. A member call + * (`x.name(` / `x->name(`) and a longer identifier do not count. */ +static long find_call(const char* t, const char* name, int prefix) +{ + size_t n = strlen(name); + const char* p = t; + + for (; (p = strstr(p, name)) != NULL; p += n) { + const char* e = p + n; + + if ((p > t) + && (is_ident_char(p[-1]) || (p[-1] == '.') + || ((p[-1] == '>') && (p - t >= 2) && (p[-2] == '-')))) { + continue; + } + if (prefix) { + while (is_ident_char(*e)) { + e++; + } + } else if (is_ident_char(*e)) { + continue; + } + while ((*e == ' ') || (*e == '\t')) { + e++; + } + if (*e == '(') { + return (long)(p - t); + } + } + return -1; +} + +static void assert_repl_trace_source_never_logs(const char* stripped, + const char* label) +{ + char* t = strdup(stripped); + char msg[512]; + size_t i; + + TEST_ASSERT_NOT_NULL(t); + for (i = 0; i < sizeof(REPL_TRACE_LOG_INCLUDES) / sizeof(char*); i++) { + snprintf(msg, sizeof(msg), "%s includes logging header %s (Req 8.7)", + label, REPL_TRACE_LOG_INCLUDES[i]); + TEST_ASSERT_NULL_MESSAGE(strstr(t, REPL_TRACE_LOG_INCLUDES[i]), msg); + } + blank_string_literals(t); + for (i = 0; i < sizeof(REPL_TRACE_LOG_CALLS) / sizeof(char*); i++) { + snprintf(msg, sizeof(msg), + "%s calls logging macro/function '%s' -- trace content " + "must never reach the scheduler log (Req 8.7)", + label, REPL_TRACE_LOG_CALLS[i]); + TEST_ASSERT_EQUAL_INT_MESSAGE( + -1, find_call(t, REPL_TRACE_LOG_CALLS[i], 0), msg); + } + for (i = 0; i < sizeof(REPL_TRACE_LOG_PREFIXES) / sizeof(char*); i++) { + snprintf(msg, sizeof(msg), + "%s calls a '%s*' logging function -- trace content must " + "never reach the scheduler log (Req 8.7)", + label, REPL_TRACE_LOG_PREFIXES[i]); + TEST_ASSERT_EQUAL_INT_MESSAGE( + -1, find_call(t, REPL_TRACE_LOG_PREFIXES[i], 1), msg); + } + free(t); +} + +/* Offset (>= from) of the next plain assignment `name = ...` (not `==`, + * not a longer identifier) in comment-stripped `t`, or -1. Member + * assignments (`x->name =`, `x.name =`) count. */ +static long find_assignment(const char* t, const char* name, long from) +{ + size_t n = strlen(name); + const char* p = t + from; + + for (; (p = strstr(p, name)) != NULL; p += n) { + const char* e = p + n; + + if (((p > t) && is_ident_char(p[-1])) || is_ident_char(*e)) { + continue; + } + while ((*e == ' ') || (*e == '\t') || (*e == '\n')) { + e++; + } + if ((e[0] == '=') && (e[1] != '=')) { + return (long)(p - t); + } + } + return -1; +} + +/* True when a string literal in comment-stripped `t` contains `word` + * (case-insensitive). */ +static int literal_mentions(const char* t, const char* word) +{ + size_t n = strlen(word); + size_t i = 0; + + while (t[i] != '\0') { + if (t[i] == '\'') { /* skip a char literal */ + i++; + while ((t[i] != '\0') && (t[i] != '\'') && (t[i] != '\n')) { + i += ((t[i] == '\\') && (t[i + 1] != '\0')) ? 2 : 1; + } + i += (t[i] == '\''); + continue; + } + if (t[i] == '"') { + size_t j = i + 1; + + while ((t[j] != '\0') && (t[j] != '"') && (t[j] != '\n')) { + if (strncasecmp(t + j, word, n) == 0) { + return 1; + } + j += ((t[j] == '\\') && (t[j + 1] != '\0')) ? 2 : 1; + } + i = j + (t[j] == '"'); + continue; + } + i++; + } + return 0; +} + +static int dirname_of(const char* path, char* out, size_t out_sz) +{ + const char* slash = strrchr(path, '/'); + size_t n; + + if (slash == NULL) { + return 0; + } + n = (size_t)(slash - path); + if (n + 1 > out_sz) { + return 0; + } + memcpy(out, path, n); + out[n] = '\0'; + return 1; +} + void setUp(void) { return; } void tearDown(void) { return; } @@ -698,12 +903,144 @@ static void test_sim_trace_repl_sources_are_isolated(void) assert_no_forbidden_includes(stripped, paths[i]); assert_no_forbidden_symbols(stripped, paths[i]); + assert_repl_trace_source_never_logs(stripped, paths[i]); free(raw); free(stripped); } } +/* The log scan itself must be able to fail: each class of planted log + * call or include is a hit, and the same names inside literals or longer + * identifiers are not. */ +static void test_repl_trace_log_scan_detects_and_ignores(void) +{ + char ok_text[] = "static const char* s = \"WARN(x) tlog_info(\";\n" + "void f(void) { MY_INFO(1); p->ERROR(2); " + "sched_trace_rec_free(0); fprintf(stdout, \"x\"); }\n"; + char hit_mac[] = "void f(void) { WARN (\"x\"); }\n"; + char hit_tlog[] = "void f(void) { tlog_debug3(\"x\"); }\n"; + char hit_sl[] = "void f(void) { SCHEDULER_LOG(INFO, \"x\"); }\n"; + + blank_string_literals(ok_text); + blank_string_literals(hit_mac); + blank_string_literals(hit_tlog); + blank_string_literals(hit_sl); + TEST_ASSERT_EQUAL_INT(-1, find_call(ok_text, "WARN", 0)); + TEST_ASSERT_EQUAL_INT(-1, find_call(ok_text, "tlog", 1)); + TEST_ASSERT_EQUAL_INT(-1, find_call(ok_text, "INFO", 0)); + TEST_ASSERT_EQUAL_INT(-1, find_call(ok_text, "ERROR", 0)); + TEST_ASSERT_NOT_EQUAL(-1, find_call(hit_mac, "WARN", 0)); + TEST_ASSERT_NOT_EQUAL(-1, find_call(hit_tlog, "tlog", 1)); + TEST_ASSERT_NOT_EQUAL(-1, find_call(hit_sl, "SCHEDULER_LOG", 0)); +} + +/* + * test_trace_enable_is_repl_only - Requirement 11.1: no command-line + * option, configuration setting or administrative request enables + * tracing. Structural proof over every scheduler source and header: + * - the only assignments to `trace_ctl` (the core's published trace + * settings, the one switch the trace hooks test) are in the REPL trace + * sources repl_trace.c / repl_trace_emit.c, plus core.c's reset, which + * must store NULL; + * - no non-REPL source carries a string literal naming "trace" (an + * option, config key or request name would be one), other than an + * #include of the trace headers. The REPL files (repl*.c/h) are the + * interactive command surface and are exempt from this half. + */ +static void scan_trace_enable_dir(const char* dir, int* nfiles) +{ + DIR* d = opendir(dir); + struct dirent* e; + + TEST_ASSERT_NOT_NULL_MESSAGE(d, dir); + while ((e = readdir(d)) != NULL) { + size_t n = strlen(e->d_name); + char path[1024]; + char msg[1200]; + char* raw; + char* t; + long at; + int is_repl, writer_ok, i; + + if ((n < 3) || ((strcmp(e->d_name + n - 2, ".c") != 0) + && (strcmp(e->d_name + n - 2, ".h") != 0))) { + continue; + } + snprintf(path, sizeof(path), "%s/%s", dir, e->d_name); + raw = read_whole_file(path); + TEST_ASSERT_NOT_NULL_MESSAGE(raw, path); + t = strip_c_comments(raw); + TEST_ASSERT_NOT_NULL_MESSAGE(t, path); + (*nfiles)++; + + is_repl = (strncmp(e->d_name, "repl", 4) == 0); + writer_ok = (strcmp(e->d_name, "repl_trace.c") == 0) + || (strcmp(e->d_name, "repl_trace_emit.c") == 0); + for (at = find_assignment(t, "trace_ctl", 0); at >= 0; + at = find_assignment(t, "trace_ctl", at + 1)) { + const char* rhs = strchr(t + at, '=') + 1; + + while ((*rhs == ' ') || (*rhs == '\t')) { + rhs++; + } + snprintf(msg, sizeof(msg), + "%s assigns trace_ctl -- only the REPL trace sources may " + "enable tracing (Req 11.1)", + path); + TEST_ASSERT_TRUE_MESSAGE( + writer_ok + || ((strcmp(e->d_name, "core.c") == 0) + && (strncmp(rhs, "NULL", 4) == 0)), + msg); + } + + if (!is_repl) { + /* drop #include lines, then look for "trace" in a literal */ + for (i = 0; t[i] != '\0'; i++) { + if ((t[i] == '#') && (strncmp(t + i, "#include", 8) == 0)) { + while ((t[i] != '\0') && (t[i] != '\n')) { + t[i++] = ' '; + } + if (t[i] == '\0') { + break; + } + } + } + snprintf(msg, sizeof(msg), + "%s has a string literal naming \"trace\" -- tracing " + "must not be reachable from an option, config key or " + "request (Req 11.1)", + path); + TEST_ASSERT_FALSE_MESSAGE(literal_mentions(t, "trace"), msg); + } + free(raw); + free(t); + } + closedir(d); +} + +static void test_trace_enable_is_repl_only(void) +{ + char src_dir[1024]; + char inc_dir[1024]; + char sub[1100]; + int nfiles = 0; + + TEST_ASSERT_TRUE(dirname_of(XCE_SIM_C_PATH, src_dir, sizeof(src_dir))); + TEST_ASSERT_TRUE(dirname_of(XCE_SIM_H_PATH, inc_dir, sizeof(inc_dir))); + + scan_trace_enable_dir(src_dir, &nfiles); + snprintf(sub, sizeof(sub), "%s/plugins", src_dir); + scan_trace_enable_dir(sub, &nfiles); + scan_trace_enable_dir(inc_dir, &nfiles); + snprintf(sub, sizeof(sub), "%s/sched", inc_dir); + scan_trace_enable_dir(sub, &nfiles); + + /* a guard against scanning an empty or wrong directory */ + TEST_ASSERT_GREATER_THAN_INT(50, nfiles); +} + /* * test_sim_driver_struct_has_no_forbidden_fields - Req 5 AC 17's * "confirmed by the struct definition itself, not runtime checks alone" @@ -826,6 +1163,8 @@ int main(void) RUN_TEST(test_sim_never_includes_forbidden_headers); RUN_TEST(test_sim_never_calls_forbidden_symbols); RUN_TEST(test_sim_trace_repl_sources_are_isolated); + RUN_TEST(test_repl_trace_log_scan_detects_and_ignores); + RUN_TEST(test_trace_enable_is_repl_only); RUN_TEST(test_sim_driver_struct_has_no_forbidden_fields); RUN_TEST(test_sim_object_has_no_forbidden_undefined_symbols); return UNITY_END(); diff --git a/src/scheduler/testsuite/test_sim_trace_driver.c b/src/scheduler/testsuite/test_sim_trace_driver.c index 3fbe01ea..5048a255 100644 --- a/src/scheduler/testsuite/test_sim_trace_driver.c +++ b/src/scheduler/testsuite/test_sim_trace_driver.c @@ -3,8 +3,8 @@ * driver's session and decision flow (scheduler-sim-decision-trace spec, * task 5.3; design.md "SimIntegration", "System Flows" -> "Session * lifecycle and capture" and "Drain-loop emission order", - * "DecisionTransport", "TraceCapture"; Requirements 1.6, 2.5, 7.1, 7.2, - * 7.3, 7.5, 10.1, 11.3). + * "DecisionTransport", "TraceCapture"; Requirements 1.5, 1.6, 2.5, 7.1, + * 7.2, 7.3, 7.5, 8.1, 10.1, 10.4, 11.3). * * Links the real scheduler_srcs (minus main.c), so sched_sim_driver_run() * runs the real picker and allocator threads and the real allocator hooks, @@ -54,6 +54,8 @@ extern int msg_root_has_shape(struct capn* c, capn_ptr* out, size_t want_words, #define TEST_RESREQ ((char*)"select[type==any] rusage[mem=1]") #define JOB_A MAKE_JOBID(1, 2, 1000, 0x0, (uint64_t)41) #define JOB_B MAKE_JOBID(1, 2, 1000, 0x0, (uint64_t)42) +#define JOB_C MAKE_JOBID(1, 2, 1000, 0x0, (uint64_t)43) +#define JOB_D MAKE_JOBID(1, 2, 1000, 0x0, (uint64_t)44) #define BEGIN_ROUND ((uint64_t)2000ULL) void setUp(void) { return; } @@ -262,7 +264,17 @@ static void append_to_run(FILE* f, uint64_t ts, uint64_t jobid) /* A session whose recorded decisions are a DISPATCH of `dispatch_job` on * the worker (0 for none). */ +static void append_session_at(FILE* f, uint64_t begin_round, + uint64_t dispatch_job); + static void append_session(FILE* f, uint64_t dispatch_job) +{ + append_session_at(f, BEGIN_ROUND, dispatch_job); +} + +/* As append_session(), with the session's begin round given. */ +static void append_session_at(FILE* f, uint64_t begin_round, + uint64_t dispatch_job) { sched_dispatch_decision_t dispatch; replay_decision_t rd; @@ -273,11 +285,11 @@ static void append_session(FILE* f, uint64_t dispatch_job) ReplaySession_ptr sp; memset(&session, 0, sizeof(session)); - session.begin_round = BEGIN_ROUND; + session.begin_round = begin_round; if (dispatch_job != 0) { xce_alloc_t* a = make_alloc((char*)"slots", NULL, 1, 1.0, -1); - a->from = BEGIN_ROUND / 1000000000ULL; + a->from = begin_round / 1000000000ULL; memset(&dispatch, 0, sizeof(dispatch)); dispatch.alloc = make_job_alloc( dispatch_job, 1, @@ -286,7 +298,7 @@ static void append_session(FILE* f, uint64_t dispatch_job) memset(&rd, 0, sizeof(rd)); rd.body_which = ReplayDecision_body_dispatch; rd.body.dispatch = &dispatch; - rd.ts = BEGIN_ROUND; + rd.ts = begin_round; decisions[0] = &rd; session.decisions = decisions; session.n_decisions = 1; @@ -570,28 +582,26 @@ static void test_decision_breakpoint_stops_after_its_trace(void) free(out); } -/* 2.5, 7.3: a dispatch rebuilt from the recording is traced as a - * reconstructed record, echoed and printed before the round's live - * decisions. */ -static void test_reconstructed_trace_precedes_live_decisions(void) +/* The reconstructed-dispatch scenario: JOB_A was recorded as dispatched + * in the session (rebuilt by the simulator), JOB_B is decided live. */ +static void reconstructed_replay(run_t* r) { - run_t r; - FILE* f; - char* out; - char echo_a[96], hdr_a[96], hdr_b[96]; - const char *p_echo, *p_hdr, *p_rec, *p_live; + FILE* f = start_replay(r->replay, sizeof(r->replay)); - memset(&r, 0, sizeof(r)); - f = start_replay(r.replay, sizeof(r.replay)); append_job(f, 1500ULL, JOB_A, 1000); append_to_run(f, 1600ULL, JOB_A); append_job(f, 1700ULL, JOB_B, 1001); append_session(f, JOB_A); append_end(f); fclose(f); +} - r.commands = "trace on all\nstep\nquit\n"; - out = run(&r); +/* Asserts the reconstructed record for JOB_A is echoed, traced, and + * printed before JOB_B's live trace in `out`. */ +static void assert_reconstructed_first(const char* out) +{ + char echo_a[96], hdr_a[96], hdr_b[96]; + const char *p_echo, *p_hdr, *p_rec, *p_live; job_marker(echo_a, sizeof(echo_a), "[sim] DISPATCH jobid=%s", JOB_A); job_marker(hdr_a, sizeof(hdr_a), "[trace] job %s session", JOB_A); @@ -609,9 +619,198 @@ static void test_reconstructed_trace_precedes_live_decisions(void) TEST_ASSERT_NOT_NULL_MESSAGE(p_live, "the live decision is traced"); TEST_ASSERT_TRUE_MESSAGE(p_rec < p_live, "the reconstructed trace comes " "before the live decisions"); +} + +/* 2.5, 7.3: a dispatch rebuilt from the recording is traced as a + * reconstructed record, echoed and printed before the round's live + * decisions. */ +static void test_reconstructed_trace_precedes_live_decisions(void) +{ + run_t r; + char* out; + + memset(&r, 0, sizeof(r)); + reconstructed_replay(&r); + r.commands = "trace on all\nstep\nquit\n"; + out = run(&r); + assert_reconstructed_first(out); free(out); } +/* 7.3 in continue mode: the round holding a traced decision is not + * collapsed, and its reconstructed dispatch's trace still comes first, + * before the live decisions' traces. */ +static void test_reconstructed_trace_precedes_live_in_continue_mode(void) +{ + run_t r; + char* out; + + memset(&r, 0, sizeof(r)); + reconstructed_replay(&r); + r.commands = "trace on all\ncontinue\nquit\n"; + out = run(&r); + assert_reconstructed_first(out); + free(out); +} + +/* 8.1: the reconstructed record reaches the trace file, byte-equal to the + * block printed on the console. The file holds only trace records, so the + * record is the text from its header to the next header (or the end). */ +static void test_reconstructed_trace_reaches_file_byte_equal(void) +{ + run_t r; + char fdir[256], fpath[PATH_MAX], cmd[PATH_MAX + 64]; + char hdr_a[96]; + char* out; + char* file; + const char* beg; + const char* nxt; + char* block; + + memset(&r, 0, sizeof(r)); + reconstructed_replay(&r); + make_tmp_dir(fdir, sizeof(fdir), "_file"); + snprintf(fpath, sizeof(fpath), "%s/trace.txt", fdir); + snprintf(cmd, sizeof(cmd), "trace on all file %s\nstep\nquit\n", fpath); + r.commands = cmd; + out = run(&r); + file = slurp(fpath); + + job_marker(hdr_a, sizeof(hdr_a), "[trace] job %s session", JOB_A); + beg = strstr(file, hdr_a); + TEST_ASSERT_NOT_NULL_MESSAGE(beg, "the reconstructed record is in the " + "trace file"); + nxt = strstr(beg + 1, "[trace] job "); + if (nxt == NULL) { + nxt = beg + strlen(beg); + } + block = strndup(beg, (size_t)(nxt - beg)); + TEST_ASSERT_NOT_NULL(block); + TEST_ASSERT_NOT_NULL_MESSAGE( + strstr(block, "dispatch reconstructed from the recorded allocation"), + "the file's record is the reconstructed one"); + TEST_ASSERT_NOT_NULL_MESSAGE(strstr(out, block), + "the file's record is byte-equal to the " + "console block"); + free(block); + free(file); + free(out); +} + +/* Six sessions: JOB_A and JOB_B are decided in the first, JOB_C arrives + * for the second and JOB_D for the third; the last three have nothing new + * (a collapsed range in continue mode). */ +static void multi_session_replay(run_t* r) +{ + FILE* f = start_replay(r->replay, sizeof(r->replay)); + + append_job(f, 1500ULL, JOB_A, 1000); + append_job(f, 1501ULL, JOB_B, 1001); + append_session_at(f, BEGIN_ROUND, 0); + append_job(f, 2500ULL, JOB_C, 1002); + append_session_at(f, BEGIN_ROUND + 1000ULL, 0); + append_job(f, 3500ULL, JOB_D, 1003); + append_session_at(f, BEGIN_ROUND + 2000ULL, 0); + append_session_at(f, BEGIN_ROUND + 3000ULL, 0); + append_session_at(f, BEGIN_ROUND + 4000ULL, 0); + append_session_at(f, BEGIN_ROUND + 5000ULL, 0); + append_end(f); + fclose(f); +} + +/* 1.5: `trace off` keeps the traces already captured. After it, and after + * the next (untraced) session, `info trace` still renders the first + * session's record, while the untraced session stores nothing new. */ +static void test_trace_off_keeps_captured_traces(void) +{ + run_t r; + char cmd[512]; + char hdr_a[96], none_c[128]; + char* out; + const char *p_live, *p_off, *p_info1, *p_info2, *p_none; + + memset(&r, 0, sizeof(r)); + multi_session_replay(&r); + snprintf(cmd, sizeof(cmd), + "trace on all\nstep\ntrace off\ninfo trace %llu\nstep\n" + "info trace %llu\ninfo trace %llu\nquit\n", + (unsigned long long)JOB_A, (unsigned long long)JOB_A, + (unsigned long long)JOB_C); + r.commands = cmd; + out = run(&r); + + job_marker(hdr_a, sizeof(hdr_a), "[trace] job %s session", JOB_A); + job_marker(none_c, sizeof(none_c), + "[sim] info trace: job %s: no trace available", JOB_C); + p_live = strstr(out, hdr_a); + p_off = find_after(out, p_live, "[sim] trace: disabled"); + p_info1 = find_after(out, p_off, hdr_a); + p_info2 = (p_info1 != NULL) ? strstr(p_info1 + 1, hdr_a) : NULL; + p_none = find_after(out, p_info2, none_c); + TEST_ASSERT_NOT_NULL_MESSAGE(p_live, "the first session is traced"); + TEST_ASSERT_NOT_NULL_MESSAGE(p_off, "`trace off` is accepted"); + TEST_ASSERT_NOT_NULL_MESSAGE(p_info1, "right after `trace off`, `info " + "trace` still renders the record"); + TEST_ASSERT_NOT_NULL_MESSAGE(p_info2, "after the next session it still " + "does"); + TEST_ASSERT_NOT_NULL_MESSAGE(p_none, "the untraced session stored no " + "trace"); + free(out); +} + +/* The output after the second "[sim] trace: disabled" line of a run of + * `pre` followed by `trace off` and `post`. */ +static char* output_after_off(const char* pre, const char* post) +{ + run_t r; + char cmd[512]; + char* out; + char* tail; + const char* p; + + memset(&r, 0, sizeof(r)); + multi_session_replay(&r); + snprintf(cmd, sizeof(cmd), "trace off\n%strace off\n%s", pre, post); + r.commands = cmd; + out = run(&r); + p = strstr(out, "[sim] trace: disabled"); + TEST_ASSERT_NOT_NULL(p); + p = strstr(p + 1, "[sim] trace: disabled"); + TEST_ASSERT_NOT_NULL(p); + p = strchr(p, '\n'); + TEST_ASSERT_NOT_NULL(p); + tail = strdup(p + 1); + TEST_ASSERT_NOT_NULL(tail); + free(out); + return tail; +} + +/* 10.4: once tracing is disabled and no traced session is in progress, + * the output is the untraced output. Both runs issue the same commands + * except that the first enables tracing for its first session; the + * untraced run never has tracing on, so it is the pre-feature output. The + * comparison covers everything after the second `trace off` reply: + * session 2 in step mode, sessions 3-6 in continue mode (with the + * collapsed range of the last three) and the replay end. No exclusion + * is needed: the traced round ran in step mode and the next round is a + * step too, so no collapsed range can start at the first round after the + * last traced round (the requirement's one allowed difference). */ +static void test_output_after_trace_off_equals_untraced(void) +{ + static const char* post = "step\ncontinue\nquit\n"; + char* traced; + char* plain; + + traced = output_after_off("trace on all\nstep\n", post); + plain = output_after_off("step\n", post); + TEST_ASSERT_NULL_MESSAGE(strstr(traced, "[trace]"), + "no trace after tracing is disabled"); + TEST_ASSERT_TRUE_MESSAGE(strlen(plain) > 0, "the untraced tail is empty"); + TEST_ASSERT_EQUAL_STRING(plain, traced); + free(traced); + free(plain); +} + /* 11.3: a simulation without the REPL never runs the session hook and the * allocator never sees settings (wraps exit 78/79), while the jobs are * still decided as usual. */ @@ -642,6 +841,10 @@ int main(void) RUN_TEST(test_trace_only_decision_skips_verify_record_and_breakpoints); RUN_TEST(test_decision_breakpoint_stops_after_its_trace); RUN_TEST(test_reconstructed_trace_precedes_live_decisions); + RUN_TEST(test_reconstructed_trace_precedes_live_in_continue_mode); + RUN_TEST(test_reconstructed_trace_reaches_file_byte_equal); + RUN_TEST(test_trace_off_keeps_captured_traces); + RUN_TEST(test_output_after_trace_off_equals_untraced); RUN_TEST(test_non_interactive_run_never_publishes_settings); return UNITY_END(); }