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(); }