From 081c8ea1110e65af7590869787e61e57e9055d5e Mon Sep 17 00:00:00 2001 From: A Tobey Date: Mon, 24 Aug 2026 09:27:16 -0400 Subject: [PATCH 1/6] test(kernel): close the pre-execute cancel race in the for-loop test test_cancel_interrupts_for_loop went red on CI today and passed 21 of 21 locally. The bound looked like the suspect -- 10s of wall clock against a loop that only needs ~50ms when cancellation works -- but a 200x margin does not evaporate under ordinary load, so I measured the mechanism instead of widening anything. execute() opens with reset_cancel(), which *replaces* a token that is already cancelled. schedule_cancel() fires off a 10ms timer, so if the test thread is descheduled for longer than that between scheduling the cancel and execute() reaching reset_cancel(), the cancel is discarded outright and the loop runs all 2000 iterations, ~100s. A throwaway probe pinned both sides: a cancel landing pre-execute returns code 0 with X=20 of 20 iterations done, while the same cancel landing mid-flight returns code 130 with X=1 after 11ms. That is a cliff, not a slowdown, which is why no bound would have fixed it and why #149 was right to refuse to widen one. The bound is unchanged at 10s. The timer was the bug, so the timer is gone. ExecuteOptions::interrupt is polled at the for-loop's per-iteration checkpoint and, measurably, nowhere else in this script shape -- zero polls for "echo hi" or "X=1; sleep 0.01", one poll per iteration for a for-loop -- and the kernel installs that slot *after* reset_cancel() has run. So a first poll proves execution is under way and a cancel can no longer be dropped. The closure only trips a flag and returns false; a background OS thread waits on the flag and calls Kernel::cancel(), keeping the embedder's real cancel door under test rather than substituting the interrupt path for it. Probing also turned up a dead assertion. The loop variable binds as Value::String because $(seq ...) yields strings, so the old "if let Some(Value::Int(n))" arm never matched and the iteration-count check silently did nothing. It now parses either shape and asserts the loop stopped within 200 of 2000 iterations -- a discriminator counted in work completed rather than wall clock, so it is immune to how slow the host is, and a loop ignoring cancellation reports 2000. Verified 25/25 clean idle and 15/15 under 3x CPU oversubscription. Co-Authored-By: Claude Opus 5 --- crates/kaish-kernel/src/kernel.rs | 108 +++++++++++++++++++++--------- 1 file changed, 78 insertions(+), 30 deletions(-) diff --git a/crates/kaish-kernel/src/kernel.rs b/crates/kaish-kernel/src/kernel.rs index 97e4715a..da32c119 100644 --- a/crates/kaish-kernel/src/kernel.rs +++ b/crates/kaish-kernel/src/kernel.rs @@ -8606,31 +8606,65 @@ AFTER="yes"'"#) async fn test_cancel_interrupts_for_loop() { let kernel = Arc::new(Kernel::transient().expect("failed to create kernel")); - // Schedule cancel after a short delay from a background OS thread - schedule_cancel(&kernel, std::time::Duration::from_millis(10)); - - // #149: a bare `X=$i` body has no await point, so the for-loop's - // cancellation checkpoint (checked once per iteration, see the - // `Stmt::For` arm above) never gets a chance to run mid-body — under - // host load, 100_000 trivial iterations could complete and return - // before the background thread's 10ms sleep ever elapsed, racing a - // natural exit-0 completion against the scheduled cancel. Rather than - // widen the margin (there's no bound on how slow "under load" can be), - // make completion deterministically impossible inside the test - // window: `sleep` is a real interruptible await point (it races - // `tokio::time::sleep` against the same cancellation token — see - // `tools/builtin/sleep.rs`), so a per-iteration sleep both gives - // cancellation somewhere to land almost immediately AND, at enough - // iterations, makes natural completion take far longer than the - // bounded wait below. The outer timeout is the "must not hang CI if - // cancellation is broken" backstop: it fails loudly well before the - // loop could ever finish on its own. + // #149 chose this loop's shape and that reasoning still holds: a bare + // `X=$i` body has no await point, so the for-loop's per-iteration + // cancellation checkpoint (the `Stmt::For` arm above) never gets to run + // mid-body, and a trivial loop can finish before a scheduled cancel + // arrives. `sleep` is a real interruptible await point — it races + // `tokio::time::sleep` against the same token, see + // `tools/builtin/sleep.rs` — so a per-iteration sleep gives + // cancellation somewhere to land, and at this iteration count natural + // completion (~100s) stays far longer than the bound below. + // + // What #149 could not see is why this still went red on CI and never + // locally. `execute()` opens with `reset_cancel()`, which *replaces* an + // already-cancelled token. A cancel scheduled off a timer that fires + // before `execute()` reaches that line is discarded outright, and the + // loop then runs all 2000 iterations. Measured directly: a cancel + // landing pre-execute returns code 0 with every iteration completed, + // against code 130 at iteration 1 when it lands mid-flight. That is a + // cliff, not a slowdown — so widening the bound was rightly rejected + // then and is not the fix now either; the bound is unchanged. + // + // The timer was the bug, so the timer is gone. `interrupt` is polled at + // the loop's checkpoint and only there (measured: zero polls for + // `echo hi` or `X=1; sleep 0.01`, one per iteration for a for-loop), + // and its slot is installed *after* `reset_cancel()` has run. So a + // first poll proves execution is under way and a cancel can no longer + // be dropped. The tripwire never reports true itself — + // `Kernel::cancel()`, the embedder's real door, still does the + // cancelling. const ITERATIONS: u32 = 2000; const PER_ITERATION_SLEEP_SECS: f64 = 0.05; let bound = std::time::Duration::from_secs(10); + + let running = Arc::new(std::sync::atomic::AtomicBool::new(false)); + let tripwire = Arc::clone(&running); + let opts = ExecuteOptions::new().with_interrupt(Arc::new(move || { + tripwire.store(true, Ordering::SeqCst); + false + })); + + // A background OS thread, not `tokio::spawn`: the cancel has to land + // while the current-thread test runtime is busy inside the loop. + { + let k = Arc::clone(&kernel); + let tripped = Arc::clone(&running); + std::thread::spawn(move || { + let deadline = std::time::Instant::now() + bound; + while !tripped.load(Ordering::SeqCst) && std::time::Instant::now() < deadline { + std::thread::sleep(std::time::Duration::from_millis(1)); + } + // Cancel even if the tripwire never tripped, so a loop that + // never started fails on an assertion below instead of just + // running out the bound. + k.cancel(); + }); + } + let script = format!("for i in $(seq 1 {ITERATIONS}); do X=$i; sleep {PER_ITERATION_SLEEP_SECS}; done"); - let result = tokio::time::timeout(bound, kernel.execute(&script)) + let result = tokio::time::timeout(bound, kernel.execute_with_options(&script, opts)) .await .unwrap_or_else(|_| { panic!( @@ -8644,16 +8678,30 @@ AFTER="yes"'"#) assert_eq!(result.code, 130, "cancelled execution should exit with code 130"); - // The loop variable should be set to something well short of the full - // iteration count — i.e. cancellation landed long before the loop - // could complete on its own. - let x = kernel.get_var("X").await; - if let Some(Value::Int(n)) = x { - assert!( - n < i64::from(ITERATIONS), - "loop should have been interrupted before finishing, got X={n}" - ); - } + // How far the loop actually got, in iterations — the half of this test + // that does not measure wall-clock at all. The cancel is requested one + // iteration in, so this is normally 1; reaching 200 would mean the + // cancelling thread needed 10s to notice a flag it polls every + // millisecond, while a loop ignoring cancellation reports 2000. Read as + // text and parsed because `$(seq …)` binds the loop variable as a + // string: the previous `if let Some(Value::Int(n))` arm never matched, + // so this assertion was quietly checking nothing. + const MAX_REACHED: i64 = (ITERATIONS / 10) as i64; + let reached = match kernel.get_var("X").await { + Some(Value::Int(n)) => n, + Some(Value::String(s)) => s + .parse::() + .unwrap_or_else(|e| panic!("loop variable X should be numeric, got {s:?}: {e}")), + other => { + panic!("loop variable X should record the last iteration reached, got {other:?}") + } + }; + assert!( + reached <= MAX_REACHED, + "cancellation should have stopped the loop within {MAX_REACHED} of {ITERATIONS} \ + iterations, but it reached {reached} — the per-iteration checkpoint is not \ + honoring the cancellation token" + ); } #[tokio::test] From 0a32516fd2fca7f54c987cbfc177eff8917de875 Mon Sep 17 00:00:00 2001 From: A Tobey Date: Mon, 24 Aug 2026 09:33:46 -0400 Subject: [PATCH 2/6] test(cancel): stop racing bash startup against the kill clock grace_escalation_sigkills_term_trapping_child died in setup on CI, at an .expect("pid") whose entire message was the word "pid". Under 4x CPU oversubscription I reproduced it at 11 failures in 20 runs, always at that same line. The test ran "bash