-
Bug
-
Resolution: Fixed
-
P4
-
21
-
b10
The IdleConnectionTimeoutTest has been observed failing once in the CI.
The test tries to detect whether a connection was reused or not in the server handler by comparing the address+port of the remote client. If the address and port is the same, it assumes that the connection has been reused.
However, when a connection is closed, there is still a chance that a new connection will be able to reuse the same port than the old connection that was just closed, and this is what has been observed here:
#section:testng
----------messages:(7/1505)----------
command: testng -Djdk.httpclient.HttpClient.log=errors -Djdk.httpclient.keepalive.timeout.h2=1 IdleConnectionTimeoutTest
...
finished: Fri Jan 27 11:30:01 UTC 2023
elapsed time (seconds): 3.609
...
----------System.out:(44/2759)----------
config IdleConnectionTimeoutTest.setup(): success
test IdleConnectionTimeoutTest.test(): failure
java.lang.AssertionError: idleConnectionTimeoutEvent was expected but did not occur expected [200] but found [400]
at org.testng.Assert.fail(Assert.java:99)
at org.testng.Assert.failNotEquals(Assert.java:1037)
at org.testng.Assert.assertEqualsImpl(Assert.java:140)
at org.testng.Assert.assertEquals(Assert.java:122)
at org.testng.Assert.assertEquals(Assert.java:907)
at IdleConnectionTimeoutTest.test(IdleConnectionTimeoutTest.java:124)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:578)
at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at org.testng.TestRunner.privateRun(TestRunner.java:764)
at org.testng.TestRunner.run(TestRunner.java:585)
at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
at org.testng.SuiteRunner.run(SuiteRunner.java:286)
at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
at org.testng.TestNG.runSuites(TestNG.java:1069)
at org.testng.TestNG.run(TestNG.java:1037)
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:93)
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:53)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:578)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:125)
at java.base/java.lang.Thread.run(Thread.java:1623)
===============================================
java/net/httpclient/http2/IdleConnectionTimeoutTest.java
Total tests run: 1, Passes: 0, Failures: 1, Skips: 0
===============================================
----------System.err:(44/2287)----------
TestServer(1): accepting connections
Test run for jdk.httpclient.keepalive.timeout.h2=1
TestServer(1): connection accepted
TestServer(1): stopping is: false
TestServer(1): accepting connections
TestServer(1): creating connection
TestServer: New connection from Socket[addr=/127.0.0.1,port=43374,localport=40965]
TestServer(1): starting connection
TestServer: GET /serverTimeoutHandler
Server: creating input stream for stream 1
TestServer(1): connection started
TestServer(1): Using handler for: /serverTimeoutHandler
Sent response headers 200
Jan 27, 2023 11:30:00 AM jdk.internal.net.http.Http2Connection shutdown
INFO: ERROR: java.net.http.HttpConnectTimeoutException: HTTP connection idle, no active streams. Shutting down.
at java.net.http/jdk.internal.net.http.Http2Connection$IdleConnectionTimeoutEvent.handle(Http2Connection.java:213)
at java.net.http/jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1850)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:1459)
Server connection to /127.0.0.1:43374 stopping. 1 streams
TestServer: Connection writer stopping
TestServer(1): connection accepted
TestServer(1): stopping is: false
TestServer(1): accepting connections
TestServer(1): creating connection
TestServer: New connection from Socket[addr=/127.0.0.1,port=43374,localport=40965]
TestServer(1): starting connection
TestServer: GET /serverTimeoutHandler
Server: creating input stream for stream 1
TestServer(1): Using handler for: /serverTimeoutHandler
Sent response headers 400
TestServer(1): connection started
java.lang.Exception: failures: 1
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:95)
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:53)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:578)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:125)
at java.base/java.lang.Thread.run(Thread.java:1623)
JavaTest Message: Test threw exception: java.lang.Exception: failures: 1
JavaTest Message: shutting down test
STATUS:Failed.`main' threw exception: java.lang.Exception: failures: 1
----------rerun:(55/11152)*----------
The test tries to detect whether a connection was reused or not in the server handler by comparing the address+port of the remote client. If the address and port is the same, it assumes that the connection has been reused.
However, when a connection is closed, there is still a chance that a new connection will be able to reuse the same port than the old connection that was just closed, and this is what has been observed here:
#section:testng
----------messages:(7/1505)----------
command: testng -Djdk.httpclient.HttpClient.log=errors -Djdk.httpclient.keepalive.timeout.h2=1 IdleConnectionTimeoutTest
...
finished: Fri Jan 27 11:30:01 UTC 2023
elapsed time (seconds): 3.609
...
----------System.out:(44/2759)----------
config IdleConnectionTimeoutTest.setup(): success
test IdleConnectionTimeoutTest.test(): failure
java.lang.AssertionError: idleConnectionTimeoutEvent was expected but did not occur expected [200] but found [400]
at org.testng.Assert.fail(Assert.java:99)
at org.testng.Assert.failNotEquals(Assert.java:1037)
at org.testng.Assert.assertEqualsImpl(Assert.java:140)
at org.testng.Assert.assertEquals(Assert.java:122)
at org.testng.Assert.assertEquals(Assert.java:907)
at IdleConnectionTimeoutTest.test(IdleConnectionTimeoutTest.java:124)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:578)
at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
at java.base/java.util.ArrayList.forEach(ArrayList.java:1511)
at org.testng.TestRunner.privateRun(TestRunner.java:764)
at org.testng.TestRunner.run(TestRunner.java:585)
at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
at org.testng.SuiteRunner.run(SuiteRunner.java:286)
at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
at org.testng.TestNG.runSuites(TestNG.java:1069)
at org.testng.TestNG.run(TestNG.java:1037)
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:93)
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:53)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:578)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:125)
at java.base/java.lang.Thread.run(Thread.java:1623)
===============================================
java/net/httpclient/http2/IdleConnectionTimeoutTest.java
Total tests run: 1, Passes: 0, Failures: 1, Skips: 0
===============================================
----------System.err:(44/2287)----------
TestServer(1): accepting connections
Test run for jdk.httpclient.keepalive.timeout.h2=1
TestServer(1): connection accepted
TestServer(1): stopping is: false
TestServer(1): accepting connections
TestServer(1): creating connection
TestServer: New connection from Socket[addr=/127.0.0.1,port=43374,localport=40965]
TestServer(1): starting connection
TestServer: GET /serverTimeoutHandler
Server: creating input stream for stream 1
TestServer(1): connection started
TestServer(1): Using handler for: /serverTimeoutHandler
Sent response headers 200
Jan 27, 2023 11:30:00 AM jdk.internal.net.http.Http2Connection shutdown
INFO: ERROR: java.net.http.HttpConnectTimeoutException: HTTP connection idle, no active streams. Shutting down.
at java.net.http/jdk.internal.net.http.Http2Connection$IdleConnectionTimeoutEvent.handle(Http2Connection.java:213)
at java.net.http/jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1850)
at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:1459)
Server connection to /127.0.0.1:43374 stopping. 1 streams
TestServer: Connection writer stopping
TestServer(1): connection accepted
TestServer(1): stopping is: false
TestServer(1): accepting connections
TestServer(1): creating connection
TestServer: New connection from Socket[addr=/127.0.0.1,port=43374,localport=40965]
TestServer(1): starting connection
TestServer: GET /serverTimeoutHandler
Server: creating input stream for stream 1
TestServer(1): Using handler for: /serverTimeoutHandler
Sent response headers 400
TestServer(1): connection started
java.lang.Exception: failures: 1
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:95)
at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:53)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
at java.base/java.lang.reflect.Method.invoke(Method.java:578)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:125)
at java.base/java.lang.Thread.run(Thread.java:1623)
JavaTest Message: Test threw exception: java.lang.Exception: failures: 1
JavaTest Message: shutting down test
STATUS:Failed.`main' threw exception: java.lang.Exception: failures: 1
----------rerun:(55/11152)*----------