diff --git a/crates/kaish-kernel/src/kernel.rs b/crates/kaish-kernel/src/kernel.rs index 97e4715a..8a085d53 100644 --- a/crates/kaish-kernel/src/kernel.rs +++ b/crates/kaish-kernel/src/kernel.rs @@ -1597,6 +1597,15 @@ impl Kernel { } /// Reset the cancellation token (called at the start of each execute). + /// + /// A `Kernel::cancel()` that arrives while nothing is running is dropped + /// here: the next `execute()` replaces the cancelled token and runs + /// normally, and nothing in that call's result reports a cancel was + /// discarded. An embedder can see the pending cancel before it is dropped — + /// `is_cancelled()` reports true until the next `execute()` clears it — but + /// a call that must start already cancelled has to supply its own + /// `ExecuteOptions::cancel_token`, which is a read-only input and is never + /// reset; a pre-cancelled one stops the call at its first checkpoint. fn reset_cancel(&self) -> tokio_util::sync::CancellationToken { #[allow(clippy::expect_used)] let mut token = self.cancel_token.lock().expect("cancel_token poisoned"); @@ -8592,8 +8601,12 @@ AFTER="yes"'"#) // Cancellation Tests // ═══════════════════════════════════════════════════════════════════════════ - /// Helper: schedule a cancel after a delay from a background thread. - /// Uses std::thread because cancel() is sync and Kernel is not Send. + /// Schedule a cancel after a delay, from an OS thread because `cancel()` + /// is sync and must run while the test runtime is inside `execute()`. + /// + /// The delay races `execute()`: a cancel firing before `reset_cancel()` is + /// discarded. Tests that need it to land use an `interrupt` tripwire + /// instead, as the loop tests below do. fn schedule_cancel(kernel: &Arc, delay: std::time::Duration) { let k = Arc::clone(kernel); std::thread::spawn(move || { @@ -8606,31 +8619,49 @@ 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. + // A `sleep` body, per #149: a bare `X=$i` has no await point for the + // per-iteration checkpoint to land on, and at this count natural + // completion (~100s) stays far past the bound. + // + // The timer this used to use raced `execute()`: `reset_cancel()` + // replaces an already-cancelled token, so a cancel firing first was + // dropped and the loop ran all 2000 iterations. The `interrupt` slot is + // installed after that line, so it cannot be dropped. + // `Kernel::cancel()` still does the cancelling. const ITERATIONS: u32 = 2000; const PER_ITERATION_SLEEP_SECS: f64 = 0.05; let bound = std::time::Duration::from_secs(10); + + // Counted, not latched: the checkpoint polls before the body, so a + // cancel released on the first poll can land before the body runs at + // all. The second poll puts one completed iteration between them. + let polls = Arc::new(std::sync::atomic::AtomicUsize::new(0)); + let tripwire = Arc::clone(&polls); + let opts = ExecuteOptions::new().with_interrupt(Arc::new(move || { + tripwire.fetch_add(1, 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(&polls); + std::thread::spawn(move || { + let deadline = std::time::Instant::now() + bound; + while tripped.load(Ordering::SeqCst) < 2 && 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 +8675,26 @@ 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 got — the half of this test that reads no clock. A + // loop ignoring cancellation reports 2000. Parsed from text because + // `$(seq …)` binds the loop variable as a string; the `Value::Int` arm + // this replaces never matched, so it asserted 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] @@ -8661,18 +8702,57 @@ AFTER="yes"'"#) let kernel = Arc::new(Kernel::transient().expect("failed to create kernel")); kernel.execute("COUNT=0").await.expect("init failed"); - schedule_cancel(&kernel, std::time::Duration::from_millis(10)); + // Same swallowed cancel as the for-loop test, but this one HUNG + // rather than failing: `while true` has no iteration count to run out + // and there was no bound, so a dropped cancel burned a core until CI's + // job timeout. Fixed the same way, plus a bound — which does fire here, + // so each iteration yields to the runtime somewhere. + let bound = std::time::Duration::from_secs(10); - let result = kernel - .execute("while true; do COUNT=$((COUNT + 1)); done") - .await - .expect("execute failed"); + // Counted, not latched: the checkpoint polls before the body, so a + // cancel released on the first poll can land before the body runs at + // all. The second poll puts one completed iteration between them. + let polls = Arc::new(std::sync::atomic::AtomicUsize::new(0)); + let tripwire = Arc::clone(&polls); + let opts = ExecuteOptions::new().with_interrupt(Arc::new(move || { + tripwire.fetch_add(1, Ordering::SeqCst); + false + })); - assert_eq!(result.code, 130); + { + let k = Arc::clone(&kernel); + let tripped = Arc::clone(&polls); + std::thread::spawn(move || { + let deadline = std::time::Instant::now() + bound; + while tripped.load(Ordering::SeqCst) < 2 && std::time::Instant::now() < deadline { + std::thread::sleep(std::time::Duration::from_millis(1)); + } + k.cancel(); + }); + } - let count = kernel.get_var("COUNT").await; - if let Some(Value::Int(n)) = count { - assert!(n > 0, "loop should have run at least once"); + let result = tokio::time::timeout( + bound, + kernel.execute_with_options("while true; do COUNT=$((COUNT + 1)); done", opts), + ) + .await + .unwrap_or_else(|_| { + panic!( + "while-loop did not return within {bound:?} — `while true` never ends on \ + its own, so the per-iteration cancellation checkpoint is not honoring the \ + token and this loop would have spun forever" + ) + }) + .expect("execute failed"); + + assert_eq!(result.code, 130, "cancelled execution should exit with code 130"); + + // A count above zero proves a *running* loop was interrupted, and it + // holds by construction: the cancel waits for the second poll. No upper + // bound — how far bare arithmetic gets is a function of host speed. + match kernel.get_var("COUNT").await { + Some(Value::Int(n)) => assert!(n > 0, "loop should have run at least once, got {n}"), + other => panic!("COUNT should be an integer set by the loop body, got {other:?}"), } } diff --git a/crates/kaish-kernel/tests/cancellation_tests.rs b/crates/kaish-kernel/tests/cancellation_tests.rs index 597fd50b..2724aad8 100644 --- a/crates/kaish-kernel/tests/cancellation_tests.rs +++ b/crates/kaish-kernel/tests/cancellation_tests.rs @@ -110,6 +110,31 @@ mod common_cancel { } } + /// Builds a script whose process installs a SIGTERM *ignore* before it + /// records its pid, then `exec`s `sleep` so the recorded pid is the very + /// process holding that ignore (SIG_IGN survives execve). + /// + /// The ordering is the whole point. Observing the pid file proves that pid + /// already ignores SIGTERM, so a later death can only have come from + /// SIGKILL. `pid_writer` records the pid from an outer shell and only then + /// execs the trapping one, which leaves a window where the pid exists but + /// the ignore does not — a SIGTERM landing in that window kills the child + /// outright and a test asserting "it died" still passes, having never + /// exercised any escalation. + pub fn term_ignoring_pid_writer(tmp_dir: &Path, pid_file: &Path) -> std::path::PathBuf { + let script_path = tmp_dir.join("term_ignoring_pid_writer.sh"); + let script = format!( + "#!/bin/bash\ntrap \"\" TERM\necho $$ > {pf}\nexec sleep 60\n", + pf = pid_file.display(), + ); + fs::write(&script_path, script).expect("write term_ignoring_pid_writer script"); + use std::os::unix::fs::PermissionsExt; + let mut perms = fs::metadata(&script_path).expect("stat script").permissions(); + perms.set_mode(0o755); + fs::set_permissions(&script_path, perms).expect("chmod script"); + script_path + } + pub fn kernel_for_test() -> Arc { Kernel::new( KernelConfig::repl() @@ -122,7 +147,10 @@ mod common_cancel { } } -use common_cancel::{child_alive, kernel_for_test, path_vars, pid_writer, wait_for_dead, wait_for_pid}; +use common_cancel::{ + child_alive, kernel_for_test, path_vars, pid_writer, term_ignoring_pid_writer, + wait_for_dead, wait_for_pid, +}; // ════════════════════════════════════════════════════════════════════════════ // 1. request_timeout kills a foreground external @@ -321,44 +349,90 @@ async fn pipeline_cascade_kills_both_stages() { #[tokio::test] async fn grace_escalation_sigkills_term_trapping_child() { + const GRACE: Duration = Duration::from_millis(200); + // Setup gets a budget of its own, and a generous one: how long bash needs + // to start is not what this test measures. + const SETUP_BUDGET: Duration = Duration::from_secs(10); + let tmp = tempfile::tempdir().expect("tempdir"); let pid_file = tmp.path().join("pid"); - // Trap SIGTERM and ignore; SIGKILL is uncatchable so the child dies after grace. - let script = pid_writer(tmp.path(), &pid_file, "bash -c 'trap \"\" TERM; sleep 60'"); + // Ignores SIGTERM before recording its pid, so the pid file appearing is + // proof the process cannot be killed by SIGTERM. SIGKILL is uncatchable, so + // if it dies at all, the escalation is what killed it. + let script = term_ignoring_pid_writer(tmp.path(), &pid_file); let kernel = Kernel::new( KernelConfig::repl() .with_skip_validation(true) - .with_kill_grace(Duration::from_millis(200)) + .with_kill_grace(GRACE) .with_initial_vars(path_vars()), ) .expect("kernel") .into_arc(); - let started = Instant::now(); - // 500ms timeout so the (nested) bash records its pid before the kill; the - // 200ms grace above is what this test really exercises — SIGKILL after the - // TERM-trapping child ignores SIGTERM. - let result = kernel - .execute_with_options( - &format!("bash {}", script.display()), - ExecuteOptions::new().with_timeout(Duration::from_millis(500))) - .await - .expect("execute"); - let elapsed = started.elapsed(); + // Setup and measurement used to share one clock: a 500ms request timeout + // started the kill while bash was still starting up, so on a loaded runner + // the child was killed before it ever wrote its pid and the test died at an + // `.expect("pid")` — in setup, having never reached the escalation it is + // named for. Reproduced at 11 failures in 20 runs under 4x CPU + // oversubscription. So the two phases are now separate: run with no request + // timeout at all, wait for the child to report itself ready on a budget that + // is allowed to be slow, and only then start the kill clock. + let command = format!("bash {}", script.display()); + let (result, ready) = tokio::join!( + kernel.execute(&command), + async { + let pid = wait_for_pid(&pid_file, SETUP_BUDGET).await.unwrap_or_else(|| { + panic!( + "SETUP FAILED — this is not a cancellation bug. The child never \ + recorded its pid in {SETUP_BUDGET:?} at {path}. The script writes its \ + pid immediately after installing its SIGTERM ignore, so nothing ever \ + reached a state that could be escalated, and the SIGTERM-to-SIGKILL \ + path this test exists to check was never exercised. Suspect a host too \ + loaded to start bash within the budget, or a broken PATH/spawn.", + path = pid_file.display(), + ) + }); + // The child is up and provably ignoring SIGTERM. Measurement starts + // here, not before. + let kill_requested = Instant::now(); + kernel.cancel(); + (pid, kill_requested) + } + ); + let result = result.expect("execute"); + let (pid, kill_requested) = ready; + let elapsed = kill_requested.elapsed(); + + // 137 is 128 + SIGKILL(9): the child's own wait status, reported straight + // through. This is the sharpest evidence the test has — 143 (128 + SIGTERM) + // would mean plain SIGTERM did the job and no escalation ever happened. + assert_eq!( + result.code, 137, + "expected 137 (128 + SIGKILL) — the TERM-ignoring child should have been \ + escalated to SIGKILL; 143 would mean SIGTERM killed it and the escalation \ + never ran", + ); - assert_eq!(result.code, 124); - let pid = wait_for_pid(&pid_file, Duration::from_secs(2)).await.expect("pid"); assert!( wait_for_dead(pid, Duration::from_secs(3)).await, - "TERM-trapping pid {} survived SIGKILL escalation", - pid, + "pid {pid} ignores SIGTERM and was still alive 3s after cancellation — the \ + SIGTERM-to-SIGKILL escalation never fired (kill grace is {GRACE:?})", ); - // Sanity: total time ≈ timeout + grace, not ~60s. + + // Escalation rather than a lucky SIGTERM: the child cannot die before the + // grace window closes, so anything faster means SIGKILL was sent without + // honoring the grace. + assert!( + elapsed >= GRACE, + "child was reaped {elapsed:?} after cancellation, inside the {GRACE:?} grace — \ + SIGKILL looks like it was sent without waiting out the grace period", + ); + + // Sanity: grace plus reaping, not ~60s of `sleep`. assert!( elapsed < Duration::from_secs(5), - "took too long ({:?}) — escalation may not have fired", - elapsed, + "took too long ({elapsed:?}) — escalation may not have fired", ); } @@ -514,8 +588,11 @@ async fn vars_plus_timeout_combo_kills_child_with_vars_visible() { assert_eq!(result.code, 124, "expected 124, got {}", result.code); - // Child wrote its PID and the WHO line before sleeping. Poll: the second - // line (WHO) may flush a beat after execute() returns under load. + // The child writes its pid on line 1 and the WHO line on line 2. This poll + // covers line 1 only: `read_pid` parses `lines().next()`, so it returns as + // soon as the pid is readable and waits for nothing else. If the WHO line + // has not landed yet, the `who line` expect below panics instead of waiting + // for it. let _ = wait_for_pid(&pid_file, Duration::from_secs(2)).await.expect("pid_file"); let contents = std::fs::read_to_string(&pid_file).expect("read pid_file"); let mut lines = contents.lines();