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 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01YAWMhfRJFnmmnG8h97yUDd
This commit is contained in:
Rongsong Shen 2026-09-02 13:00:09 +00:00
parent f587a441ac
commit cc78d09140
No known key found for this signature in database
GPG key ID: 5BCDAAE0123E9FE2
4 changed files with 124 additions and 18 deletions

View file

@ -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. - 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). - 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** **Dependencies**
- Inbound: `xce_repl_on_event` — calls this gate before its existing breakpoint check (P0) - 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) - 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)

View file

@ -36,7 +36,7 @@
- _Boundary: Event Echo Gate_ - _Boundary: Event Echo Gate_
- _Depends: 1.2, 2.2_ - _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 - 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 - 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 - 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

View file

@ -17937,20 +17937,22 @@
"error_message": "User-reported (live REPL session, xce_scheduler -i -s <replay>): 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').", "error_message": "User-reported (live REPL session, xce_scheduler -i -s <replay>): 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", "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.", "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": [ "tags": [
"repl", "repl",
"sim", "sim",
"verbosity", "verbosity",
"continue", "continue",
"ux", "ux",
"scheduler-sim-diagnostics" "scheduler-sim-diagnostics",
"scheduler-sim-repl-verbosity"
], ],
"related_bugs": [ "related_bugs": [
"bug-1595" "bug-1595",
"bug-1763"
], ],
"occurrences": 1, "occurrences": 1,
"last_seen": "2026-08-20T21:10:00Z" "last_seen": "2026-09-02T13:00:00Z"
}, },
{ {
"id": "bug-1610", "id": "bug-1610",
@ -20775,6 +20777,30 @@
"related_bugs": [], "related_bugs": [],
"occurrences": 1, "occurrences": 1,
"last_seen": "2026-09-02T07:50:00Z" "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"
} }
] ]
} }

View file

@ -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 /* 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 * against the JOB_IS_*() bitmask macros (xce/types.h) every other live
* state check in this codebase already uses, rather than an exact bitwise * 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; break;
case XCE_CORE_EVENT_JOBS_PUSH: { case XCE_CORE_EVENT_JOBS_PUSH: {
/* 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; int i;
fprintf(stdout, "[sim] event: JOB_PUSH njobs=%d jobids=[", for (i = 0; (i < n) && (jobids != NULL); i++) {
ev->u.jobs_push.njobs);
for (i = 0; i < ev->u.jobs_push.njobs; i++) {
xce_job_t* j = ev->u.jobs_push.jobs[i]; xce_job_t* j = ev->u.jobs_push.jobs[i];
if (j != NULL) {
jobids[njobids++] = j->jobid;
}
}
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]; char jobidStr[64];
if (j == NULL) { fmt_jobid(jobidStr, sizeof(jobidStr), jobids[i]);
continue;
}
fmt_jobid(jobidStr, sizeof(jobidStr), j->jobid);
fprintf(stdout, "%s%s", (i > 0) ? "," : "", jobidStr); fprintf(stdout, "%s%s", (i > 0) ? "," : "", jobidStr);
} }
}
}
fprintf(stdout, "]\n"); fprintf(stdout, "]\n");
free(jobids);
break; break;
} }
@ -733,13 +787,29 @@ void xce_repl_on_event(xce_sched_sim_driver_t* sim, xce_core_event_t* ev)
rs->event_index++; rs->event_index++;
/* task 12.5, bug-1595: unconditional echo, printed before the /*
* breakpoint check below so the operator sees "event happened" before * task 12.5, bug-1595: printed before the breakpoint check below so the
* (if it also matches) "breakpoint hit". */ * 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); 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); bp = repl_find_event_breakpoint(rs, ev);
if (bp != NULL) { 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, fprintf(stdout, "[sim] hit breakpoint %d @ event #%llu: %s\n", bp->id,
(unsigned long long)rs->event_index, bp->token); (unsigned long long)rs->event_index, bp->token);
repl_command_loop(sim); 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); bp = repl_find_begin_round_breakpoint(rs);
if (bp != NULL) { 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, fprintf(stdout, "[sim] hit breakpoint %d @ BEGIN_ROUND round=%llu\n", bp->id,
(unsigned long long)begin_round); (unsigned long long)begin_round);
repl_command_loop(sim); 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 /* bug-1591: see repl_info.c's repl_info_worker_one() comment on
* fmt_jobid() -- same fix, same rationale. */ * fmt_jobid() -- same fix, same rationale. */
fmt_jobid(jobidStr, sizeof(jobidStr), decision_jobid(d)); 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", fprintf(stdout, "[sim] hit breakpoint %d @ decision: %s jobid=%s\n",
bp->id, decision_op_name(d->op), jobidStr); bp->id, decision_op_name(d->op), jobidStr);
repl_command_loop(sim); repl_command_loop(sim);