Cancellation tests raced their own setup - #416
Merged
Merged
Conversation
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 <noreply@anthropic.com>
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 <script>" with a 500ms request timeout, then waited
up to 2s for the child to report its pid. Those two things look like
setup and measurement but they shared one clock: the timeout starts
when execute() is called, so a loaded host that needs longer than
500ms to fork, exec and reach the first line of bash gets its child
killed before the pid is ever written. Polling for 2s afterwards
cannot help -- the process is already dead and nothing will ever write
that file. So the test failed having never reached the
SIGTERM-to-SIGKILL escalation it is named for.
The phases are now split. The command runs with no request timeout at
all, a concurrent branch waits for the child on a 10s budget that is
allowed to be slow, and only once the child reports ready does that
branch take an Instant and call Kernel::cancel(). wait_or_kill races
the cancellation token, so cancel drives exactly the same
kill_with_grace cascade the timeout did -- the escalation under test
is unchanged, only what starts it.
Probing the old script turned up a second, quieter problem. It wrote
its pid from an outer bash and only then exec'd the trapping inner
one, so the pid could exist before the trap did; a SIGTERM landing in
that window kills the child outright, and a test that only asserts
"it died" passes without exercising any escalation. The new helper
installs the ignore first, records the pid second, and execs sleep
(SIG_IGN survives execve -- verified: the process shows Name: sleep
with SigIgn bit 15 set and shrugs off SIGTERM). Now the pid file
appearing is proof that pid cannot be killed by SIGTERM.
That let the assertions get sharper rather than looser. The exit code
is pinned to 137, which is 128 + SIGKILL and is direct evidence of the
escalation -- 143 would mean SIGTERM did the job. Elapsed time is
asserted to be at least the grace, so a cascade skipping straight to
SIGKILL fails too; that is a lower bound on wall clock, which load can
only push the right way. The pid wait now explains that a failure
there is setup, not a cancellation bug, and says what it waited for
and for how long.
25/25 clean under the same 4x oversubscription that failed the old
test 11 times in 20.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
test_cancel_interrupts_while_loop has the same swallowed-cancel race the for-loop test just lost: schedule_cancel() arms a 10ms timer before execute() is called, and execute() opens with reset_cancel(), which replaces an already-cancelled token. If the test thread is descheduled past the timer, the cancel is discarded. The for-loop test went red when that happened. This one does not go red at all -- it hangs. "while true" has no iteration count to run out and the test had no bound, so a dropped cancel leaves the loop spinning until CI's own job timeout kills the run: no assertion fires, no message is printed, and a core burns the whole time. I forced the swallow to confirm it, and the loop simply never returns. That is strictly worse than a flake, because a flake at least tells you it failed. Same fix as the for-loop. An ExecuteOptions::interrupt tripwire trips on its first poll, which happens at the Stmt::While arm's per-iteration checkpoint and cannot happen until after reset_cancel() has run, so the cancel can no longer be dropped; a background OS thread waits on that flag and calls Kernel::cancel(), keeping the embedder's real cancel door under test. Then a bound, so a broken checkpoint can never hang this again. I had assumed a bound could not help, on the theory that a body of bare arithmetic never yields and an in-task timeout can only fire if the future it wraps returns Pending. Measured instead of assumed: a 3s tokio::time::timeout does preempt this loop, so each iteration yields to the runtime somewhere. A plain bound is enough and the loop body did not have to change. The COUNT check is now unconditional. The old "if let Some(Value::Int(n))" silently asserted nothing whenever the type did not match -- the same shape that had already quietly killed the for-loop test's own iteration check. It stays a lower bound only: the body is bare arithmetic with no sleep, so how far it gets before the cancel lands is a function of host speed and is not worth pinning. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Both were found while fixing the flaky cancellation tests, and both
are the load-bearing kind: they tell a reader a safety net exists
where there is none.
schedule_cancel's doc said "Kernel is not Send". It is Send + Sync --
the helper moves an Arc<Kernel> into the thread on the next line,
which would not compile otherwise. The real reasons for an OS thread
are that cancel() is sync and that the thread has to run while the
current-thread test runtime is inside execute(). The doc now says
that, and also warns what the delay actually races: a cancel firing
before execute() reaches reset_cancel() is discarded, which is the bug
that made two tests in this file flaky. Its one remaining caller
should know.
The vars-combo test claimed its poll covered the WHO line flushing "a
beat after execute() returns under load". It does not. wait_for_pid
calls read_pid, which parses lines().next() and returns the moment the
pid on line 1 is readable; it never looks at line 2. If the WHO line
has not landed, the expect("who line") below panics rather than
waiting. Comment now says which line the poll covers and what happens
to the other one.
Also documents, at reset_cancel itself, the behavior that caused the
flakes: a cancel arriving while nothing runs is dropped, the next
execute() reports nothing about it, an embedder can observe it in
advance via is_cancelled(), and a call that must start already
cancelled has to pass its own ExecuteOptions::cancel_token, which is
never reset. Comment only -- no behavior change.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Review found the flake fix had opened a narrower one of its own. `is_cancelled()` polls the interrupt closure and only then reads the token. The closure trips the tripwire, the background thread watches the tripwire and calls `cancel()`, and the checkpoint runs BEFORE the loop body. So on the first poll the cancel can land before the body has run once: the loop exits, `COUNT`/`X` was never assigned, and the test fails on an assertion about a loop that was cancelled correctly. The comment above that assertion claimed a count above zero proves the body ran. It did not prove it — it hoped for it, and the hope was the stated reason the assertion was written that way. Load-bearing and false, which is the shape we keep finding by reading rather than by testing. Count the polls instead of latching a bool, and release the cancel on the second. `self.is_cancelled()` has exactly two call sites, both loop checkpoints, so one complete iteration separates poll one from poll two and the assertion is true by construction. The comment now says why.
95 comment lines across the two tests, for the reasoning behind the fix rather than what a reader needs at the site. The narrative is already in the commit messages; 48 lines is what stays.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Two cancellation tests failed at random on CI and passed on an idle machine; a third hung until the job timed out. All three shared one cause, and it was not a slow runner.
Kernel::execute()opens withreset_cancel(), which replaces a token that is already cancelled. The test helper started its timer beforeexecute()was called, so when the thread was descheduled past the delay the cancel was discarded and the loop ran to natural completion.A cliff, not a slowdown, so no larger bound would have helped and the bounds are unchanged. Each test now waits for evidence that execution is under way before it cancels.
The third test hung because
while truehas no iteration cap and no timeout. It now fails in ten seconds and says why.Two assertions had been passing silently: a loop variable binds as a string, so
if let Some(Value::Int(n))never matched. Both are unconditional now, and each fix was checked by breaking the mechanism it guards and confirming the test fails.Test-only. Every change outside the test module is a doc comment.
🤖 Generated with Claude Code