Bug ID: JDK-8240553 httpclient/whitebox/FlowTestDriver.java fails due to "SSLException: Tag mismatch!"

JDK-8240553 : httpclient/whitebox/FlowTestDriver.java fails due to "SSLException: Tag mismatch!"

Type: Bug
Component: core-libs
Sub-Component: java.net
Affected Version: 15

Priority: P3
Status: Resolved
Resolution: Duplicate
OS: linux
CPU: x86_64

Submitted: 2020-03-04
Updated: 2020-03-11
Resolved: 2020-03-11

Related Reports

Duplicate :	JDK-8240794 - [BACKOUT] 8238384 CTW: C2 compilation fails with "assert(store != load->find_exact_control(load->in(0))) failed: dependence cycle found"
Relates :	JDK-8240794 - [BACKOUT] 8238384 CTW: C2 compilation fails with "assert(store != load->find_exact_control(load->in(0))) failed: dependence cycle found"

Sub Tasks

JDK-8240754 :

Instrument FlowTest.java to provide more debug traces. - Resolved

Description

The following test fails in the JDK15 CI:

java/net/httpclient/whitebox/FlowTestDriver.java

Here's a snippet from the log file:

----------System.out:(91/5998)----------
Seed from AbstractRandomTest.getSeed = 7283647866038179423L
Monitor starting
clientReader: bufsize = 15896
serverLoopback: bufsize = 512
ALPN: proto2
AAALPN = proto2
Handshake took 484 ms
[TestNG] Running:
  java/net/httpclient/whitebox/FlowTestDriver.java

Submitting 3000 buffer arrays
LoopCount should be 2400000
Finished submission. Waiting for loopback
All bytes received: 
clientWriter close: 19287412 written
clientWriter close return
test jdk.internal.net.http.FlowTest.run(): failure
java.util.concurrent.CompletionException: javax.net.ssl.SSLException: Tag mismatch!
	at java.base/java.util.concurrent.CompletableFuture.reportJoin(CompletableFuture.java:412)
	at java.base/java.util.concurrent.CompletableFuture.join(CompletableFuture.java:2108)
	at java.net.http/jdk.internal.net.http.FlowTest.run(FlowTest.java:146)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
	at org.testng.internal.Invoker.invokeMethod(Invoker.java:639)
	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:821)
	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1131)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:124)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:108)
	at org.testng.TestRunner.privateRun(TestRunner.java:773)
	at org.testng.TestRunner.run(TestRunner.java:623)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:357)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:352)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:310)
	at org.testng.SuiteRunner.run(SuiteRunner.java:259)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1185)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1110)
	at org.testng.TestNG.run(TestNG.java:1018)
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:832)
Caused by: javax.net.ssl.SSLException: Tag mismatch!
	at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:133)
	at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:324)
	at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:267)
	at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:262)
	at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:121)
	at java.base/sun.security.ssl.SSLEngineImpl.decode(SSLEngineImpl.java:729)
	at java.base/sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:684)
	at java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:499)
	at java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:475)
	at java.base/javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:634)
	at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.unwrapBuffer(SSLFlowDelegate.java:529)
	at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:433)
	at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:268)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	... 1 more
Caused by: javax.crypto.AEADBadTagException: Tag mismatch!
	at java.base/com.sun.crypto.provider.GaloisCounterMode.decryptFinal(GaloisCounterMode.java:623)
	at java.base/com.sun.crypto.provider.CipherCore.finalNoPadding(CipherCore.java:1118)
	at java.base/com.sun.crypto.provider.CipherCore.fillOutputBuffer(CipherCore.java:1055)
	at java.base/com.sun.crypto.provider.CipherCore.doFinal(CipherCore.java:943)
	at java.base/com.sun.crypto.provider.AESCipher.engineDoFinal(AESCipher.java:491)
	at java.base/javax.crypto.CipherSpi.bufferCrypt(CipherSpi.java:794)
	at java.base/javax.crypto.CipherSpi.engineDoFinal(CipherSpi.java:730)
	at java.base/javax.crypto.Cipher.doFinal(Cipher.java:2502)
	at java.base/sun.security.ssl.SSLCipher$T12GcmReadCipherGenerator$GcmReadCipher.decrypt(SSLCipher.java:1656)
	at java.base/sun.security.ssl.SSLEngineInputRecord.decodeInputRecord(SSLEngineInputRecord.java:240)
	at java.base/sun.security.ssl.SSLEngineInputRecord.decode(SSLEngineInputRecord.java:197)
	at java.base/sun.security.ssl.SSLEngineInputRecord.decode(SSLEngineInputRecord.java:160)
	at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:109)
	... 14 more

===============================================
java/net/httpclient/whitebox/FlowTestDriver.java
Total tests run: 1, Failures: 1, Skips: 0
===============================================

----------System.err:(14/858)----------

Starting this as a P3 since this is a Tier2 failure.

Comments

