Repository navigation
Flaky test: GrizzlyLDAPListenerTestCase#testLDAPListenerProxyDuringHandleAccept times out on CI #1180
Description
Summary
GrizzlyLDAPListenerTestCase#testLDAPListenerProxyDuringHandleAccept (module opendj-grizzly) timed out on the master build after #1171 was merged, which turned the README Build badge red. #1171 does not touch opendj-grizzly. This is the only failure among the 1040 tests of the module, and every other OS/JDK combination in the same run passed.
Example failure
Run: https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/37594301543/job/112703019797 (build-maven (windows-latest, 26), push of 3f4deb9 to master, attempt 1)
[ERROR] org.forgerock.opendj.grizzly.GrizzlyLDAPListenerTestCase.testLDAPListenerProxyDuringHandleAccept -- Time elapsed: 10.03 s <<< FAILURE!
java.util.concurrent.TimeoutException
at org.forgerock.util.promise.PromiseImpl.await(PromiseImpl.java:636)
at org.forgerock.util.promise.PromiseImpl.get(PromiseImpl.java:138)
at org.forgerock.opendj.grizzly.GrizzlyLDAPListenerTestCase.testLDAPListenerProxyDuringHandleAccept(GrizzlyLDAPListenerTestCase.java:605)
This test does not appear in the failures of the last 30 failed build.yml runs, so it is rare.
What the failure tells us
Line 605 is the first wait:
assertThat(proxyServerConnection.context.get(10, TimeUnit.SECONDS)).isNotNull(); // line 605
assertThat(onlineServerConnection.context.get(10, TimeUnit.SECONDS)).isNotNull();The total elapsed time is 10.03 s, so the client connect to the proxy listener returned almost at once, and then the proxy's context promise was not resolved for the full 10 seconds.
In this test the proxy's context is resolved only by super.handleAccept(clientContext) at the end of the overridden handleAccept (line 588). Before that, handleAccept makes two blocking connections on the accepting thread:
- to an "offline" address from
findFreeSocketAddress(), which is expected to fail with aConnectionException; - to the online listener.
So the 10 s window covers both of those connection attempts as well as the accept itself. This is a different signature from #766. There, the bind succeeded and the second wait expired, because the load balancer had connected back to the proxy through a reused port. Here, the "offline" port is picked inside handleAccept, after both listeners are already bound, so the proxy cannot be handed that port.
Hypotheses to check
- A refused connect to the offline port is slow on Windows. On Windows,
connect()to a closed loopback port does not fail on the first RST: the stack retries the SYN and reports the refusal only after about 2 s.offlineAddress.getHostName()may also resolve to more than one address, and each one costs a separate attempt. On a loaded 4-CPU runner, that time plus the online connection plus the accept itself can approach the 10 s window. A local Windows run that times the offlinelcf.getConnection()would confirm or rule this out. - The accept event is processed late.
handleAcceptblocks a transport thread for the whole duration of both connection attempts. If the same thread also has to process the client or online-server connection events, the wait gets longer.
Test-hygiene problems found along the way (same kind as #766/#767)
- Neither
LDAPConnectionFactorycreated insidehandleAccept(offline and online) is closed, and neither is the factory behind the clientconnection. connection.close()is reached only if both asserts pass. On a timeout, the client connection leaks into the rest of the module run.proxyServerConnection.isClosed.await()has no timeout, and the method has no@Test(timeOut = …), unlike its neighbourtestLDAPListenerProxyDuringHandleBind. A real hang here would block the whole CI job instead of failing one test.
Suggested direction
- Measure first (hypothesis 1) instead of only enlarging the window. If the time goes into the refused connect, the test can bound the "offline" attempt with an explicit short
LDAPConnectionFactory.CONNECT_TIMEOUTand connect to the numeric loopback address instead ofgetHostName(). - Close the factories and the client connection in
finally, and bound theisClosedwait.
Activity
[OpenIdentityPlatform#1180] Report every fail-over failure of the Gri…
[OpenIdentityPlatform#1180] Report the fail-over failure of the Grizz…