JDK-8157482 : java/net/httpclient/http2/TLSConnection.java fails intermittently
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.net
  • Affected Version: 9
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • Submitted: 2016-05-20
  • Updated: 2016-12-15
  • Resolved: 2016-12-12
Related Reports
Duplicate :  
JDK-8160033 - java/net/httpclient/http2/TLSConnection.java.TLSConnection failed with SSLException
Duplicate :  
JDK-8170648 - Move java.net.http package out of Java SE to incubator namespace
Duplicate :  
JDK-8160830 - java/net/httpclient/http2/TLSConnection.java failed: java.io.IOException: Engine closed
Relates :  
JDK-8160502 - Problem listing of several http2 tests
Description
The test fails intermittently with different errors. See comments for details.
Comments
At the moment, HTTP/2 implementation doesn't seem to be stable. Looks like the implementation is being updated in http-client-branch of http://hg.openjdk.java.net/jdk9/sandbox/ , see JDK-8156974. It may be better to wait for all updates go to jdk9/dev, and then investigate these intermittent failures.
25-08-2016
There is another exception which has been observed: javax.net.ssl.SSLProtocolException: ChangeCipherSpec message sequence violation at sun.security.ssl.HandshakeStateManager.changeCipherSpec(java.base@9-ea/HandshakeStateManager.java:891) at sun.security.ssl.Handshaker.receiveChangeCipherSpec(java.base@9-ea/Handshaker.java:1137) at sun.security.ssl.SSLSocketImpl.processInputRecord(java.base@9-ea/SSLSocketImpl.java:1226) at sun.security.ssl.SSLSocketImpl.readRecord(java.base@9-ea/SSLSocketImpl.java:1069) at sun.security.ssl.SSLSocketImpl.readRecord(java.base@9-ea/SSLSocketImpl.java:968) at sun.security.ssl.SSLSocketImpl.performInitialHandshake(java.base@9-ea/SSLSocketImpl.java:1395) at sun.security.ssl.SSLSocketImpl.bytesInCompletePacket(java.base@9-ea/SSLSocketImpl.java:902) at sun.security.ssl.AppInputStream.read(java.base@9-ea/AppInputStream.java:144) at java.io.BufferedInputStream.fill(java.base@9-ea/BufferedInputStream.java:246) at java.io.BufferedInputStream.read1(java.base@9-ea/BufferedInputStream.java:286) at java.io.BufferedInputStream.read(java.base@9-ea/BufferedInputStream.java:345) at java.io.InputStream.readNBytes(java.base@9-ea/InputStream.java:309) at java.net.http.Http2TestServerConnection.readPreface(java.httpclient@9-ea/Http2TestServerConnection.java:104) at java.net.http.Http2TestServerConnection.run(java.httpclient@9-ea/Http2TestServerConnection.java:158) at java.net.http.Http2TestServer.lambda$start$1(java.httpclient@9-ea/Http2TestServer.java:148) at java.util.concurrent.Executors$RunnableAdapter.call(java.base@9-ea/Executors.java:514) at java.util.concurrent.FutureTask.run(java.base@9-ea/FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@9-ea/ThreadPoolExecutor.java:1158) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@9-ea/ThreadPoolExecutor.java:632) at java.lang.Thread.run(java.base@9-ea/Thread.java:843)
24-06-2016
I am not sure these failures are caused by any issue in the test. I suspect that there is some issue in HTTP2 implementation. It starts handshaking in a separate threads (the impl is multi-threaded in general), so I suspect that something gets out of sync. This needs some time to investigate. Please add the test to the problem list if you think it is necessary.
24-06-2016
Mach5 failures: http://java.se.oracle.com/mach5/job/9-dev/701/artifact/testresults/linux-x86/tier2/JTwork/jdk_test/java/net/httpclient/http2/TLSConnection.jtr/*view*/ http://java.se.oracle.com/mach5/job/9-dev/718/artifact/testresults/macosx-x64/tier2/JTwork/jdk_test/java/net/httpclient/http2/TLSConnection.jtr/*view*/ http://java.se.oracle.com/mach5/job/9-dev/719/artifact/testresults/macosx-x64/tier2/JTwork/jdk_test/java/net/httpclient/http2/TLSConnection.jtr/*view*/ http://java.se.oracle.com/mach5/job/9-dev/712/artifact/testresults/macosx-x64/tier2/JTwork/jdk_test/java/net/httpclient/http2/TLSConnection.jtr/*view*/ The test fails frequently in Mach5, please try to fix it ASAP.
24-06-2016
At the moment I see two different issues. 1. Unexpected handshaking message on server side (exceptions may be different). HTTP/2 client does TLS handshaking in a separate thread, see src/java.httpclient/share/classes/java/net/http/AsyncSSLDelegate.java for details. Unexpected handshake error may occur if HTTP/2 client tries to send application data before handshaking has finished. This may happen due to lack of synchronization. Needs more investigation. http://hg.openjdk.java.net/jdk9/dev/jdk/file/26cb3ae62fd3/src/java.httpclient/share/classes/java/net/http/AsyncSSLDelegate.java 2. No SSL session available after client and server finished the connection. Needs more investigation.
15-06-2016
The test also may fails with the following exception: May 24, 2016 2:59:40 PM java.net.http.Http2Connection <init> INFO: TRACE: Connection send window size 65535 May 24, 2016 2:59:40 PM java.net.http.AsyncSSLDelegate logParams INFO: SSL: SSLParameters: May 24, 2016 2:59:40 PM java.net.http.AsyncSSLDelegate logParams INFO: SSL: application protocol: h2 New connection from 49d3cb05[SSL_NULL_WITH_NULL_NULL: Socket[addr=/127.0.0.1,port=59289,localport=59286]] May 24, 2016 2:59:40 PM java.net.http.Http2Connection sendConnectionPreface INFO: FRAME: OUT: SETTINGS: length=30, streamid=0, flags=0 Settings: HEADER_TABLE_SIZE=16384 ENABLE_PUSH=1 MAX_CONCURRENT_STREAMS=16 INITIAL_WINDOW_SIZE=32768 MAX_FRAME_SIZE=16384 May 24, 2016 2:59:40 PM java.net.http.Http2Connection sendConnectionPreface INFO: FRAME: OUT: WINDOW_UPDATE: length=4, streamid=0, flags=0 WindowUpdate: 196609 May 24, 2016 2:59:40 PM java.net.http.Stream sendHeadersOnly INFO: REQUEST: https://127.0.0.1:59286 GET May 24, 2016 2:59:40 PM java.net.http.Http2Connection sendOneFrame INFO: FRAME: OUT: HEADERS: length=22, streamid=1, flags=END_HEADERS TestServer: start exception: javax.net.ssl.SSLProtocolException: ChangeCipherSpec message sequence violation javax.net.ssl.SSLProtocolException: ChangeCipherSpec message sequence violation at sun.security.ssl.HandshakeStateManager.changeCipherSpec(java.base@9-ea/HandshakeStateManager.java:891) at sun.security.ssl.Handshaker.receiveChangeCipherSpec(java.base@9-ea/Handshaker.java:1137) at sun.security.ssl.SSLSocketImpl.processInputRecord(java.base@9-ea/SSLSocketImpl.java:1224) at sun.security.ssl.SSLSocketImpl.readRecord(java.base@9-ea/SSLSocketImpl.java:1067) at sun.security.ssl.SSLSocketImpl.readRecord(java.base@9-ea/SSLSocketImpl.java:966) at sun.security.ssl.SSLSocketImpl.performInitialHandshake(java.base@9-ea/SSLSocketImpl.java:1393) at sun.security.ssl.SSLSocketImpl.bytesInCompletePacket(java.base@9-ea/SSLSocketImpl.java:900) at sun.security.ssl.AppInputStream.read(java.base@9-ea/AppInputStream.java:144) at java.io.BufferedInputStream.fill(java.base@9-ea/BufferedInputStream.java:246) at java.io.BufferedInputStream.read1(java.base@9-ea/BufferedInputStream.java:286) at java.io.BufferedInputStream.read(java.base@9-ea/BufferedInputStream.java:345) at java.io.InputStream.readNBytes(java.base@9-ea/InputStream.java:309) at java.net.http.Http2TestServerConnection.readPreface(java.httpclient@9-ea/Http2TestServerConnection.java:104) at java.net.http.Http2TestServerConnection.run(java.httpclient@9-ea/Http2TestServerConnection.java:158) at java.net.http.Http2TestServer.lambda$start$1(java.httpclient@9-ea/Http2TestServer.java:148) at java.util.concurrent.Executors$RunnableAdapter.call(java.base@9-ea/Executors.java:514) at java.util.concurrent.FutureTask.run(java.base@9-ea/FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@9-ea/ThreadPoolExecutor.java:1158) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@9-ea/ThreadPoolExecutor.java:632) at java.lang.Thread.run(java.base@9-ea/Thread.java:843) May 24, 2016 2:59:40 PM java.net.http.Http2Connection sendOneFrame INFO: FRAME: OUT: DATA: length=4, streamid=1, flags=END_STREAM May 24, 2016 2:59:40 PM java.net.http.PlainHttpConnection close INFO: ERROR: Closing: PlainHttpConnection: HttpConnection: java.nio.channels.SocketChannel[connected local=/127.0.0.1:59289 remote=/127.0.0.1:59286] May 24, 2016 2:59:40 PM java.net.http.Http2Connection shutdown INFO: ERROR: java.io.IOException: Connection aborted at java.net.http.PlainHttpConnection.shutdown(java.httpclient@9-ea/PlainHttpConnection.java:231) at java.net.http.PlainHttpConnection.asyncRead(java.httpclient@9-ea/PlainHttpConnection.java:252) at java.net.http.PlainHttpConnection$ReadEvent.handle(java.httpclient@9-ea/PlainHttpConnection.java:332) at java.net.http.HttpClientImpl$SelectorManager.handleEvent(java.httpclient@9-ea/HttpClientImpl.java:331) at java.net.http.HttpClientImpl$SelectorManager.run(java.httpclient@9-ea/HttpClientImpl.java:301)
24-05-2016
"Check protocol: no session provided" error may occur. Test #2: default SSL parameters, expect successful connection method = GET path = scheme = https authority = 127.0.0.1:41356 Handler: received request to https://127.0.0.1:41356 Handler: read 4 bytes of body: body Response: Test response Passed Check protocol: no session provided It means that no SSL session was available even if HTTP/2 connection over TLS succeeded.
20-05-2016
The following exception may occur on client side: ew connection from 3633ed4d[SSL_NULL_WITH_NULL_NULL: Socket[addr=/127.0.0.1,port=35025,localport=55641]] May 20, 2016 12:48:29 PM java.net.http.Http2Connection sendConnectionPreface INFO: FRAME: OUT: SETTINGS: length=30, streamid=0, flags=0 Settings: HEADER_TABLE_SIZE=16384 ENABLE_PUSH=1 MAX_CONCURRENT_STREAMS=16 INITIAL_WINDOW_SIZE=32768 MAX_FRAME_SIZE=16384 May 20, 2016 12:48:29 PM java.net.http.Http2Connection sendConnectionPreface INFO: FRAME: OUT: WINDOW_UPDATE: length=4, streamid=0, flags=0 WindowUpdate: 196609 May 20, 2016 12:48:29 PM java.net.http.Stream sendHeadersOnly INFO: REQUEST: https://127.0.0.1:55641 GET May 20, 2016 12:48:29 PM java.net.http.Http2Connection sendOneFrame INFO: FRAME: OUT: HEADERS: length=22, streamid=1, flags=END_HEADERS May 20, 2016 12:48:29 PM java.net.http.Http2Connection sendOneFrame INFO: FRAME: OUT: DATA: length=4, streamid=1, flags=END_STREAM javax.net.ssl.SSLException: Received fatal alert: unexpected_message at sun.security.ssl.Alerts.getSSLException(java.base@9-internal/Alerts.java:214) at sun.security.ssl.SSLEngineImpl.fatal(java.base@9-internal/SSLEngineImpl.java:1711) at sun.security.ssl.SSLEngineImpl.fatal(java.base@9-internal/SSLEngineImpl.java:1679) at sun.security.ssl.SSLEngineImpl.recvAlert(java.base@9-internal/SSLEngineImpl.java:1852) at sun.security.ssl.SSLEngineImpl.processInputRecord(java.base@9-internal/SSLEngineImpl.java:1118) at sun.security.ssl.SSLEngineImpl.readRecord(java.base@9-internal/SSLEngineImpl.java:998) at sun.security.ssl.SSLEngineImpl.readNetRecord(java.base@9-internal/SSLEngineImpl.java:895) at sun.security.ssl.SSLEngineImpl.unwrap(java.base@9-internal/SSLEngineImpl.java:673) at javax.net.ssl.SSLEngine.unwrap(java.base@9-internal/SSLEngine.java:624) at java.net.http.AsyncSSLDelegate.unwrapBuffer(java.httpclient@9-internal/AsyncSSLDelegate.java:422) at java.net.http.AsyncSSLDelegate.handshakeReceiveAndUnWrap(java.httpclient@9-internal/AsyncSSLDelegate.java:368) at java.net.http.AsyncSSLDelegate.doHandshakeImpl(java.httpclient@9-internal/AsyncSSLDelegate.java:272) at java.net.http.AsyncSSLDelegate.lambda$doHandshake$0(java.httpclient@9-internal/AsyncSSLDelegate.java:230) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@9-internal/ThreadPoolExecutor.java:1158) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@9-internal/ThreadPoolExecutor.java:632) at java.lang.Thread.run(java.base@9-internal/Thread.java:843) TestServer: start exception: javax.net.ssl.SSLProtocolException: Expected to get a handshake fragment javax.net.ssl.SSLProtocolException: Expected to get a handshake fragment at sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(java.base@9-internal/SSLSocketInputRecord.java:247) at sun.security.ssl.SSLSocketInputRecord.decode(java.base@9-internal/SSLSocketInputRecord.java:178) at sun.security.ssl.SSLSocketImpl.readRecord(java.base@9-internal/SSLSocketImpl.java:1024) at sun.security.ssl.SSLSocketImpl.readRecord(java.base@9-internal/SSLSocketImpl.java:966) at sun.security.ssl.SSLSocketImpl.performInitialHandshake(java.base@9-internal/SSLSocketImpl.java:1393) at sun.security.ssl.SSLSocketImpl.bytesInCompletePacket(java.base@9-internal/SSLSocketImpl.java:900) at sun.security.ssl.AppInputStream.read(java.base@9-internal/AppInputStream.java:144) at java.io.BufferedInputStream.fill(java.base@9-internal/BufferedInputStream.java:246) at java.io.BufferedInputStream.read1(java.base@9-internal/BufferedInputStream.java:286) at java.io.BufferedInputStream.read(java.base@9-internal/BufferedInputStream.java:345) at java.io.InputStream.readNBytes(java.base@9-internal/InputStream.java:309) at java.net.http.Http2TestServerConnection.readPreface(java.httpclient@9-internal/Http2TestServerConnection.java:104) at java.net.http.Http2TestServerConnection.run(java.httpclient@9-internal/Http2TestServerConnection.java:158) at java.net.http.Http2TestServer.lambda$start$1(java.httpclient@9-internal/Http2TestServer.java:148) at java.util.concurrent.Executors$RunnableAdapter.call(java.base@9-internal/Executors.java:514) at java.util.concurrent.FutureTask.run(java.base@9-internal/FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@9-internal/ThreadPoolExecutor.java:1158) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@9-internal/ThreadPoolExecutor.java:632) at java.lang.Thread.run(java.base@9-internal/Thread.java:843) Closing java.net.http.Queue@561385b8 May 20, 2016 12:48:29 PM java.net.http.PlainHttpConnection close INFO: ERROR: Closing: PlainHttpConnection: HttpConnection: java.nio.channels.SocketChannel[connected local=/127.0.0.1:35025 remote=/127.0.0.1:55641] Closing java.net.http.Queue@43b51811 Closing PlainHttpConnection: HttpConnection: java.nio.channels.SocketChannel[closed] Shutdown: java.io.IOException: Connection aborted java.io.IOException: Connection aborted at java.net.http.PlainHttpConnection.shutdown(java.httpclient@9-internal/PlainHttpConnection.java:231) at java.net.http.PlainHttpConnection.asyncRead(java.httpclient@9-internal/PlainHttpConnection.java:252) at java.net.http.PlainHttpConnection$ReadEvent.handle(java.httpclient@9-internal/PlainHttpConnection.java:332) at java.net.http.HttpClientImpl$SelectorManager.handleEvent(java.httpclient@9-internal/HttpClientImpl.java:331) at java.net.http.HttpClientImpl$SelectorManager.run(java.httpclient@9-internal/HttpClientImpl.java:301) May 20, 2016 12:48:29 PM java.net.http.Stream cancelImpl INFO: TRACE: cancelling stream: java.io.IOException: Connection aborted May 20, 2016 12:48:29 PM java.net.http.Http2Connection resetStream INFO: ERROR: Resetting stream 1 with error code 8 May 20, 2016 12:48:29 PM java.net.http.Http2Connection sendOneFrame INFO: FRAME: OUT: RESET: length=4, streamid=1, flags=0 Error: Stream cancelled Closing java.net.http.AsyncSSLDelegate@22f700fb Closing java.net.http.Queue@561385b8 Closing java.net.http.Queue@43b51811 Closing PlainHttpConnection: HttpConnection: java.nio.channels.SocketChannel[closed] Closing java.nio.channels.SocketChannel[closed] The test fails with timeout in this case.
20-05-2016