Skip to content

Give in-flight jobs enough pause to survive slow shutdowns in tests - #782

Open
wintan1418 wants to merge 3 commits into
rails:mainfrom
wintan1418:widen-shutdown-race-margins
Open

Give in-flight jobs enough pause to survive slow shutdowns in tests#782
wintan1418 wants to merge 3 commits into
rails:mainfrom
wintan1418:widen-shutdown-race-margins

Conversation

@wintan1418

Copy link
Copy Markdown
Contributor

Related to #602. Companion to #776, targeting the next-most-frequent flakes in recent CI runs: AsyncProcessesLifecycleTest#test_term_supervisor_exceeding_timeout_while_there_are_jobs_in-flight (and its forked twin) and ConcurrencyControlsTest#test_don't_block_claimed_executions_that_get_released, each seen failing standalone on recent main/PR runs with:

Expected "completed" to not be equal to "completed".   # lifecycle variant
Expected true to be nil or false                       # job.finished? variant

The race

All three tests enqueue a job that pauses for shutdown_timeout + 10.seconds and assert it does not complete while its process is terminated mid-flight. But the pause clock starts when the job begins executing, not when the test detects it started. On a slow runner, the detection polling (up to ~8s) plus the termination window (up to ~7s) can add up to more than the pause: the sleep finishes inside the still-alive process, the job writes completed, and the assertion fails. Nothing kills the sleeping thread earlier — wait_for_termination only waits, so the job thread survives until actual process death.

Fix

Widen the pause to shutdown_timeout + 30.seconds. Since the job is killed mid-sleep in every intended outcome, this doesn't change any test's runtime — only the margin against slow runners (from ~2s of slack to ~22s).

Verified all three tests green on MySQL locally; runtime unchanged (the two lifecycle tests together still run in ~6s).

Three tests assert that a job paused mid-flight does NOT complete while
its process is terminated: the async and forked "term supervisor
exceeding timeout" tests and "don't block claimed executions that get
released". They paused the job for shutdown_timeout + 10 seconds, but
that clock starts when the job starts executing, and on a slow CI
runner the test's detection waits (up to 8 seconds of polling for the
job to show as started) plus the termination window (up to 7 more) can
outlast it: the sleep finishes inside the still-alive process, the job
writes its completed status, and the assertion fails.

Widen the pause to shutdown_timeout + 30 seconds. The job is killed
mid-sleep either way, so the test's runtime doesn't change; only the
margin against slow runners does.

Related to rails#602
The pause job's sleep is far longer than the test's entire timeline, so
when this assertion fails on CI with the job completed, the write must
have come from outside the test's own flow — a process or thread leaked
from a neighboring test. That can't be diagnosed from "expected
completed to not be equal to completed", so include all job results and
the registered processes in the failure message.
@wintan1418

Copy link
Copy Markdown
Contributor Author

Update: the async variant of this flake fired again on this PR's own CI run, so the widened pause alone doesn't fully explain it. Notably, with the pause now at shutdown_timeout + 30s, the job cannot complete within the test's ~15s timeline through its own code path — so a completed status can only come from a process or thread leaked by a neighboring test. I couldn't reproduce that locally (15 isolated runs + several full-suite runs with random seeds on Postgres, all green, one non-reproducible failure), so I've added forensics to the assertion: on failure it now dumps all JobResult rows and the registered processes, which will identify the writer the next time CI catches it.

The test waits for the job's "started" result before SIGKILLing the
worker, but with the non-raising wait and only 2 seconds of margin: on a
slow runner, worker boot plus polling plus claiming can take longer, the
guard gives up silently, and the KILL lands before the job ever starts —
so the "started" row the test asserts on later never gets written.

Use the raising variant with a 10 second margin, so a job that never
starts fails the test right at the guard, and widen the job's pause so
the KILL can't arrive after the pause has already finished on a slow
runner (which would complete the job and erase the "started" status
too). Neither change affects the test's runtime in the intended flow.
@wintan1418

Copy link
Copy Markdown
Contributor Author

Pushed one more fix in the same family: test_kill_worker_individually (seen failing on a recent CI run with Expected: 1, Actual: 0 at the assert_started_job_result line). The test guards the SIGKILL behind a wait for the job's "started" row, but with the non-raising wait variant and only 2s of margin — on a slow runner the guard gives up silently and the KILL lands before the job ever starts, so the asserted row never exists. Now uses the raising variant with 10s margin (a job that never starts fails loudly at the guard), and the job's pause is widened so the KILL can't land after the pause already finished. No runtime change in the intended flow; file green 3/3 + full file pass on Postgres locally.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant