From 6a2aa47f5e1aaf08573d633fd70efea8ca72e1bb Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Thu, 3 Sep 2026 03:54:01 +0000 Subject: [PATCH] test(scheduler-sim-step-verbosity): task 1.1 - RED tests for preamble dedup Adds 6 failing tests for the Event Echo Preamble Deduplicator (Requirements 1.1-1.4, 2.2): a second echoed event sharing its predecessor's rendered timestamp+session omits its preamble; two events across a session boundary both print their own preamble; the critical raw-vs-rendered nuance (Requirement 1.3) - two events whose raw nanosecond timestamps genuinely differ but whose rendered, second-granularity timestamp and session are identical still dedupe, with a fixture-premise self-check proving the two raw values really do render identically; the first echoed event in a fresh session always prints its preamble; a structural event under continue mode after suppressed routine events follows the same rule; event content and ordering are unaffected regardless of the preamble decision. Lands in a new test_repl_step_verbosity.c (1010 lines, 6 tests) rather than extending test_repl_event_echo.c (705 lines) - proactive split per this file family's established practice, since appending would have pushed that file well past the project's ~1000-line trigger. Registered in testsuite/meson.build. No production code touched. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01YAWMhfRJFnmmnG8h97yUDd --- .../scheduler-sim-step-verbosity/tasks.md | 2 +- src/scheduler/testsuite/meson.build | 39 + .../testsuite/test_repl_step_verbosity.c | 1010 +++++++++++++++++ 3 files changed, 1050 insertions(+), 1 deletion(-) create mode 100644 src/scheduler/testsuite/test_repl_step_verbosity.c diff --git a/.kiro/specs/scheduler-sim-step-verbosity/tasks.md b/.kiro/specs/scheduler-sim-step-verbosity/tasks.md index d335a5fe..e2f65a26 100644 --- a/.kiro/specs/scheduler-sim-step-verbosity/tasks.md +++ b/.kiro/specs/scheduler-sim-step-verbosity/tasks.md @@ -1,7 +1,7 @@ # Implementation Plan - [ ] 1. Core: event echo preamble deduplication -- [ ] 1.1 Write failing tests for preamble deduplication across consecutive echoed events +- [x] 1.1 Write failing tests for preamble deduplication across consecutive echoed events - Cover: two consecutive echoed events with identical rendered timestamp and session omit the second's preamble; two consecutive events with a different session both print their own preamble; two consecutive events whose raw high-resolution timestamps differ but whose rendered timestamp and session are identical still dedupe; the first echoed event in a fresh REPL session always prints its preamble; a structural event echoed under continue mode after a stretch of suppressed routine events follows the same rule; every event's own content line and ordering remain present and unaffected regardless of the preamble decision - Observable: the new test cases fail against today's REPL, which prints the timestamp/session preamble unconditionally before every echoed event - After adding the new test cases, check `test_repl_event_echo.c`'s resulting line count against this project's ~1000-line split trigger (design.md's File Structure Plan); if approached or exceeded, split the preamble-dedup tests into a new `test_repl_step_verbosity.c` (duplicating shared fixture helpers per this file family's established convention) and register the new file's test target in `testsuite/meson.build` diff --git a/src/scheduler/testsuite/meson.build b/src/scheduler/testsuite/meson.build index 4834a7ef..28a39b61 100644 --- a/src/scheduler/testsuite/meson.build +++ b/src/scheduler/testsuite/meson.build @@ -965,6 +965,42 @@ sched_repl_event_echo_test = executable( dependencies: [scheduler_test_deps, libedit_dep], install: false) +# Contract test for the interactive simulation REPL's Event Echo Preamble +# Deduplicator component (scheduler-sim-step-verbosity spec, task 1.1, +# Requirements 1 and 2 "collapse the repeated timestamp/session preamble +# across consecutive same-context echoed events"): two consecutive echoed +# events sharing the same rendered (second-granularity) timestamp and +# displayed session omit the second's preamble line while still printing +# its own content line; events spanning a session boundary each print their +# own full preamble; two events whose raw high-resolution timestamps differ +# but whose rendered timestamp and session are identical still dedupe (the +# design's central "rendered value, not raw ns" nuance); the first echoed +# event of a fresh REPL session always prints its preamble; the same rule +# applies to a structural event echoed under `continue` mode after a +# stretch of suppressed routine events; and event content/ordering stay +# unaffected by the preamble decision at N=3 consecutive same-context +# events. THIS TASK (1.1) IS RED-PHASE ONLY -- see this file's own header +# comment. Same white-box #include pattern and forked-child/real-stdout- +# capture technique as sched_repl_event_echo_test above (core.c, +# core_clock.c, core_events.c, core_session.c, decision.c, plugin.c, +# plugins/builtin_fcfs.c, recording.c, recording_session.c, sim.c, +# sim_loop.c, sim_record.c, sim_verify.c, +# snapshot.c/snapshot_wire.c/snapshot_load.c, repl.c, repl_fmt.c, +# repl_rollup.c, repl_break.c, repl_info.c, repl_params.c). Split into its +# own file from the start rather than appended to test_repl_event_echo.c +# (705 lines before this feature) -- design.md's File Structure Plan flags +# this file's ~1000-line split trigger, and this task's six behavioral +# cases plus their own preamble-construction helper would have pushed it +# well past that threshold; the same reasoning that already split +# test_repl_round_rollup.c/test_repl_event_echo.c/test_repl_prompt_context.c/ +# test_sim_print_decision_gate.c out of test_repl_execution_control.c. +sched_repl_step_verbosity_test = executable( + 'sched_repl_step_verbosity_test', + ['test_repl_step_verbosity.c'], + include_directories:[incdir], + dependencies: [scheduler_test_deps, libedit_dep], + install: false) + # Contract test for the interactive simulation REPL's Prompt Context # component (scheduler-sim-repl-verbosity spec, task 6.1, Requirement 5.5 # "REPL prompt shows session/timestamp"): the readline() prompt is the @@ -1563,6 +1599,9 @@ test('scheduler repl round rollup test', test('scheduler repl event echo test', sched_repl_event_echo_test, suite: 'scheduler', env: ['ASAN_OPTIONS=detect_leaks=0']) +test('scheduler repl step verbosity test', + sched_repl_step_verbosity_test, suite: 'scheduler', + env: ['ASAN_OPTIONS=detect_leaks=0']) test('scheduler repl prompt context test', sched_repl_prompt_context_test, suite: 'scheduler', env: ['ASAN_OPTIONS=detect_leaks=0']) diff --git a/src/scheduler/testsuite/test_repl_step_verbosity.c b/src/scheduler/testsuite/test_repl_step_verbosity.c new file mode 100644 index 00000000..f5a2888c --- /dev/null +++ b/src/scheduler/testsuite/test_repl_step_verbosity.c @@ -0,0 +1,1010 @@ +/* + * test_repl_step_verbosity.c - contract test for the interactive simulation + * REPL's Event Echo Preamble Deduplicator component + * (scheduler-sim-step-verbosity spec, task 1.1, Requirements 1 and 2): the + * "[sim] t= () session=" preamble line + * repl_print_event_summary() (repl_break.c) prints immediately before an + * echoed event's own content line should print once per distinct + * (rendered second-granularity timestamp, displayed session) run of + * consecutive echoed events, not once per event -- leaving which events are + * echoed, their own content, and their ordering completely unchanged. + * + * Split into its own file from the start (rather than appended to the + * sibling test_repl_event_echo.c) -- design.md's File Structure Plan flags + * that file's ~1000-line split trigger: it was already 705 lines + * (scheduler-sim-repl-verbosity's Event Echo Gate tests) before this + * feature began, and this task's six behavioral cases plus their own + * preamble-construction helper would have pushed it well past that + * threshold. Following this file family's established convention (see + * test_repl_event_echo.c's own header comment on why IT split out of + * test_repl_execution_control.c, and test_repl_round_rollup.c before it), + * this file duplicates -- rather than shares via a new header -- the + * pre-existing static fixture helpers it needs from test_repl_event_echo.c. + * + * Fixture strategy and white-box #include set: identical to + * test_repl_event_echo.c/test_repl_round_rollup.c/ + * test_repl_execution_control.c (see those files' own header comments) -- + * this file exercises the same real sched_sim_driver_run() end-to-end, + * forked-child, real-stdout-capture technique. Discrete-simulation + * determinism note (research.md's own key finding, load-bearing for every + * test below): `child_run_repl_and_exit()` sets args.sim_speed = 0, which + * sim_set_virtual_clock() (sim.c) stores as core.speed_num == 0; with + * speed_num == 0, xce_core_now()'s (core_clock.c) `elapsed * num / den` term + * is always exactly zero, so xce_core_now() returns EXACTLY the raw + * nanosecond `ts` value most recently passed to sim_advance_virtual_clock() + * (sim_loop.c) for the event just decoded -- i.e. exactly the `ts` argument + * each append_*_event() helper below is given, with no wall-clock jitter. + * This is what makes it possible to construct exact, reproducible raw-ns + * values below (including deliberately far-apart raw values that still + * round to the identical displayed second) rather than merely hoping two + * events land in the same second. + * + * bug-1595 jobid-safety discipline: NONE of this file's fixtures push, + * mutate, or reference any job or jobid at all -- same discipline + * test_repl_event_echo.c's own header comment documents, for the same + * reason (every event used below, QUEUE_UPDATE/WORKERS_PUSH, is deliberately + * job-free). + * + * THIS TASK (1.1) IS RED-PHASE ONLY: the preamble-dedup cache/short-circuit + * under test does not exist yet in repl_print_event_summary() (repl_break.c) + * today -- that function unconditionally builds and prints the preamble on + * every single call, with no reference to any "last printed" state on + * xce_sched_repl_state_s (task 1.2, a separate later task, adds both the + * cache fields and the short-circuit). Every symbol this file references + * already exists today, so every test below builds and links cleanly but + * FAILS certain of its own runtime assertions -- specifically, every + * assertion that a SECOND same-context event's preamble is ABSENT. Verified + * concretely (not assumed) against a real incremental ASAN build before + * this task was reported done -- see this task's own Status Report. + * + * Assumed output contract this file pins (matches design.md's Event Echo + * Preamble Deduplicator component and test_repl_event_echo.c's own + * "Assumed output contract" precedent): + * - repl_print_event_summary() prints "[sim] t= () + * session=\n" where is the exact raw nanosecond value + * xce_core_now() returns for that event (see the determinism note + * above), is that same value rendered via + * repl_format_ts_human() to second granularity, and is + * rs->session_count + 1 at the moment the event is echoed. + * - TARGET (post task 1.2) behavior this file's RED assertions pin: that + * preamble line is printed only when or differs from the + * immediately preceding ECHOED event's own printed / (or + * when there is no preceding echoed event this session) -- never based + * on the raw value, which may legitimately differ between two + * events sharing the same displayed / (Requirement 1.3). + * - An event's own content line (the existing "[sim] event: ..." switch + * in repl_print_event_summary()) is unaffected either way -- always + * printed exactly as today, in the same relative order (Requirement + * 1.4, 2.2). + * - Tests use strstr()/pointer-order comparisons on captured real stdout, + * the same technique test_repl_event_echo.c's own tests establish. + */ +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +#include "controller.capnp.h" +#include "kvmgr.h" +#include "scheduler.h" +#include "xstring.h" + +/* Pull in the real functions under test into this TU (white-box #include, + * same convention as test_repl_event_echo.c/test_repl_round_rollup.c/ + * test_repl_execution_control.c/test_repl_breakpoints_inspection.c). */ +#include "../src/core.c" +#include "../src/core_clock.c" +#include "../src/core_events.c" +#include "../src/core_session.c" +#include "../src/decision.c" +#include "../src/plugin.c" +#include "../src/plugins/builtin_fcfs.c" +#include "../src/recording.c" +#include "../src/recording_session.c" +#include "../src/repl.c" +#include "../src/repl_fmt.c" +#include "../src/repl_rollup.c" +#include "../src/repl_break.c" +#include "../src/repl_info.c" +#include "../src/repl_params.c" +#include "../src/sim.c" +#include "../src/sim_loop.c" +#include "../src/sim_picker.c" /* bug-1567: sched_sim_driver_run() now calls sim_bootstrap_picker() (sim_loop.c-cap sibling) as an extern -- undefined reference at link time otherwise */ +#include "../src/sim_record.c" +#include "../src/sim_verify.c" +#include "../src/snapshot.c" +#include "../src/snapshot_load.c" +#include "../src/snapshot_wire.c" + +void kill_sched_job(void* arg) { (void)arg; } +void kill_sched_queue(void* arg) { (void)arg; } +void kill_sched_worker(void* arg) { (void)arg; } +void kill_sched_user(void* arg) { (void)arg; } +void kill_sched_project(void* arg) { (void)arg; } +void kill_sched_resval(xce_val_t* val) { (void)val; } + +/* resource-accounting.md's reconciliation (resource.c, not linked here -- + * this file only #includes core_events.c). core_events.c's + * XCE_CORE_EVENT_JOB_RUSAGE handler calls this whenever job->accounts != + * NULL; link-satisfying stub only, same rationale as every other stub in + * this block (see test_repl_event_echo.c's identical stub). */ +int sched_reconcile_job_resource_usage(xce_sched_core_t* c, + xce_job_account_t* a, + xce_job_rusages_t* r) +{ + (void)c; (void)a; (void)r; return 0; +} + +void sched_worker_release_host_ctx(xce_sched_worker_t* w) { (void)w; } + +int sched_fill_limit_requests(xce_scheduler_t* sched, xvec_idval_t* vec, + xlist_t* limits) +{ + (void)sched; + (void)vec; + (void)limits; + return 0; +} + +/* sched_sim_driver_run()'s (sim_loop.c, scheduler-sim-decision-parity task + * 2.1) new round-boundary call to the relocated sched_account_jobs() + * (core.h) -- a no-op stand-in here since this file does not link + * scheduler.c/resource.c, same rationale test_repl_event_echo.c's own copy + * documents. */ +int sched_account_jobs(xce_sched_core_t* core) +{ + (void)core; + return 0; +} + +/* Real reimplementation of schedobj.c's sched_resolve_job_picker -- same + * copy test_repl_event_echo.c/test_repl_round_rollup.c/ + * test_repl_execution_control.c/test_sim_alt_events.c/test_sim_verify.c/ + * test_sim_event_loop.c each carry (schedobj.c is not linked here: it would + * need plugin_register(), which requires a genuine xce_scheduler_t* neither + * this file's fixtures nor sim_loop.c's own core-scoped registration path + * have, Req 5 AC 17). */ +int sched_resolve_job_picker(xce_sched_core_t* core, xce_sched_plugin_t** out) +{ + xce_sched_plugin_t* plugin = NULL; + int rc = 0; + + if ((core == NULL) || (out == NULL)) { + return -EINVAL; + } + + *out = NULL; + + if (core->job_pick_plugin == NULL) { + return -EINVAL; + } + + lock(core->plugins, RTTI_LOCK_READ); + rc = key_find(core->plugins, core->job_pick_plugin, (void**)&plugin); + unlock(core->plugins); + + if (rc <= 0) { + return (rc < 0) ? rc : -ENOENT; + } + + if ((plugin == NULL) || (plugin->picker_iface == NULL) + || (plugin->picker_iface->next_job == NULL) + || (plugin->picker_iface->begin_session == NULL) + || (plugin->picker_iface->end_session == NULL) + || (plugin->picker_iface->on_dispatch == NULL) + || (plugin->picker_iface->on_pend == NULL)) { + return -EINVAL; + } + + *out = plugin; + + return 0; +} + +void setUp(void) { return; } +void tearDown(void) { return; } + +/* ---------------------------------------------------------------------- */ +/* Fixture helpers -- duplicated from test_repl_event_echo.c (itself */ +/* duplicated from test_repl_round_rollup.c/test_repl_execution_control.c),*/ +/* per this file family's established split convention (see header comment */ +/* above): copied, not shared via a new header. */ +/* ---------------------------------------------------------------------- */ + +static void make_tmp_dir(char* out, size_t out_len, const char* suffix) +{ + char tmpl[PATH_MAX]; + + snprintf(tmpl, sizeof(tmpl), "/tmp/sched_replexec%s_XXXXXX", suffix); + TEST_ASSERT_NOT_NULL(mkdtemp(tmpl)); + TEST_ASSERT_TRUE(strlen(tmpl) < out_len); + strcpy(out, tmpl); +} + +static void build_fixture_scheduler(xce_scheduler_t* sched, char* record_dir) +{ + int rc; + + memset(sched, 0, sizeof(*sched)); + mylock_init(&(sched->record_lock)); + + rc = xce_sched_core_init(&(sched->core)); + TEST_ASSERT_EQUAL_INT(0, rc); + + sched->core.job_pick_plugin = (char*)"builtin_fcfs"; + sched->record_dir = record_dir; +} + +static FILE* write_header_and_snapshot(char* out_path, size_t out_path_len, + const char* suffix) +{ + char record_dir[PATH_MAX]; + xce_scheduler_t sched; + int rc; + + make_tmp_dir(record_dir, sizeof(record_dir), suffix); + build_fixture_scheduler(&sched, record_dir); + + rc = sched_record_start(&sched, "fixture.replay"); + TEST_ASSERT_EQUAL_INT(0, rc); + TEST_ASSERT_TRUE(strlen(sched.record_file_path) < out_path_len); + strcpy(out_path, sched.record_file_path); + + return sched.record_file; +} + +static void append_queue_update_event(FILE* f, uint64_t ts, + const char* queue_name) +{ + xce_queue_t queue; + replay_event_t src; + struct capn c; + struct capn_segment* cs; + ReplayEvent_ptr p; + + memset(&queue, 0, sizeof(queue)); + queue.queue = (char*)queue_name; + queue.status = QUEUE_STAT_OPEN; + queue.priority = 1; + + memset(&src, 0, sizeof(src)); + src.ts = ts; + src.body_which = ReplayEvent_body_queueUpdate; + src.body.queue_update = &queue; + + capn_init_malloc(&c); + cs = capn_root(&c).seg; + encode_ReplayEvent_ptr(cs, &p, &src); + capn_setp(capn_root(&c), 0, p.p); + + TEST_ASSERT_EQUAL_INT(0, write_capnp_message(f, &c)); + capn_free(&c); +} + +/* append_workers_push_event - a structural event (WORKERS_PUSH, per + * design.md's Event Echo Gate classification list, unmodified by this + * spec), encoded the same minimal-zeroed-wire-struct way + * test_repl_event_echo.c's own copy of this helper builds it -- only the + * fields core_upsert_worker()/core_build_worker() (core_events.c) actually + * read (w->name, w->status, w->nresvals_to_sched) are set; everything else + * stays zeroed/NULL. Deliberately job-free -- see this file's own header + * comment on bug-1595 jobid safety. */ +static void append_workers_push_event(FILE* f, uint64_t ts, + const char* worker_name) +{ + xce_worker_t worker; + xce_worker_t* workers[1]; + xce_workers_data_t workers_data; + replay_event_t src; + struct capn c; + struct capn_segment* cs; + ReplayEvent_ptr p; + + memset(&worker, 0, sizeof(worker)); + worker.name = (char*)worker_name; + + workers[0] = &worker; + + memset(&workers_data, 0, sizeof(workers_data)); + workers_data.n_total = 1; + workers_data.count = 1; + workers_data.workers = workers; + + memset(&src, 0, sizeof(src)); + src.ts = ts; + src.body_which = ReplayEvent_body_workersPush; + src.body.workers_push = &workers_data; + + capn_init_malloc(&c); + cs = capn_root(&c).seg; + encode_ReplayEvent_ptr(cs, &p, &src); + capn_setp(capn_root(&c), 0, p.p); + + TEST_ASSERT_EQUAL_INT(0, write_capnp_message(f, &c)); + capn_free(&c); +} + +static void append_replay_session(FILE* f, uint64_t begin_round) +{ + struct capn c; + struct capn_segment* cs; + ReplaySession_ptr sp; + + capn_init_malloc(&c); + cs = capn_root(&c).seg; + sp = new_ReplaySession(cs); + ReplaySession_set_beginRound(sp, begin_round); + capn_setp(capn_root(&c), 0, sp.p); + + TEST_ASSERT_EQUAL_INT(0, write_capnp_message(f, &c)); + capn_free(&c); +} + +static void append_end_of_stream_marker(FILE* f) +{ + replay_event_t src; + struct capn c; + struct capn_segment* cs; + ReplayEvent_ptr p; + + memset(&src, 0, sizeof(src)); + src.body_which = ReplayEvent_body_endSession; + + capn_init_malloc(&c); + cs = capn_root(&c).seg; + encode_ReplayEvent_ptr(cs, &p, &src); + capn_setp(capn_root(&c), 0, p.p); + + TEST_ASSERT_EQUAL_INT(0, write_capnp_message(f, &c)); + capn_free(&c); +} + +static void write_text_file(const char* path, const char* content) +{ + FILE* f = fopen(path, "w"); + + TEST_ASSERT_NOT_NULL(f); + TEST_ASSERT_TRUE(fputs(content, f) >= 0); + fclose(f); +} + +static char* read_whole_file(const char* path) +{ + FILE* f = fopen(path, "rb"); + long len; + char* buf; + + TEST_ASSERT_NOT_NULL(f); + TEST_ASSERT_EQUAL_INT(0, fseek(f, 0, SEEK_END)); + len = ftell(f); + TEST_ASSERT_TRUE(len >= 0); + rewind(f); + + buf = (char*)malloc((size_t)len + 1); + TEST_ASSERT_NOT_NULL(buf); + if (len > 0) { + TEST_ASSERT_EQUAL_INT((int)len, (int)fread(buf, 1, (size_t)len, f)); + } + buf[len] = '\0'; + fclose(f); + + return buf; +} + +/* child_run_repl_and_exit / run_repl_fixture_and_capture - the same fork/ + * freopen/waitpid/capture shape test_repl_event_echo.c's own pair + * establishes: run a scripted command sequence to completion against a real + * sched_sim_driver_run(), capturing real stdout. args.sim_speed = 0 below is + * this file's own load-bearing determinism note (see header comment) -- it + * is what makes xce_core_now() return EXACTLY each event's own `ts`. */ +static void child_run_repl_and_exit(const char* replay_path, + const char* script_path, + const char* capture_path) +{ + xce_sched_sim_driver_t sim; + sched_sim_args_t args; + + if (freopen(script_path, "r", stdin) == NULL) { + _exit(120); + } + if (freopen(capture_path, "w", stdout) == NULL) { + _exit(121); + } + + memset(&sim, 0, sizeof(sim)); + memset(&args, 0, sizeof(args)); + args.replay_path = replay_path; + args.sim_start_ts = SCHED_SIM_START_TS_LATEST; + args.sim_speed = 0; + args.interactive = true; + + (void)sched_sim_driver_run(&sim, &args); + + fflush(stdout); + _exit(111); /* unreachable -- the script's `quit` must already have + * exited */ +} + +static char* run_repl_fixture_and_capture(const char* replay_path, + const char* script, + const char* aux_suffix) +{ + char aux_dir[PATH_MAX]; + char script_path[PATH_MAX]; + char capture_path[PATH_MAX]; + pid_t pid; + int status; + + make_tmp_dir(aux_dir, sizeof(aux_dir), aux_suffix); + snprintf(script_path, sizeof(script_path), "%s/script.txt", aux_dir); + snprintf(capture_path, sizeof(capture_path), "%s/capture.out", aux_dir); + write_text_file(script_path, script); + + pid = fork(); + TEST_ASSERT_TRUE_MESSAGE(pid >= 0, "fork() must succeed"); + + if (pid == 0) { + child_run_repl_and_exit(replay_path, script_path, capture_path); + _exit(112); /* unreachable -- child_run_repl_and_exit never returns */ + } + + TEST_ASSERT_EQUAL_INT_MESSAGE(pid, waitpid(pid, &status, 0), + "waitpid must reap the REPL child"); + TEST_ASSERT_TRUE_MESSAGE(WIFEXITED(status), + "the REPL child must exit normally via quit's " + "exit(0)"); + TEST_ASSERT_EQUAL_INT(0, WEXITSTATUS(status)); + + return read_whole_file(capture_path); +} + +/* build_preamble_line - constructs the EXACT text + * repl_print_event_summary() (repl_break.c) prints for one event's preamble + * given its raw nanosecond timestamp and displayed session number, using + * the real repl_format_ts_human() (pulled into this TU verbatim via + * repl_fmt.c's white-box #include -- the same renderer production uses, + * never a hand-rolled ISO8601 string) so this helper can never silently + * drift from what repl_print_event_summary() actually emits. Deliberately + * excludes the trailing '\n' so the result is a valid strstr() needle + * immediately followed by that event's own content line. Because this + * needle embeds the exact raw `ts`, it unambiguously targets ONE specific + * event's preamble even when a neighboring event shares the same rendered + * (, session) pair but a different raw ts. */ +static void build_preamble_line(char* out, size_t outsz, uint64_t raw_ts_ns, + uint64_t session_num) +{ + char ts_human[32]; + + repl_format_ts_human(raw_ts_ns, ts_human, sizeof(ts_human)); + snprintf(out, outsz, "[sim] t=%llu (%s) session=%llu", + (unsigned long long)raw_ts_ns, ts_human, + (unsigned long long)session_num); +} + +/* ---------------------------------------------------------------------- */ +/* Test 1: two consecutive echoed events sharing the same rendered */ +/* timestamp and session -- the second's preamble must be OMITTED, while */ +/* both events' own content lines stay present and in order (Requirements */ +/* 1.1, 1.2, 1.4, 2.2). THE primary RED case: today's REPL prints both */ +/* preambles unconditionally. */ +/* ---------------------------------------------------------------------- */ + +static void test_second_event_with_same_rendered_context_omits_preamble(void) +{ + char replay_path[PATH_MAX]; + FILE* f; + char* captured; + char preamble1[96]; + char preamble2[96]; + char* preamble1_pos; + char* preamble2_pos; + char* content1_pos; + char* content2_pos; + + f = write_header_and_snapshot(replay_path, sizeof(replay_path), + "_svsamectx"); + TEST_ASSERT_NOT_NULL(f); + + /* Two consecutive routine events (QUEUE_UPDATE), both decoded before + * the first ReplaySession boundary -- both echoed with the SAME + * displayed session (rs->session_count + 1 == 1 for both, since no + * ReplaySession has been processed yet) and the SAME rendered second + * (both raw ts values floor to second 0 via repl_format_ts_human()'s + * ns/1e9 truncation). "step" (default N=1) puts the REPL in STEP mode + * for the whole round, so both routine events are echoed. */ + append_queue_update_event(f, 1000ULL, "queueA"); + append_queue_update_event(f, 2000ULL, "queueB"); + append_replay_session(f, 2000000000ULL); /* round 1: idle */ + append_end_of_stream_marker(f); + fclose(f); + + captured = run_repl_fixture_and_capture(replay_path, "step\nquit\n", + "_svsamectxaux"); + + build_preamble_line(preamble1, sizeof(preamble1), 1000ULL, 1ULL); + build_preamble_line(preamble2, sizeof(preamble2), 2000ULL, 1ULL); + + preamble1_pos = strstr(captured, preamble1); + preamble2_pos = strstr(captured, preamble2); + content1_pos + = strstr(captured, "[sim] event: QUEUE_UPDATE queue=queueA"); + content2_pos + = strstr(captured, "[sim] event: QUEUE_UPDATE queue=queueB"); + + TEST_ASSERT_NOT_NULL_MESSAGE( + preamble1_pos, + "the FIRST echoed event of a fresh REPL session must always print " + "its own preamble -- there is no preceding echoed event yet to " + "compare against (Requirement 1.2)"); + TEST_ASSERT_NOT_NULL_MESSAGE( + content1_pos, + "event1's own content line must appear regardless of the preamble " + "decision (Requirement 1.4)"); + TEST_ASSERT_NOT_NULL_MESSAGE( + content2_pos, + "event2's own content line must appear regardless of the preamble " + "decision (Requirement 1.4)"); + + /* THE RED ASSERTION (Requirement 1.1): event2's rendered timestamp and + * displayed session are IDENTICAL to event1's -- the immediately + * preceding echoed event -- so event2's preamble line must be OMITTED. + * Today's repl_print_event_summary() prints it unconditionally on + * every call, so preamble2_pos is found (non-NULL) against today's + * code, when it must be NULL (absent) once task 1.2 lands. */ + TEST_ASSERT_NULL_MESSAGE( + preamble2_pos, + "event2 shares its immediately preceding echoed event's rendered " + "timestamp and session -- its preamble line must be OMITTED " + "(Requirement 1.1); expected to fail against today's REPL, which " + "prints the preamble unconditionally before every echoed event"); + + TEST_ASSERT_TRUE_MESSAGE( + preamble1_pos < content1_pos, + "event1's preamble must still precede its own content line"); + TEST_ASSERT_TRUE_MESSAGE( + content1_pos < content2_pos, + "event content lines must stay in their original relative order " + "regardless of any preamble's presence or absence (Requirement " + "2.2)"); + + free(captured); + + printf( + "test_second_event_with_same_rendered_context_omits_preamble: " + "PASS\n"); +} + +/* ---------------------------------------------------------------------- */ +/* Test 2: two consecutive echoed events spanning a session boundary -- */ +/* BOTH must print their own full preamble (Requirement 1.2). */ +/* ---------------------------------------------------------------------- */ + +static void test_events_across_session_boundary_both_print_own_preamble(void) +{ + char replay_path[PATH_MAX]; + FILE* f; + char* captured; + char preamble1[96]; + char preamble2[96]; + char* preamble1_pos; + char* preamble2_pos; + + f = write_header_and_snapshot(replay_path, sizeof(replay_path), + "_svsessbound"); + TEST_ASSERT_NOT_NULL(f); + + /* event1 is decoded before round 1's ReplaySession boundary, so it is + * echoed with session = rs->session_count + 1 == 0 + 1 == 1. The first + * "step" command processes exactly round 1 (echoing event1, then + * pausing right after round 1's decisions drain -- xce_repl_ + * post_session_pause()/repl_should_pause(), repl.c). event2 is only + * decoded once the SECOND "step" command resumes the replay stream; by + * then round 1's begin_round hook (xce_repl_on_begin_round(), + * repl_break.c) has already incremented rs->session_count to 1, so + * event2 is echoed with session == 1 + 1 == 2 -- a genuine session + * boundary between these two consecutive echoed events, with no other + * echoed event between them. */ + append_queue_update_event(f, 1000ULL, "queueA"); + append_replay_session(f, 2000000000ULL); /* round 1 boundary */ + append_queue_update_event(f, 2500000000ULL, "queueB"); + append_replay_session(f, 3000000000ULL); /* round 2 boundary */ + append_end_of_stream_marker(f); + fclose(f); + + captured = run_repl_fixture_and_capture( + replay_path, "step\nstep\nquit\n", "_svsessboundaux"); + + build_preamble_line(preamble1, sizeof(preamble1), 1000ULL, 1ULL); + build_preamble_line(preamble2, sizeof(preamble2), 2500000000ULL, 2ULL); + + preamble1_pos = strstr(captured, preamble1); + preamble2_pos = strstr(captured, preamble2); + + TEST_ASSERT_NOT_NULL_MESSAGE( + preamble1_pos, + "event1 (session 1) must print its own full preamble"); + TEST_ASSERT_NOT_NULL_MESSAGE( + preamble2_pos, + "event2's displayed session (2) differs from event1's (1) -- a " + "session boundary occurred between these two consecutive echoed " + "events, so event2 must print its own full preamble rather than " + "being deduped against event1 (Requirement 1.2)"); + TEST_ASSERT_TRUE_MESSAGE(preamble1_pos < preamble2_pos, + "the two sessions' preambles must appear in " + "their original relative order"); + + free(captured); + + printf( + "test_events_across_session_boundary_both_print_own_preamble: " + "PASS\n"); +} + +/* ---------------------------------------------------------------------- */ +/* Test 3 (the critical nuance, research.md's Design Decision): two */ +/* consecutive echoed events whose RAW high-resolution timestamps differ */ +/* substantially, but whose RENDERED (second-granularity) timestamp and */ +/* session are identical -- the second's preamble must STILL be omitted. */ +/* This is the case that would fail if a future implementation keyed dedup */ +/* on the raw xce_core_now() value instead of the rendered display value */ +/* (Requirement 1.3). */ +/* ---------------------------------------------------------------------- */ + +static void +test_dedup_key_is_rendered_timestamp_not_raw_nanoseconds(void) +{ + char replay_path[PATH_MAX]; + FILE* f; + char* captured; + char ts_human1[32]; + char ts_human2[32]; + char preamble1[96]; + char preamble2[96]; + char* preamble1_pos; + char* preamble2_pos; + char* content1_pos; + char* content2_pos; + + /* Fixture premise check (not a test of production behavior): raw ts + * values 1ns and 999,999,999ns are as far apart as two values can be + * while still flooring to the SAME displayed second under + * repl_format_ts_human()'s ns/1e9 truncation -- confirms this fixture + * genuinely exercises "raw differs, rendered doesn't", not merely two + * values that happen to be numerically close. */ + repl_format_ts_human(1ULL, ts_human1, sizeof(ts_human1)); + repl_format_ts_human(999999999ULL, ts_human2, sizeof(ts_human2)); + TEST_ASSERT_EQUAL_STRING_MESSAGE( + ts_human1, ts_human2, + "fixture premise: raw ts 1ns and 999999999ns must render to the " + "IDENTICAL displayed second for this test to exercise Requirement " + "1.3's actual nuance"); + + f = write_header_and_snapshot(replay_path, sizeof(replay_path), + "_svrawnsdiff"); + TEST_ASSERT_NOT_NULL(f); + + append_queue_update_event(f, 1ULL, "queueA"); + append_queue_update_event(f, 999999999ULL, "queueB"); + append_replay_session(f, 2000000000ULL); /* round 1: idle */ + append_end_of_stream_marker(f); + fclose(f); + + captured = run_repl_fixture_and_capture(replay_path, "step\nquit\n", + "_svrawnsdiffaux"); + + build_preamble_line(preamble1, sizeof(preamble1), 1ULL, 1ULL); + build_preamble_line(preamble2, sizeof(preamble2), 999999999ULL, 1ULL); + + preamble1_pos = strstr(captured, preamble1); + preamble2_pos = strstr(captured, preamble2); + content1_pos + = strstr(captured, "[sim] event: QUEUE_UPDATE queue=queueA"); + content2_pos + = strstr(captured, "[sim] event: QUEUE_UPDATE queue=queueB"); + + TEST_ASSERT_NOT_NULL_MESSAGE(preamble1_pos, + "event1 (first echo) must print its own " + "preamble"); + TEST_ASSERT_NOT_NULL_MESSAGE(content1_pos, "event1's content line must " + "appear"); + TEST_ASSERT_NOT_NULL_MESSAGE(content2_pos, "event2's content line must " + "appear"); + + /* THE RED ASSERTION (Requirement 1.3): event2's raw ts (999999999ns) + * differs enormously from event1's (1ns) -- almost a full second apart + * -- yet both render to the identical displayed second and session. + * The dedup key must be the RENDERED pair, never the raw value, so + * event2's preamble must still be omitted. Today's code prints a fresh + * preamble unconditionally on every call (using the raw, always-unique + * value), so this fails against today's REPL. */ + TEST_ASSERT_NULL_MESSAGE( + preamble2_pos, + "event2's raw nanosecond timestamp genuinely differs from event1's, " + "but its RENDERED timestamp and session are identical -- its " + "preamble must still be omitted (Requirement 1.3); a naive " + "raw-nanosecond dedup key would wrongly print this preamble since " + "raw t values essentially never repeat"); + + TEST_ASSERT_TRUE_MESSAGE(content1_pos < content2_pos, + "event content lines must stay in their " + "original relative order (Requirement 2.2)"); + + free(captured); + + printf( + "test_dedup_key_is_rendered_timestamp_not_raw_nanoseconds: PASS\n"); +} + +/* ---------------------------------------------------------------------- */ +/* Test 4: the very first echoed event of a fresh REPL session always */ +/* prints its preamble -- there is no preceding echoed event to compare */ +/* against (Requirement 1.2). Uses a structural event (WORKERS_PUSH) under */ +/* `continue` so it also doubles as a baseline outside step mode. */ +/* ---------------------------------------------------------------------- */ + +static void test_first_echoed_event_in_fresh_session_prints_preamble(void) +{ + char replay_path[PATH_MAX]; + FILE* f; + char* captured; + char preamble1[96]; + char* preamble1_pos; + char* content1_pos; + + f = write_header_and_snapshot(replay_path, sizeof(replay_path), + "_svfirstecho"); + TEST_ASSERT_NOT_NULL(f); + + append_workers_push_event(f, 1234ULL, "workerOnly"); + append_replay_session(f, 2000000000ULL); /* round 1: idle */ + append_end_of_stream_marker(f); + fclose(f); + + captured = run_repl_fixture_and_capture(replay_path, "continue\nquit\n", + "_svfirstechoaux"); + + build_preamble_line(preamble1, sizeof(preamble1), 1234ULL, 1ULL); + preamble1_pos = strstr(captured, preamble1); + content1_pos = strstr( + captured, "[sim] event: WORKERS_PUSH nworkers=1 names=[workerOnly]"); + + TEST_ASSERT_NOT_NULL_MESSAGE( + preamble1_pos, + "the very first echoed event of a fresh REPL session must print " + "its preamble -- no preceding echoed event exists this session to " + "compare its rendered context against (Requirement 1.2)"); + TEST_ASSERT_NOT_NULL_MESSAGE(content1_pos, + "the event's own content line must appear"); + TEST_ASSERT_TRUE_MESSAGE(preamble1_pos < content1_pos, + "the preamble must precede the event's own " + "content line"); + + free(captured); + + printf( + "test_first_echoed_event_in_fresh_session_prints_preamble: PASS\n"); +} + +/* ---------------------------------------------------------------------- */ +/* Test 5: a structural event echoed under `continue` mode after a */ +/* stretch of suppressed routine events follows the SAME dedup rule as any */ +/* other echoed event -- exercised at both ends: the first structural */ +/* event has no preceding ECHOED event (the suppressed routine events */ +/* never reached repl_print_event_summary() at all, so they never touched */ +/* the dedup cache) and so prints its preamble; a second structural event */ +/* immediately after it, sharing the same rendered context, has its */ +/* preamble omitted exactly as Test 1 exercises in step mode (Requirements */ +/* 1.1, 1.2). */ +/* ---------------------------------------------------------------------- */ + +static void +test_structural_event_after_suppressed_routine_events_follows_dedup_rule( + void) +{ + char replay_path[PATH_MAX]; + FILE* f; + char* captured; + char preambleA[96]; + char preambleB[96]; + char* preambleA_pos; + char* preambleB_pos; + char* contentA_pos; + char* contentB_pos; + + f = write_header_and_snapshot(replay_path, sizeof(replay_path), + "_svcontsuppress"); + TEST_ASSERT_NOT_NULL(f); + + /* Two routine QUEUE_UPDATE events -- suppressed entirely under + * `continue` mode (Event Echo Gate, scheduler-sim-repl-verbosity + * Requirement 1), so they never reach repl_print_event_summary() and + * can never contribute to (or be affected by) the preamble dedup + * cache. */ + append_queue_update_event(f, 500ULL, "normal1"); + append_queue_update_event(f, 600ULL, "normal2"); + /* Two structural WORKERS_PUSH events sharing the same rendered second + * (both floor to second 0) and the same displayed session (both + * decoded before the first ReplaySession boundary, so both are echoed + * with session == 0 + 1 == 1). */ + append_workers_push_event(f, 700ULL, "workerA"); + append_workers_push_event(f, 800ULL, "workerB"); + append_replay_session(f, 2000000000ULL); /* round 1: idle */ + append_end_of_stream_marker(f); + fclose(f); + + captured = run_repl_fixture_and_capture(replay_path, "continue\nquit\n", + "_svcontsuppressaux"); + + /* Confirm the suppressed routine events really produced no line at all + * -- reusing test_repl_event_echo.c's own Event Echo Gate assertion + * pattern so this test's "after a stretch of suppressed routine + * events" framing is verified here, not merely assumed. */ + TEST_ASSERT_NULL_MESSAGE( + strstr(captured, "[sim] event: QUEUE_UPDATE"), + "the routine events preceding the structural events must produce " + "no line at all under continue mode (scheduler-sim-repl-verbosity " + "Requirement 1) -- this test's premise"); + + build_preamble_line(preambleA, sizeof(preambleA), 700ULL, 1ULL); + build_preamble_line(preambleB, sizeof(preambleB), 800ULL, 1ULL); + + preambleA_pos = strstr(captured, preambleA); + preambleB_pos = strstr(captured, preambleB); + contentA_pos + = strstr(captured, "[sim] event: WORKERS_PUSH nworkers=1 names=[workerA]"); + contentB_pos + = strstr(captured, "[sim] event: WORKERS_PUSH nworkers=1 names=[workerB]"); + + TEST_ASSERT_NOT_NULL_MESSAGE( + preambleA_pos, + "workerA is the first ECHOED event of this continue-mode run (the " + "suppressed routine events before it never touched the dedup " + "cache) -- it must print its own preamble (Requirement 1.2)"); + TEST_ASSERT_NOT_NULL_MESSAGE(contentA_pos, "workerA's content line " + "must appear"); + TEST_ASSERT_NOT_NULL_MESSAGE(contentB_pos, "workerB's content line " + "must appear"); + + /* THE RED ASSERTION: workerB shares its immediately preceding echoed + * event's (workerA's) rendered timestamp and session, so its preamble + * must be omitted -- the same rule Test 1 exercises in step mode, + * proven here to apply identically under continue mode's structural + * echo path (Requirement 1.1). */ + TEST_ASSERT_NULL_MESSAGE( + preambleB_pos, + "workerB shares its immediately preceding ECHOED event's (workerA) " + "rendered timestamp and session -- its preamble must be omitted " + "(Requirement 1.1); expected to fail against today's REPL"); + + TEST_ASSERT_TRUE_MESSAGE(preambleA_pos < contentA_pos, + "workerA's preamble must precede its own " + "content line"); + TEST_ASSERT_TRUE_MESSAGE(contentA_pos < contentB_pos, + "event content lines must stay in their " + "original relative order (Requirement 2.2)"); + + free(captured); + + printf( + "test_structural_event_after_suppressed_routine_events_follows_" + "dedup_rule: PASS\n"); +} + +/* ---------------------------------------------------------------------- */ +/* Test 6: an event's own content line and the relative ordering of all */ +/* events' content lines are completely unaffected by the preamble dedup */ +/* decision, generalized to THREE consecutive same-context events mixing */ +/* routine and structural types (Requirements 1.4, 2.2) -- a stronger, */ +/* standalone regression guard than Test 1's two-event case, mirroring the */ +/* "3 consecutive same-context events" precedent test_repl_breakpoints_ */ +/* inspection.c's test_step_echoes_events_before_session_decisions already */ +/* establishes (without that test's own jobid-bearing event types, per */ +/* this file's job-free discipline). */ +/* ---------------------------------------------------------------------- */ + +static void +test_event_content_and_ordering_preserved_regardless_of_preamble_dedup(void) +{ + char replay_path[PATH_MAX]; + FILE* f; + char* captured; + char preamble1[96]; + char preamble2[96]; + char preamble3[96]; + char* content1_pos; + char* content2_pos; + char* content3_pos; + + f = write_header_and_snapshot(replay_path, sizeof(replay_path), + "_svcontentorder"); + TEST_ASSERT_NOT_NULL(f); + + /* Three consecutive events -- routine, structural, routine -- all + * decoded before the first ReplaySession boundary, so all three share + * the same displayed session (1) and (all three raw ts values below + * floor to second 0) the same rendered timestamp. "step" (STEP mode) + * echoes routine events too, so all three are echoed. */ + append_queue_update_event(f, 100ULL, "q1"); + append_workers_push_event(f, 200ULL, "wA"); + append_queue_update_event(f, 300ULL, "q2"); + append_replay_session(f, 2000000000ULL); /* round 1: idle */ + append_end_of_stream_marker(f); + fclose(f); + + captured = run_repl_fixture_and_capture(replay_path, "step\nquit\n", + "_svcontentorderaux"); + + content1_pos = strstr(captured, "[sim] event: QUEUE_UPDATE queue=q1"); + content2_pos = strstr( + captured, "[sim] event: WORKERS_PUSH nworkers=1 names=[wA]"); + content3_pos = strstr(captured, "[sim] event: QUEUE_UPDATE queue=q2"); + + TEST_ASSERT_NOT_NULL_MESSAGE(content1_pos, "q1's content line must " + "appear"); + TEST_ASSERT_NOT_NULL_MESSAGE(content2_pos, "wA's content line must " + "appear"); + TEST_ASSERT_NOT_NULL_MESSAGE(content3_pos, "q2's content line must " + "appear"); + + /* THIS TEST'S PRIMARY ASSERTION (Requirement 1.4, 2.2): every event's + * own content line stays present, in its original relative order, + * regardless of the preamble dedup decision or whether the event type + * mixes routine and structural classifications. */ + TEST_ASSERT_TRUE_MESSAGE( + content1_pos < content2_pos, + "q1's content line must precede wA's, unaffected by preamble " + "dedup (Requirement 2.2)"); + TEST_ASSERT_TRUE_MESSAGE( + content2_pos < content3_pos, + "wA's content line must precede q2's, unaffected by preamble " + "dedup (Requirement 2.2)"); + + /* Incidental reinforcement of Requirement 1.1 generalizing to N=3 + * consecutive same-context events across mixed event types -- not this + * test's main purpose (that is the ordering assertion above), but a + * natural corollary of the fixture's construction. */ + build_preamble_line(preamble1, sizeof(preamble1), 100ULL, 1ULL); + build_preamble_line(preamble2, sizeof(preamble2), 200ULL, 1ULL); + build_preamble_line(preamble3, sizeof(preamble3), 300ULL, 1ULL); + + TEST_ASSERT_NOT_NULL_MESSAGE(strstr(captured, preamble1), + "q1 (first echo) must print its preamble"); + TEST_ASSERT_NULL_MESSAGE( + strstr(captured, preamble2), + "wA shares q1's rendered context -- its preamble must be omitted " + "(Requirement 1.1), expected to fail against today's REPL"); + TEST_ASSERT_NULL_MESSAGE( + strstr(captured, preamble3), + "q2 shares q1's/wA's rendered context -- its preamble must be " + "omitted (Requirement 1.1), expected to fail against today's REPL"); + + free(captured); + + printf( + "test_event_content_and_ordering_preserved_regardless_of_preamble_" + "dedup: PASS\n"); +} + +int main(void) +{ + UNITY_BEGIN(); + + RUN_TEST(test_second_event_with_same_rendered_context_omits_preamble); + RUN_TEST(test_events_across_session_boundary_both_print_own_preamble); + RUN_TEST(test_dedup_key_is_rendered_timestamp_not_raw_nanoseconds); + RUN_TEST(test_first_echoed_event_in_fresh_session_prints_preamble); + RUN_TEST( + test_structural_event_after_suppressed_routine_events_follows_dedup_rule); + RUN_TEST( + test_event_content_and_ordering_preserved_regardless_of_preamble_dedup); + + return UNITY_END(); +}