ci: make the three untraceable CI flakes say what is happening when they next occur - #16220
ci: make the three untraceable CI flakes say what is happening when they next occur#16220codeconsole wants to merge 6 commits into
Conversation
GRAILS-16219: AsyncPromiseSpec fails now and then with the client giving up after 120 seconds, against an endpoint that cannot take that long - it waits on a future for five seconds and answers. All four occurrences say only that the client gave up, which does not distinguish a request that was never served from one that was served too slowly. An integration test runs the application in the test's own JVM, so the threads that would answer are here to be asked. A request that passes 90 seconds now prints every thread in the JVM, Tomcat's acceptor and workers among them, while the request is still outstanding - after the client times out they have moved on. Each request also carries a correlation id, so a line from the client can be paired with one from the server. Off with -Dgrails.http.client.diagnostics=false, and the threshold moves with -Dgrails.http.client.diagnostics.seconds. The timer thread is a daemon, deliberately: a build has already hung on a test JVM that could not exit. Checked by lowering the threshold to zero: 17 reports, 36 threads each, Tomcat's included; and at one second, none, because nothing was that slow. 800 functional tests unchanged either way.
GRAILS-16217: UserControllerSpec waits thirty seconds for a login page that never goes away, and the page captured at the failure is a fresh login form - empty fields, no error. Three explanations fit that page, and the captured page cannot tell them apart: no session cookie was ever issued, one was issued for another host, or one was issued and then lost. What tells them apart is which cookie the browser held, and when. It is now reported when the login page loads, immediately before the form is submitted, and at whatever follows - hashed rather than printed, which is enough to see a session replaced or lost without putting a session id in a public log. Spring Security logs at debug in this application for the other half of the question: whether the request arrived, under which session, and what was made of it. On a passing run the three lines read as they should: the same session through the submit, and a new one after it, which is session fixation protection doing its job.
GRAILS-16218: this job has twice stopped producing output after its last task and held a runner until GitHub's six hour ceiling. There is no evidence about it beyond the process list the runner prints as it cleans up, and a step placed after the build cannot help - while the build is hung, a later step never arrives. So the watchdog is armed before the build instead, and sleeps past the point where this job should have finished. It then reports every JVM twice, a minute apart: command line, heap, and threads with locks, plus the process tree and the tail of the Gradle daemon logs. One dump says what a thread is doing; two say whether it is doing anything at all. The job is also capped at two hours. It normally finishes in 40 to 65 minutes, so a hang now costs a fifth of what it did, and the watchdog has long since reported by then. Its output is printed by a step marked always(), which is reached when the cap cancels the job.
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## 8.0.x #16220 +/- ##
==================================================
+ Coverage 54.1129% 54.1453% +0.0325%
+ Complexity 20301 20262 -39
==================================================
Files 2107 2099 -8
Lines 101146 100945 -201
Branches 17922 17899 -23
==================================================
- Hits 54733 54657 -76
+ Misses 38605 38497 -108
+ Partials 7808 7791 -17
🚀 New features to boost your workflow:
|
The failing run on this branch is #16217SiteMesh 2 Functional Tests (Java 21, indy=false) failed on That is not a regression from this branch. It is #16217 occurring on the branch that instruments it, and the instrumentation caught it. What follows is the first evidence on this issue beyond a client-side stack trace. What the browser heldThree logins ran back to back in the same test JVM against the same application. The two that passed: The one that failed: What that settlesThe description offered three explanations: no cookie was issued, one was issued for another host, or one was issued and then lost. None of them holds. A cookie was issued, it carried the right domain and path, and it was still held - unchanged, same hash - for the full thirty seconds after the submit. What is absent is the change both successful logins show. The url is consistent with that. This application has no So the fault is upstream of the cookie, and two possibilities remain:
The report as it stood cannot separate those two. Why it could not go furtherTwo pieces of evidence existed on the runner and neither reached us. The server half never ran. The The page was captured and then discarded. Changes
One asymmetry worth naming: the client-side report hashes session ids deliberately, and Spring Security at DEBUG prints them in full. These are sessions of a throwaway test application with hardcoded credentials, running in a container for the length of one test, so there is nothing there to protect - but it is not the same standard on both sides, and it is another reason this logger comes out when #16217 closes. Each change remains revertible on its own. |
GRAILS-16217: the run of this branch on 25 August reproduced the flake, and the browser reports did their job - the same session was held, unchanged, through the submit and for the thirty seconds after. That rules out all three explanations they were written to tell apart: a cookie was issued, it carried the right domain and path, and it was neither lost nor replaced. What is absent is the session rotation both passing logins show, so nothing was ever authenticated. The server half was supposed to say whether the request arrived, and it said nothing, because the logger sat inside <springProfile name="development"> while integration tests run under "test". It was never applied, and a root level of ERROR silenced it - across 49,134 lines of that job's log there is not one line from it. It now sits outside every springProfile block, and a local run prints "Securing POST /login", the authentication, and the session change. Each browser report also carries form=, which reads retained while the field still holds what was typed, empty once a new login document has replaced it, and gone when the field is absent. A passing login reads empty, retained, gone. That distinguishes a submit that never left the browser from one that arrived and was answered with another login page, which the cookies alone cannot do.
GRAILS-16217: these specs run with reporting enabled, so GebOnFailureReporter writes the page source and a screenshot of the failing browser into build/geb-reports. gradle.yml uploads that directory when its functional job fails; this workflow runs the same suites and had no upload step at all, so on 25 August the page from the failure was written on the runner and then died with it. It now uploads the same path, on failure, as gradle.yml does.
✅ All tests passed ✅🏷️ Commit: 556a442 Learn more about TestLens at testlens.app/docs. |
1 participant
Instrumentation for the three CI flakes that are currently untraceable: #16217, #16218 and #16219. No production code, no behaviour change, and each piece removable when its issue closes.
They are together rather than in three pull requests because each run of this branch exercises all three, and these failures are rare enough that coverage per run is what decides whether the next one is diagnosable.
Why instrumentation rather than a fix
Each of the three has occurrences but no evidence beyond a client-side stack trace, and each has already had a fix proposed on a mechanism that turned out to be wrong. What follows is designed to make the next occurrence say which layer is responsible - not to guess at it now.
#16219 - a request that never answers
AsyncPromiseSpecfails withHttpTimeoutExceptionafter 120 seconds against/asyncTest/useAsyncService, an action that waits on a future for five seconds and answers. Four occurrences, three different features, two applications, one of them on8.0.x; all say only that the client gave up.An integration test runs the application in the test's own JVM, so the threads that would serve the request are available to be asked. A request that passes 90 seconds now prints every thread in the JVM while it is still outstanding; after the client times out, those threads have moved on. Every request also carries
X-Grails-Test-Correlation-Id.That distinguishes: never served, queued and starved, blocked in the controller, or answered but not read.
-Dgrails.http.client.diagnostics=falseturns it off;-Dgrails.http.client.diagnostics.secondsmoves the threshold.Checked: with the threshold at zero, 17 reports, 36 threads each including Tomcat's acceptor and every
http-nio-auto-1-exec-*. With it at one second, none, because no request was that slow. 800 functional tests pass unchanged either way.#16217 - a login form submitted without a session
The page captured at that failure is a fresh login form: empty fields, no error. Three explanations fit it and the page cannot tell them apart - no cookie was issued, one was issued for another host, or one was issued and then lost.
The browser is now reported at three moments - login page loaded, about to submit, and whatever follows - with cookie names, hashes, domain and path, plus the url. Hashed rather than printed: enough to see a session replaced or lost, without putting a session id in a public log. Spring Security logs at debug in this application for the server half.
Checked, on a passing run:
The same session through the submit, a new one after it - session fixation protection working. A failure will differ in exactly one of those places.
#16218 - a build that stops after its last task
Twice this job has stopped producing output after
:grails-test-examples-aot:checkand held a runner to the six hour ceiling, leaving only the process list the runner prints while cleaning up.A step placed after the build cannot help: while the build is hung, a later step never arrives. The watchdog is therefore armed before it, sleeps past the point where the job should have finished, and reports every JVM twice a minute apart - command line, heap, threads with locks - plus the process tree and the tail of the Gradle daemon logs. One dump says what a thread is doing; two say whether it is doing anything at all.
The job is also capped at
timeout-minutes: 120. It normally finishes in 40 to 65 minutes, so a hang costs a fifth of what it did, and the watchdog has reported long before. Its output is printed by a step markedalways(), which is reached when the cap cancels the job.Checked: the script runs locally, finds the JVMs through
jpsand dumps them;./gradlew validateActionspasses and the workflow parses with the steps in the intended order.Removing it
Each commit is self-contained and revertible on its own. When an issue closes, its commit goes.