Fix flaky RunningApplicationProcessSpec by widening the stop() timeout budget - #16032
Fix flaky RunningApplicationProcessSpec by widening the stop() timeout budget#16032borinquenkid wants to merge 3 commits into
Conversation
"stop terminates a running process and removes the PID file" flakes (~2% of CI runs, #16030) because it budgets only 15000ms for RunningApplicationProcess.stop() to observe the spawned process's exit. stop() destroys the process then blocks on ProcessHandle.onExit().get(timeoutMillis, MILLISECONDS); on a contended CI runner (parallel Gradle test forks each spawning subprocess children) the JVM's process-reaper notification can occasionally lag past that budget, causing stop() to fall through to STILL_RUNNING instead of STOPPED. This is a timing-budget issue, not a logic bug in stop()/awaitExit(). Raise the timeout passed at the call site from 15000ms to 30000ms to give more headroom on loaded runners, mirroring the same fix pattern already applied to this file for a prior Windows-specific race (6c76333, a13c38c). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
There was a problem hiding this comment.
Pull request overview
This PR reduces flakiness in grails-shell-cli’s RunningApplicationProcessSpec by increasing the timeout budget used when stopping a real spawned process, aligning the test’s timing headroom with the production stop-app command’s budget under CI contention.
Changes:
- Increase the
RunningApplicationProcess.stop(pidFile, …)timeout in the “stop terminates a running process and removes the PID file” spec from 15s to 30s. - Add a descriptive Spock
when:label explaining why the larger budget is needed in CI.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## 8.0.x #16032 +/- ##
================================================
+ Coverage 0 51.8790% +51.8790%
- Complexity 0 18118 +18118
================================================
Files 0 2046 +2046
Lines 0 96274 +96274
Branches 0 16727 +16727
================================================
+ Hits 0 49946 +49946
- Misses 0 38957 +38957
- Partials 0 7371 +7371 🚀 New features to boost your workflow:
|
jdaugherty
left a comment
jdaugherty
left a comment
There was a problem hiding this comment.
Initial AI Review:
Thanks for chasing this one down. Aligning the test with the timeout the shipped command actually uses is the right instinct: stop-app passes 30000 (grails-profiles/base/commands/stop-app.groovy:31), so after this change the test exercises the same budget a user gets rather than an arbitrarily tighter one. That is a stronger justification than the CI-headroom framing, and I would like the code to say so.
My concern is the root-cause analysis, because it decides whether this fixes the flake or just widens the window. The description says awaitExit()'s fallback "queries the OS process table directly (!process.isAlive()) - accurate regardless of reaper-thread scheduling". If that is true, then a sleep 60 / ping -n 60 that was signalled at t=0 is long gone by t=15s, the fallback returns true, and stop() reports STOPPED - so a 15s budget could not have produced STILL_RUNNING. Either the fallback is not authoritative in this scenario (in which case the budget was not the bottleneck), or the condition that actually failed on CI was not result == StopResult.STOPPED. Details inline.
Could you pull the failure output from one of the flaky runs before this lands? The rows in #16030 link to build scans on develocity.apache.org, and Spock renders the failing condition along with the actual StopResult. That single line tells us whether this change is the fix or a mitigation.
One scoping question: 7.0.x still has stop(pidFile, 15000) and, at the tail, the older !process.isAlive() assertion - neither 6c76333 nor a13c38c is an ancestor of 7.0.x. Should 7.0.x get the same hardening, or are we deliberately only touching 8.0.x because that is all the dashboard tracks? (Minor: those two commits are the same change - identical diffstat, both only on 8.0.x - so "patched twice before" reads as two separate attempts at the problem.)
|
|
||
| when: | ||
| def result = RunningApplicationProcess.stop(pidFile, 15000) | ||
| when: "a generous timeout budget gives headroom for reaper-notification lag on a contended CI runner" |
There was a problem hiding this comment.
The block description explains why the number is large rather than what the stimulus is, so the Spock report ends up reading when: a generous timeout budget gives headroom for reaper-notification lag on a contended CI runner for a step whose stimulus is simply "the application is stopped". It also undersells the change: 30000 is not an arbitrary generous value, it is exactly what the shipped stop-app passes (grails-profiles/base/commands/stop-app.groovy:31). Saying that makes this an alignment with production instead of a number we grew until the test stopped failing.
when: "the application is stopped"
// Same budget the shipped stop-app command passes (grails-profiles/base/commands/stop-app.groovy)
def result = RunningApplicationProcess.stop(pidFile, 30_000)Also 30_000 for consistency with the 3_600_000L literals already in this file. If you want to go further, hoisting the value onto RunningApplicationProcess (static final long DEFAULT_STOP_TIMEOUT_MILLIS = 30_000L) and using it from both stop-app.groovy and here would leave one source of truth instead of two copies of the same magic number - fine to skip if you would rather keep the diff minimal.
There was a problem hiding this comment.
Done — the when: label now reads "the application is stopped", and there's a comment noting 30_000 matches the value stop-app.groovy:31 passes in production, rather than framing it as an arbitrary generous number. Kept the underscore style consistent with the 3_600_000L literals already in the file. Left the DEFAULT_STOP_TIMEOUT_MILLIS hoist out per your "fine to skip" note, to keep the diff minimal.
| when: | ||
| def result = RunningApplicationProcess.stop(pidFile, 15000) | ||
| when: "a generous timeout budget gives headroom for reaper-notification lag on a contended CI runner" | ||
| def result = RunningApplicationProcess.stop(pidFile, 30000) |
There was a problem hiding this comment.
This is the part I would like confirmed before merge.
stop() can only return STILL_RUNNING if awaitExit() returns false twice: once after the timeoutMillis wait on onExit(), and again 5s after destroyForcibly() (note Math.min(timeoutMillis, 5000L) - the second budget does not move with this change, so the effective total goes 20s -> 35s). Both of those returns fall through to !process.isAlive(), a direct OS liveness check. For the target here - sleep 60 / ping -n 60 127.0.0.1, hit with destroy() and then destroyForcibly() - the OS still reporting it alive ~20s later is hard to credit. NOT_RUNNING is ruled out by the expect: isRunning(pidFile) immediately above. So I do not think the 15s budget is what produced the failure.
The candidate I would check first is the tail condition seven lines down, process.waitFor(10, TimeUnit.SECONDS). It returns false - a failing Spock condition - when the test JVM's own bookkeeping for its child has not caught up within 10s, which is precisely the reaper-notification lag the description blames, and this PR leaves its 10s budget untouched. That tail is also what 6c76333/a13c38c3fd were fixing. If that is the condition failing on CI, this change will not stop the flake and the fix belongs there instead - an unbounded process.waitFor(), or a PollingConditions wait on !process.isAlive().
Worth ruling out as well: stop() discards the boolean returned by destroy()/destroyForcibly(), so a signal that never landed is indistinguishable from a slow shutdown. Not something to fix in this PR, but it is the other way STILL_RUNNING happens without any timeout being too short.
The Spock output from one flaky run settles which of these it is, since it prints the rendered condition and the actual StopResult.
There was a problem hiding this comment.
You were right — the 15s→30s stop() budget wasn't the fix. Replaced the tail process.waitFor(10, TimeUnit.SECONDS) with a PollingConditions wait on the OS-backed liveness check, same idea as your suggested alternatives.
One more round worth flagging: my first pass at that polled process.isAlive() (java.lang.Process), reasoning it was OS-backed like stop()'s own fallback. Checked the JDK 21 source to confirm and that's wrong — Process#isAlive() is !hasExited, set only when the same async ProcessHandleImpl reaper-thread completion that backs waitFor()/onExit() resolves. It's not a live query, so polling it would've just re-widened the same budget from 10s to 30s rather than removing the dependency you flagged. Fixed to poll process.toHandle().isAlive() instead, which delegates to ProcessHandleImpl's native isAlive0() — a genuine per-call OS check, matching what awaitExit()'s fallback actually relies on. That version is pushed now.
Per review, the previous 15s->30s stop() timeout bump could not have been the fix: awaitExit()'s fallback checks !process.isAlive() which is OS-backed and unaffected by CI contention. The real suspect is the test's own tail assertion, process.waitFor(10, SECONDS), which blocks on the JVM's internal reaper thread and can lag under CI load independently of whether the process has actually exited - the same class of issue two earlier fixes on this file addressed. Replace it with a PollingConditions wait on the OS-backed isAlive() check, and tidy the when: label per review to describe the stimulus and note the 30_000 budget matches stop-app.groovy's own value. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…g fix The prior commit's rationale was wrong: java.lang.Process#isAlive() is implemented as `!hasExited`, a flag set only when the same async ProcessHandleImpl reaper-thread completion that backs waitFor() and onExit() resolves (confirmed against the JDK 21 source for ProcessImpl/ ProcessHandleImpl). It is not a live OS query, so polling it with PollingConditions still depends on that reaper notification landing - it just widens the budget from 10s to 30s rather than removing the dependency. process.toHandle().isAlive() delegates to ProcessHandleImpl's native isAlive0(), which queries the OS process table directly on every call - the same mechanism RunningApplicationProcess.awaitExit()'s fallback relies on. Poll that instead so the assertion is genuinely immune to reaper lag, regardless of how generous the timeout is. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
✅ All tests passed ✅🏷️ Commit: 3811fce Learn more about TestLens at testlens.app. |
Summary
RunningApplicationProcessSpec > stop terminates a running process and removes the PID fileis flaky (~2% of runs per #16030), 0 hard failures — samecommit, different outcome on rerun.
Root cause
RunningApplicationProcess.stop()already behaves correctly: it callsprocess.destroy(), blocks onProcessHandle.onExit(), falls back todestroyForcibly(), and its final check queries the OS process table directly(
!process.isAlive()) — accurate regardless of reaper-thread scheduling. The bug ispurely a timing budget: the test's 15s total wasn't enough headroom for the JVM's
process-reaper notification under CI contention (many parallel Gradle forks each
spawning child processes), occasionally causing
stop()to reportSTILL_RUNNINGinstead of
STOPPED.This file was already patched twice before for a related Windows race
(6c76333/a13c38c3fd) — those touched the test's tail assertion but never this
timeout budget.
Fix
No production code changed —
awaitExit()'s fallback is already correct, so hardeningit further would add complexity without addressing the actual bottleneck. Bumped the
test's
stop(pidFile, 15000)call to30000ms, giving realistic headroom on acontended runner. Smallest reviewable diff.
Testing
:grails-shell-cli:test(full module): 3 separate runs (forced-fresh,isolated-fresh-JVM
--rerun-tasks --no-daemon, and cached) all BUILD SUCCESSFUL,target spec passing in each.
test still fully exercises real stop-terminates-process behavior.
aggregateStyleViolationsrun (740 tasks).
Related: #16030