Skip to content

Cancellation tests raced their own setup #416

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
tobert merged 6 commits into from
Aug 25, 2026
Merged

Cancellation tests raced their own setup #416

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
081c8ea
test(kernel): close the pre-execute cancel race in the for-loop test
tobert Aug 24, 2026
0a32516
test(cancel): stop racing bash startup against the kill clock
tobert Aug 24, 2026
2e9b6fa
test(kernel): the while-loop cancel test hung instead of failing
tobert Aug 24, 2026
293336e
docs: correct two comments that describe behavior the code lacks
tobert Aug 24, 2026
5104c18
Release the cancel on the second poll, not the first
tobert Aug 25, 2026
10c717b
Cut the cancellation-test comments to the house length
tobert Aug 25, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
162 changes: 121 additions & 41 deletions crates/kaish-kernel/src/kernel.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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");
Expand Down Expand Up @@ -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<Kernel>, delay: std::time::Duration) {
let k = Arc::clone(kernel);
std::thread::spawn(move || {
Expand All @@ -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!(
Expand All @@ -8644,35 +8675,84 @@ 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::<i64>()
.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]
async fn test_cancel_interrupts_while_loop() {
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:?}"),
}
}

Expand Down
125 changes: 101 additions & 24 deletions crates/kaish-kernel/tests/cancellation_tests.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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> {
Kernel::new(
KernelConfig::repl()
Expand All @@ -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
Expand Down Expand Up @@ -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",
);
}

Expand Down Expand Up @@ -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();
Expand Down