Bugs should only be closed as "Fixed" when they are associated with a changeset.
11-03-2020
Fixed by JDK-8240794
11-03-2020
After instrumenting the test here is an interesting trace: It shows the failure happening on the server side in the SSLSocket returned by SSLServerSocket.accept(). For some reason JDK-8238384 is the root cause of this intermittent failure. ----------System.out:(40/1993)---------- Seed from AbstractRandomTest.getSeed = -7043641217607513552L Monitor starting [Thread[serverLoopback,5,MainThreadGroup]] [682ms 922330ns] serverLoopback: bufsize = 1000 [Thread[clientReader,5,MainThreadGroup]] [682ms 888980ns] clientReader: bufsize = 13776 [Thread[pool-1-thread-2,5,MainThreadGroup]] [1s 167ms 321160ns] ALPN: proto2 [Thread[pool-1-thread-2,5,MainThreadGroup]] [1s 173ms 421040ns] Handshake took 423 ms [Thread[MainThread,5,MainThreadGroup]] [1s 173ms 821460ns] AAALPN = proto2 [TestNG] Running: java/net/httpclient/whitebox/FlowTestDriver.java [Thread[MainThread,5,MainThreadGroup]] [1s 214ms 80920ns] Submitting 3000 buffer arrays [Thread[MainThread,5,MainThreadGroup]] [1s 214ms 431500ns] LoopCount should be 2400000 [Thread[serverLoopback,5,MainThreadGroup]] [3s 105ms 842590ns] serverLoopback failed: javax.net.ssl.SSLException: Tag mismatch! [Thread[clientWriter,5,MainThreadGroup]] [3s 106ms 28420ns] clientWriter failed: java.net.SocketException: Connection reset by peer [Thread[clientReader,5,MainThreadGroup]] [3s 106ms 693750ns] clientReader failed: java.net.SocketException: An established connection was aborted by the software in your host machine --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- --o-o-o-o-o-o-o-o-o-o-o-o-o-o- Timeout refired 480 times --o-o-o-o-o-o-o-o-o-o-o-o-o-o- ----------System.err:(44/3387)---------- javax.net.ssl.SSLException: Tag mismatch! at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:133) at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:324) at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:267) at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:262) at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:121) at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1465) at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1433) at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1022) at java.base/java.io.InputStream.read(InputStream.java:218) at java.net.http/jdk.internal.net.http.FlowTest$SSLLoopbackSubscriber.serverLoopback(FlowTest.java:332) at java.base/java.lang.Thread.run(Thread.java:832) Caused by: javax.crypto.AEADBadTagException: Tag mismatch! at java.base/com.sun.crypto.provider.GaloisCounterMode.decryptFinal(GaloisCounterMode.java:623) at java.base/com.sun.crypto.provider.CipherCore.finalNoPadding(CipherCore.java:1118) at java.base/com.sun.crypto.provider.CipherCore.fillOutputBuffer(CipherCore.java:1055) at java.base/com.sun.crypto.provider.CipherCore.doFinal(CipherCore.java:943) at java.base/com.sun.crypto.provider.AESCipher.engineDoFinal(AESCipher.java:491) at java.base/javax.crypto.CipherSpi.bufferCrypt(CipherSpi.java:794) at java.base/javax.crypto.CipherSpi.engineDoFinal(CipherSpi.java:730) at java.base/javax.crypto.Cipher.doFinal(Cipher.java:2502) at java.base/sun.security.ssl.SSLCipher$T12GcmReadCipherGenerator$GcmReadCipher.decrypt(SSLCipher.java:1656) at java.base/sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(SSLSocketInputRecord.java:262) at java.base/sun.security.ssl.SSLSocketInputRecord.decode(SSLSocketInputRecord.java:190) at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:109) ... 6 more java.net.SocketException: An established connection was aborted by the software in your host machine at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:325) at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350) at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803) at java.base/java.net.Socket$SocketInputStream.read(Socket.java:982) at java.base/java.io.InputStream.read(InputStream.java:218) at java.net.http/jdk.internal.net.http.FlowTest$SSLLoopbackSubscriber.clientReader(FlowTest.java:249) at java.base/java.lang.Thread.run(Thread.java:832) java.net.SocketException: Connection reset by peer at java.base/sun.nio.ch.NioSocketImpl.implWrite(NioSocketImpl.java:420) at java.base/sun.nio.ch.NioSocketImpl.write(NioSocketImpl.java:440) at java.base/sun.nio.ch.NioSocketImpl$2.write(NioSocketImpl.java:826) at java.base/java.net.Socket$SocketOutputStream.write(Socket.java:1052) at java.base/java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:81) at java.base/java.io.BufferedOutputStream.flush(BufferedOutputStream.java:142) at java.net.http/jdk.internal.net.http.FlowTest$SSLLoopbackSubscriber.writeToStream(FlowTest.java:312) at java.net.http/jdk.internal.net.http.FlowTest$SSLLoopbackSubscriber.clientWriter(FlowTest.java:293) at java.base/java.lang.Thread.run(Thread.java:832)
09-03-2020
I have experimented with some modification of FlowTest.java thinking that maybe there could be some race condition that JDK-8238384 had revealed. However the test is still intermittently failing. The issue is probably not in the test itself.
09-03-2020
The culprit seems to be this changeset: changeset 58254:1d4d4c9d03c2 8238384: CTW: C2 compilation fails with ��assert(store != load->find_exact_control(load->in(0))) failed: dependence cycle found�� Reviewed-by: vlivanov, thartmann How JDK-8238384 does affect things? I have no idea.
06-03-2020
This test has been stable for a very long time and is now failing relatively frequently. This might be linked to JDK-8233619 which was recently pushed. I am investigating to see if there's a link.
05-03-2020