From cc78d09140673950c0a4dfb46cb3cb06cdc55b79 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Wed, 2 Sep 2026 13:00:09 +0000 Subject: [PATCH] feat(scheduler-sim-repl-verbosity): task 3.2 - implement Event Echo Gate Implements mode-aware event echo classification, job-arrival range compression (Req 4.5), and round-collapse flush wiring at all 3 breakpoint-match/structural-event call sites (Requirements 1.1-1.4, 3.5, 3.6). All 4 of task 3.1's tests pass; also closes bug-1609 ("continue is as verbose as step"). repl_break.c grew 827->905 lines (13% over the 800-line cap). Unlike task 2.2's Round Rollup, this logic is wiring inside pre-existing driver-facing hooks, not a relocatable subsystem - accepted in place per design.md's established residual-tolerance precedent. Review independently investigated a one-off ASAN stack-use-after-return in an unrelated test (sched_sim_record_output_test) surfaced by this change's stack-layout perturbation: traced to the same documented pre-existing thread-lifecycle bug class as bug-1598/bug-1632 (an unjoined picker thread reading a stack-local sim after test-function return), confirmed via 11/11 clean reruns - logged as bug-1763, not a regression from this task. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_01YAWMhfRJFnmmnG8h97yUDd --- .../scheduler-sim-repl-verbosity/design.md | 2 + .../scheduler-sim-repl-verbosity/tasks.md | 2 +- .wolf/buglog.json | 34 +++++- src/scheduler/src/repl_break.c | 104 +++++++++++++++--- 4 files changed, 124 insertions(+), 18 deletions(-) diff --git a/.kiro/specs/scheduler-sim-repl-verbosity/design.md b/.kiro/specs/scheduler-sim-repl-verbosity/design.md index 3687b8b1..b064b349 100644 --- a/.kiro/specs/scheduler-sim-repl-verbosity/design.md +++ b/.kiro/specs/scheduler-sim-repl-verbosity/design.md @@ -169,6 +169,8 @@ See the Architecture Pattern & Boundary Map diagram above — it is the only non - Routine events (echoed only in `step` mode): `RESVALS_DELTA`, `JOB_STATE_CHANGE`, `JOB_UPDATE`, `QUEUE_UPDATE`, `JOB_RUSAGE`. `JOB_STATE_CHANGE` is classified routine deliberately — the Round Rollup (Requirement 2.4) already surfaces job status transitions at round granularity, so an individual `JOB_STATE_CHANGE` line under `continue` would duplicate that information. - Breakpoint matching (`repl_find_event_breakpoint`, plus the equivalent checks in `xce_repl_on_begin_round`/`xce_repl_on_decision`) runs on every event regardless of echo suppression — Requirement 1.4 is unaffected by this gate. On a match, before re-entering `repl_command_loop()`, the matching hook calls the Round Rollup's flush entry point so the operator sees the collapsed range's final state before the prompt returns (Requirement 3.6). +**Accepted residual (post-review, task 3.2)**: implementing this gate (classifier + 3 flush call sites + `JOBS_PUSH`'s range-compression adoption) grew `repl_break.c` from 827 to 905 lines (13% over the 800-line cap; the file was already 827/3.4% over before this task, a pre-existing condition unrelated to this spec). Unlike Round Rollup's task 2.2, this logic is wiring inside `repl_break.c`'s own pre-existing driver-facing hooks (`xce_repl_on_event`/`xce_repl_on_begin_round`/`xce_repl_on_decision`/`repl_print_event_summary`) rather than a relocatable standalone subsystem — there is no cohesive block to extract into a sibling file without fragmenting those functions. Accepted in place, same reasoning as `repl.c`'s task-2.2 residual above. + **Dependencies** - Inbound: `xce_repl_on_event` — calls this gate before its existing breakpoint check (P0) - Outbound: `repl_print_event_summary` — invoked only when the gate allows it (P0); Round Rollup's flush entry point — called before a structural-event line or a breakpoint-triggered command-loop re-entry (P0) diff --git a/.kiro/specs/scheduler-sim-repl-verbosity/tasks.md b/.kiro/specs/scheduler-sim-repl-verbosity/tasks.md index 94a035d7..5109c1f1 100644 --- a/.kiro/specs/scheduler-sim-repl-verbosity/tasks.md +++ b/.kiro/specs/scheduler-sim-repl-verbosity/tasks.md @@ -36,7 +36,7 @@ - _Boundary: Event Echo Gate_ - _Depends: 1.2, 2.2_ -- [ ] 3.2 (P) Implement the mode-aware event echo, range compression adoption, and range-ending wiring +- [x] 3.2 (P) Implement the mode-aware event echo, range compression adoption, and range-ending wiring - Suppress routine per-event lines during continuous execution while preserving full detail while single-stepping; keep structural-change lines and breakpoint interruption behavior unaffected by the classification - Render job-arrival listings using the compressed range format - Before printing a structural-change line, and before a breakpoint interruption is shown, end any active collapsed range first so output never interleaves out of order diff --git a/.wolf/buglog.json b/.wolf/buglog.json index 8ac8245d..c2fbd23b 100644 --- a/.wolf/buglog.json +++ b/.wolf/buglog.json @@ -17937,20 +17937,22 @@ "error_message": "User-reported (live REPL session, xce_scheduler -i -s ): after 'continue' with zero breakpoints set, output is just as verbose as single-stepping -- every decoded event still prints a '[sim] t=... session=...' + '[sim] event: ...' two-line block, defeating continue's documented purpose ('Run until next breakpoint hit or EOF').", "file": "src/scheduler/src/repl_break.c", "root_cause": "xce_repl_on_event() (repl_break.c:708-731) calls repl_print_event_summary() unconditionally before its breakpoint-match check, with no reference to sim->repl_state->mode (XCE_REPL_MODE_STEP vs XCE_REPL_MODE_CONTINUE). This was intentional for bug-1595 ('in each step, ... show the decisions/events that occur'), but the fix's implementation echoes on every xce_repl_check_event() call regardless of which command (step or continue) put the driver in motion -- the request was step-specific but the fix applies to both modes, so continue never actually reduces output versus stepping one session at a time.", - "fix": "Not yet fixed -- proposed: gate repl_print_event_summary()'s call in xce_repl_on_event() on rs->mode == XCE_REPL_MODE_STEP (or a new explicit 'set verbose on|off'), so continue only prints breakpoint-hit lines (and, optionally, one summary line per BEGIN_ROUND) while step keeps its current full per-event echo.", + "fix": "FIXED (2026-09-02, scheduler-sim-repl-verbosity spec, task 3.2 -- design.md's Event Echo Gate component, Requirement 1). Close to the originally proposed shape, refined per design.md's fuller classification: xce_repl_on_event() (repl_break.c) now calls a new repl_event_is_structural(ev->type) classifier before deciding whether to call repl_print_event_summary() -- CONFIG_PUSH/JOBS_PUSH/WORKERS_PUSH/RESOURCES_PUSH/RESVALS_FULL (structural) are always echoed regardless of rs->mode (AC 1.3), while RESVALS_DELTA/JOB_STATE_CHANGE/JOB_UPDATE/QUEUE_UPDATE/JOB_RUSAGE (routine) are echoed only when rs->mode == XCE_REPL_MODE_STEP (AC 1.1/1.2), so `continue` now genuinely reduces output versus single-stepping, exactly this bug's original complaint. Breakpoint matching (repl_find_event_breakpoint()) is unaffected by the classification -- runs on every event regardless (AC 1.4), same as before. A structural event's own line, and a breakpoint-triggered repl_command_loop() re-entry (in xce_repl_on_event()/xce_repl_on_begin_round()/xce_repl_on_decision()), now also call repl_round_collapse_flush() (task 2.2, repl_rollup.c) first, so a mode-suppressed stretch of routine events that got collapsed into a Round Rollup range is reported before either of those (Req 3.5/3.6) -- a Requirement 2/3 dependency this bug's original proposal didn't anticipate (Round Rollup didn't exist yet in task 12.5's original codebase). TDD: task 3.1's RED-phase test_repl_event_echo.c (4 tests, real forked-child stdout-capture against sched_sim_driver_run()) pinned this exact contract before the fix landed; all 4 pass after. Full scheduler suite verified via /xce-build scheduler --incremental: 56/58 test binaries OK, the 2 failures being the pre-existing unrelated bug-1758 (test_core_events.c mem-reservation reconciliation) and a one-off ASAN stack-use-after-return in sched_sim_record_output_test logged separately as bug-1763 (same pre-existing thread-lifecycle class as bug-1598/bug-1632, triggered by this task's repl_break.c size change perturbing that binary's stack layout, not a correctness defect in this fix -- 4/4 isolated re-runs of that binary were clean).", "tags": [ "repl", "sim", "verbosity", "continue", "ux", - "scheduler-sim-diagnostics" + "scheduler-sim-diagnostics", + "scheduler-sim-repl-verbosity" ], "related_bugs": [ - "bug-1595" + "bug-1595", + "bug-1763" ], "occurrences": 1, - "last_seen": "2026-08-20T21:10:00Z" + "last_seen": "2026-09-02T13:00:00Z" }, { "id": "bug-1610", @@ -20775,6 +20777,30 @@ "related_bugs": [], "occurrences": 1, "last_seen": "2026-09-02T07:50:00Z" + }, + { + "id": "bug-1763", + "timestamp": "2026-09-02T13:00:00Z", + "error_message": "sched_sim_record_output_test (scheduler-sim-repl-verbosity task 3.2 GREEN-phase build): AddressSanitizer stack-use-after-return in cbuf_get (lib/mylock.c:151), thread T1 (sim_picker_thread_fn, sim_loop.c:456), reading the stack of test_output_file_is_decodable_with_full_stream_symmetry's stack-local `sim` (xce_sched_sim_driver_t, test_sim_record_output.c:341) after that frame returned. Fired once during a `/xce-build scheduler --incremental` run after this task's repl_break.c edits; 4/4 direct re-runs of the isolated binary afterward were clean (OK).", + "file": "src/scheduler/testsuite/test_sim_record_output.c", + "root_cause": "Same class already documented by bug-1598/bug-1632, not a new defect: sched_sim_driver_run() spawns sim_picker_thread_fn on an unjoined pthread that reads its xce_sched_sim_driver_t* for the rest of the process's life; any stack-local `sim` fixture is therefore a latent stack-use-after-return the moment its owning test function returns, and whether ASAN's shadow memory actually catches a given run is purely a function of incidental stack-layout/timing -- bug-1598's own root cause entry documents an unrelated new test shifting stack layout enough to make this fire deterministically for a different file. test_sim_record_output.c #includes repl_break.c white-box (test_sim_record_output.c:78), so this task's repl_break.c size/layout change is what perturbed this particular binary's stack layout enough to surface the latent bug here, on this run -- not a correctness defect in the Event Echo Gate wiring itself (test_repl_event_echo.c's own 4 tests, plus every other scheduler REPL suite, passed cleanly in the same build; a direct 4x re-run of sched_sim_record_output_test alone was clean every time).", + "fix": "NOT FIXED -- out of scope for scheduler-sim-repl-verbosity task 3.2 (repl_break.c wiring only, no sim_loop.c/test_sim_record_output.c changes in this task's boundary). Same remediation bug-1598 already applied elsewhere would apply here too: change test_output_file_is_decodable_with_full_stream_symmetry's (and any sibling in this file with the same shape) stack-local `xce_sched_sim_driver_t sim;` to `static` storage, safe under bug-1598's own documented reasoning (sched_sim_driver_start() memset()s the whole struct first; verify non-reentrancy per test binary before applying). Logged so a future session doesn't re-diagnose this as a new correctness regression from a passing but stack-layout-perturbing change.", + "tags": [ + "scheduler", + "sim", + "repl", + "asan", + "stack-use-after-return", + "flaky", + "thread-lifecycle", + "scheduler-sim-repl-verbosity" + ], + "related_bugs": [ + "bug-1598", + "bug-1632" + ], + "occurrences": 1, + "last_seen": "2026-09-02T13:00:00Z" } ] } diff --git a/src/scheduler/src/repl_break.c b/src/scheduler/src/repl_break.c index 4ddc476d..0bfeeb59 100644 --- a/src/scheduler/src/repl_break.c +++ b/src/scheduler/src/repl_break.c @@ -116,6 +116,33 @@ static xce_repl_bp_kind_t repl_bp_kind_for_core_event(xce_core_event_type_t t) } } +/* + * repl_event_is_structural - scheduler-sim-repl-verbosity spec, task 3.2, + * design.md's "Event Echo Gate" component (Requirement 1): partitions the + * same ten xce_core_event_type_t members BP_KIND_TABLE/ + * repl_bp_kind_for_core_event() above already enumerate into structural + * (CONFIG_PUSH, JOBS_PUSH, WORKERS_PUSH, RESOURCES_PUSH, RESVALS_FULL -- + * population/config arrivals echoed every mode, AC 1.3) vs. routine + * (RESVALS_DELTA, JOB_STATE_CHANGE, JOB_UPDATE, QUEUE_UPDATE, JOB_RUSAGE -- + * echoed only while single-stepping, AC 1.1/1.2). Used only to gate + * xce_repl_on_event()'s call to repl_print_event_summary() below -- + * breakpoint matching (repl_find_event_breakpoint()) runs on every event + * regardless of this classification (Requirement 1.4). + */ +static bool repl_event_is_structural(xce_core_event_type_t t) +{ + switch (t) { + case XCE_CORE_EVENT_CONFIG_PUSH: + case XCE_CORE_EVENT_JOBS_PUSH: + case XCE_CORE_EVENT_WORKERS_PUSH: + case XCE_CORE_EVENT_RESOURCES_PUSH: + case XCE_CORE_EVENT_RESVALS_FULL: + return true; + default: + return false; + } +} + /* repl_job_state_matches - AC 22's `state=RUN`-style filter value, matched * against the JOB_IS_*() bitmask macros (xce/types.h) every other live * state check in this codebase already uses, rather than an exact bitwise @@ -616,21 +643,48 @@ static void repl_print_event_summary(xce_sched_sim_driver_t* sim, break; case XCE_CORE_EVENT_JOBS_PUSH: { - int i; + /* Requirement 4.5: adopt range compression for this job-arrival + * listing instead of printing each jobid individually. */ + int n = ev->u.jobs_push.njobs; + uint64_t* jobids = (n > 0) + ? (uint64_t*)malloc((size_t)n * sizeof(*jobids)) + : NULL; + int njobids = 0; + int i; - fprintf(stdout, "[sim] event: JOB_PUSH njobs=%d jobids=[", - ev->u.jobs_push.njobs); - for (i = 0; i < ev->u.jobs_push.njobs; i++) { + for (i = 0; (i < n) && (jobids != NULL); i++) { xce_job_t* j = ev->u.jobs_push.jobs[i]; - char jobidStr[64]; - if (j == NULL) { - continue; + if (j != NULL) { + jobids[njobids++] = j->jobid; } - fmt_jobid(jobidStr, sizeof(jobidStr), j->jobid); - fprintf(stdout, "%s%s", (i > 0) ? "," : "", jobidStr); } + + fprintf(stdout, "[sim] event: JOB_PUSH njobs=%d jobids=[", n); + + if (njobids > 0) { + char jobids_buf[1024]; + int rc = repl_fmt_jobid_range(jobids_buf, sizeof(jobids_buf), + jobids, njobids); + + if (rc >= 0) { + fprintf(stdout, "%s", jobids_buf); + } else { + /* design.md's Error Handling: a too-small compression + * buffer falls back to the pre-existing uncompressed + * per-id listing rather than truncating or dropping a + * jobid. */ + for (i = 0; i < njobids; i++) { + char jobidStr[64]; + + fmt_jobid(jobidStr, sizeof(jobidStr), jobids[i]); + fprintf(stdout, "%s%s", (i > 0) ? "," : "", jobidStr); + } + } + } + fprintf(stdout, "]\n"); + free(jobids); break; } @@ -733,13 +787,29 @@ void xce_repl_on_event(xce_sched_sim_driver_t* sim, xce_core_event_t* ev) rs->event_index++; - /* task 12.5, bug-1595: unconditional echo, printed before the - * breakpoint check below so the operator sees "event happened" before - * (if it also matches) "breakpoint hit". */ - repl_print_event_summary(sim, ev); + /* + * task 12.5, bug-1595: printed before the breakpoint check below so the + * operator sees "event happened" before (if it also matches) "breakpoint + * hit". scheduler-sim-repl-verbosity task 3.2 (Event Echo Gate, + * Requirement 1): a structural event is always echoed -- first flushing + * any active Round Rollup collapsed range so the two never interleave + * out of order (Requirement 3.5) -- while a routine event is echoed only + * while single-stepping; `continue` mode suppresses it. + */ + if (repl_event_is_structural(ev->type)) { + repl_round_collapse_flush(sim); + repl_print_event_summary(sim, ev); + } else if (rs->mode == XCE_REPL_MODE_STEP) { + repl_print_event_summary(sim, ev); + } bp = repl_find_event_breakpoint(rs, ev); if (bp != NULL) { + /* Requirement 3.6: end any active collapsed range before the + * breakpoint interruption is shown -- breakpoint matching itself + * is unaffected by the routine/structural classification above + * (Requirement 1.4). */ + repl_round_collapse_flush(sim); fprintf(stdout, "[sim] hit breakpoint %d @ event #%llu: %s\n", bp->id, (unsigned long long)rs->event_index, bp->token); repl_command_loop(sim); @@ -774,6 +844,10 @@ void xce_repl_on_begin_round(xce_sched_sim_driver_t* sim, uint64_t begin_round) bp = repl_find_begin_round_breakpoint(rs); if (bp != NULL) { + /* scheduler-sim-repl-verbosity task 3.2, Requirement 3.6: end any + * active collapsed range before this breakpoint interruption is + * shown. */ + repl_round_collapse_flush(sim); fprintf(stdout, "[sim] hit breakpoint %d @ BEGIN_ROUND round=%llu\n", bp->id, (unsigned long long)begin_round); repl_command_loop(sim); @@ -820,6 +894,10 @@ void xce_repl_on_decision(xce_sched_sim_driver_t* sim, xce_decision_t* d) /* bug-1591: see repl_info.c's repl_info_worker_one() comment on * fmt_jobid() -- same fix, same rationale. */ fmt_jobid(jobidStr, sizeof(jobidStr), decision_jobid(d)); + /* scheduler-sim-repl-verbosity task 3.2, Requirement 3.6: end any + * active collapsed range before this breakpoint interruption is + * shown. */ + repl_round_collapse_flush(sim); fprintf(stdout, "[sim] hit breakpoint %d @ decision: %s jobid=%s\n", bp->id, decision_op_name(d->op), jobidStr); repl_command_loop(sim);