JDK-8224829 : AsyncSSLSocketClose.java has timing issue
  • Type: Bug
  • Component: security-libs
  • Sub-Component: javax.net.ssl
  • Affected Version: 13
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • Submitted: 2019-05-27
  • Updated: 2023-07-24
  • Resolved: 2019-06-14
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 11 JDK 13 JDK 14 JDK 8
11.0.14Fixed 13 b26Fixed 14Fixed 8u271Fixed
Related Reports
Duplicate :  
Relates :  
Relates :  
Relates :  
Relates :  
Relates :  
Description
AsyncSSLSocketClose.java times out when being executed with -Xcomp and -XX:-TieredCompilation because execution is slower and as a result the client thread hits the OutputStream buffer limit before the server thread calls Socket.close(). The client thread blocks forever in os.write(ba).

The same behavior can be triggered by this change:
diff -r 987508afad96 test/jdk/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.java
--- a/test/jdk/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.java	Sun May 26 17:25:43 2019 -0700
+++ b/test/jdk/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.java	Mon May 27 12:23:56 2019 +0200
@@ -92,6 +92,7 @@
 
         socket.setSoLinger(true, 10);
         System.out.println("Calling Socket.close");
+        Thread.sleep(1000);
         socket.close();
         System.out.println("ssl socket get closed");
         System.out.flush();
 
I wonder if that is even expected behavior according to the spec?


----------messages:(150/9065)----------
command: main AsyncSSLSocketClose
reason: User specified action: run main/othervm AsyncSSLSocketClose 
Mode: othervm [/othervm specified]
Timeout information:
Running jstack on process 18825
2019-05-27 12:16:06
Full thread dump Java HotSpot(TM) 64-Bit Server VM (13-internal+0-adhoc.tobias.open compiled mode):

Threads class SMR info:
_java_thread_list=0x00007eff68002d50, length=11, elements={
0x00007effa4024000, 0x00007effa42e1000, 0x00007effa42e6800, 0x00007effa4319800,
0x00007effa431c000, 0x00007effa431e800, 0x00007effa43ad000, 0x00007effa452f000,
0x00007effa4580800, 0x00007eff50235000, 0x00007eff68001000
}
_java_thread_list_alloc_cnt=12, _java_thread_list_free_cnt=10, _java_thread_list_max=11, _nested_thread_list_max=1
_tlh_cnt=878, _tlh_times=1, avg_tlh_time=0.00, _tlh_time_max=1
_delete_lock_wait_cnt=0, _delete_lock_wait_max=0
_to_delete_list_cnt=0, _to_delete_list_max=1

"main" #1 prio=5 os_prio=0 cpu=1010.31ms elapsed=121.34s tid=0x00007effa4024000 nid=0x498c in Object.wait()  [0x00007effac455000]
   java.lang.Thread.State: WAITING (on object monitor)
Thread: 0x00007effa4024000  [0x498c] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base/Native Method)
	- waiting on <no object reference available>
	at java.lang.Thread.join(java.base/Thread.java:1303)
	- locked <0x0000000717902bf8> (a java.lang.Thread)
	at java.lang.Thread.join(java.base/Thread.java:1371)
	at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.81ms elapsed=121.28s tid=0x00007effa42e1000 nid=0x4993 waiting on condition  [0x00007eff943f0000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa42e1000  [0x4993] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ref.Reference.waitForReferencePendingList(java.base/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.29ms elapsed=121.28s tid=0x00007effa42e6800 nid=0x4994 in Object.wait()  [0x00007eff942ef000]
   java.lang.Thread.State: WAITING (on object monitor)
Thread: 0x00007effa42e6800  [0x4994] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base/Native Method)
	- waiting on <0x0000000717904168> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base/ReferenceQueue.java:155)
	- locked <0x0000000717904168> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.38ms elapsed=121.27s tid=0x00007effa4319800 nid=0x4995 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa4319800  [0x4995] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=50156.91ms elapsed=121.27s tid=0x00007effa431c000 nid=0x4996 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa431c000  [0x4996] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"Sweeper thread" #7 daemon prio=9 os_prio=0 cpu=1017.75ms elapsed=121.27s tid=0x00007effa431e800 nid=0x4997 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa431e800  [0x4997] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Common-Cleaner" #8 daemon prio=8 os_prio=0 cpu=1.24ms elapsed=120.23s tid=0x00007effa43ad000 nid=0x4998 in Object.wait()  [0x00007eff7ed7d000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
Thread: 0x00007effa43ad000  [0x4998] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base/Native Method)
	- waiting on <no object reference available>
	at java.lang.ref.ReferenceQueue.remove(java.base/ReferenceQueue.java:155)
	- locked <0x0000000717906ee8> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base/CleanerImpl.java:148)
	at java.lang.Thread.run(java.base/Thread.java:830)
	at jdk.internal.misc.InnocuousThread.run(java.base/InnocuousThread.java:134)

"Service Thread" #9 daemon prio=9 os_prio=0 cpu=13.07ms elapsed=106.18s tid=0x00007effa452f000 nid=0x49a0 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007effa452f000  [0x49a0] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"MainThread" #11 prio=5 os_prio=0 cpu=3022.36ms elapsed=103.32s tid=0x00007effa4580800 nid=0x49a2 waiting on condition  [0x00007eff7ea79000]
   java.lang.Thread.State: WAITING (parking)
Thread: 0x00007effa4580800  [0x49a2] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base/Native Method)
	- parking to wait for  <0x0000000709a2fb90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(java.base/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base/AbstractQueuedSynchronizer.java:885)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base/AbstractQueuedSynchronizer.java:917)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base/AbstractQueuedSynchronizer.java:1240)
	at java.util.concurrent.locks.ReentrantLock.lock(java.base/ReentrantLock.java:267)
	at sun.security.ssl.SSLSocketImpl.duplexCloseOutput(java.base/SSLSocketImpl.java:621)
	at sun.security.ssl.SSLSocketImpl.close(java.base/SSLSocketImpl.java:555)
	at AsyncSSLSocketClose.<init>(AsyncSSLSocketClose.java:95)
	at AsyncSSLSocketClose.main(AsyncSSLSocketClose.java:69)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base/NativeMethodAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base/Method.java:567)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.lang.Thread.run(java.base/Thread.java:830)

"Thread-1" #12 prio=5 os_prio=0 cpu=1587.97ms elapsed=81.27s tid=0x00007eff50235000 nid=0x49ae runnable  [0x00007eff7df1d000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007eff50235000  [0x49ae] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_in_native
	at java.net.SocketOutputStream.socketWrite0(java.base/Native Method)
	at java.net.SocketOutputStream.socketWrite(java.base/SocketOutputStream.java:108)
	at java.net.SocketOutputStream.write(java.base/SocketOutputStream.java:148)
	at java.net.Socket$SocketOutputStream.write(java.base/Socket.java:980)
	at sun.security.ssl.SSLSocketOutputRecord.deliver(java.base/SSLSocketOutputRecord.java:342)
	at sun.security.ssl.SSLSocketImpl$AppOutputStream.write(java.base/SSLSocketImpl.java:1181)
	at java.io.OutputStream.write(java.base/OutputStream.java:122)
	at AsyncSSLSocketClose.run(AsyncSSLSocketClose.java:124)
	at java.lang.Thread.run(java.base/Thread.java:830)

"Attach Listener" #13 daemon prio=9 os_prio=0 cpu=0.47ms elapsed=0.10s tid=0x00007eff68001000 nid=0x49f5 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
Thread: 0x00007eff68001000  [0x49f5] State: _at_safepoint _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"VM Thread" os_prio=0 cpu=35.21ms elapsed=121.29s tid=0x00007effa42c7000 nid=0x4992 runnable  

"GC Thread#0" os_prio=0 cpu=19.58ms elapsed=121.33s tid=0x00007effa4092000 nid=0x498d runnable  

"GC Thread#1" os_prio=0 cpu=9.44ms elapsed=65.80s tid=0x00007eff78001000 nid=0x49b2 runnable  

"GC Thread#2" os_prio=0 cpu=8.76ms elapsed=65.80s tid=0x00007eff78002800 nid=0x49b3 runnable  

"GC Thread#3" os_prio=0 cpu=9.41ms elapsed=65.80s tid=0x00007eff78004800 nid=0x49b4 runnable  

"GC Thread#4" os_prio=0 cpu=8.59ms elapsed=65.80s tid=0x00007eff78006800 nid=0x49b5 runnable  

"GC Thread#5" os_prio=0 cpu=12.28ms elapsed=65.80s tid=0x00007eff78008800 nid=0x49b6 runnable  

"G1 Main Marker" os_prio=0 cpu=0.12ms elapsed=121.33s tid=0x00007effa40ab800 nid=0x498e runnable  

"G1 Conc#0" os_prio=0 cpu=0.04ms elapsed=121.33s tid=0x00007effa40ad800 nid=0x498f runnable  

"G1 Refine#0" os_prio=0 cpu=0.18ms elapsed=121.33s tid=0x00007effa41d3000 nid=0x4990 runnable  

"G1 Young RemSet Sampling" os_prio=0 cpu=27.51ms elapsed=121.33s tid=0x00007effa41d5000 nid=0x4991 runnable  
"VM Periodic Task Thread" os_prio=0 cpu=118.90ms elapsed=106.01s tid=0x00007effa4532800 nid=0x49a1 waiting on condition  

JNI global refs: 16, weak refs: 0

--- Timeout information end.
elapsed time (seconds): 121.516
----------configuration:(0/0)----------
----------System.out:(9209/228061)----------
1024 bytes to be written
1024 bytes written
2048 bytes to be written
2048 bytes written
3072 bytes to be written
3072 bytes written
4096 bytes to be written
4096 bytes written
5120 bytes to be written
5120 bytes written
6144 bytes to be written
6144 bytes written
7168 bytes to be written
7168 bytes written
8192 bytes to be written
8192 bytes written
9216 bytes to be written
9216 bytes written
10240 bytes to be written
10240 bytes written
11264 bytes to be written
11264 bytes written
12288 bytes to be written
12288 bytes written
13312 bytes to be written
13312 bytes written

[...]

4714496 bytes to be written
Calling Socket.close
Timeout refired 120 times
----------System.err:(0/0)----------
----------rerun:(25/1532)*----------
cd /oracle/jdk_jdk/JTwork/scratch && \\
DISPLAY=:0 \\
GNOME_DESKTOP_SESSION_ID=this-is-deprecated \\
HOME=/home/tobias \\
LANG=en_US.UTF-8 \\
LD_LIBRARY_PATH=/oracle/documents/misc/ \\
PATH=/bin:/usr/bin \\
XMODIFIERS=@im=ibus \\
CLASSPATH=/oracle/jdk_jdk/JTwork/classes/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.d:/oracle/jdk_jdk/open/test/jdk/sun/security/ssl/SSLSocketImpl:/home/tobias/programs/jtreg/lib/javatest.jar:/home/tobias/programs/jtreg/lib/jtreg.jar \\
    /oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk/bin/java \\
        -Dtest.src=/oracle/jdk_jdk/open/test/jdk/sun/security/ssl/SSLSocketImpl \\
        -Dtest.src.path=/oracle/jdk_jdk/open/test/jdk/sun/security/ssl/SSLSocketImpl \\
        -Dtest.classes=/oracle/jdk_jdk/JTwork/classes/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.d \\
        -Dtest.class.path=/oracle/jdk_jdk/JTwork/classes/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.d \\
        -Dtest.vm.opts= \\
        -Dtest.tool.vm.opts= \\
        -Dtest.compiler.opts= \\
        -Dtest.java.opts='-XX:-TieredCompilation -Xcomp' \\
        -Dtest.jdk=/oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk \\
        -Dcompile.jdk=/oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk \\
        -Dtest.timeout.factor=1.0 \\
        -Dtest.root=/oracle/jdk_jdk/open/test/jdk \\
        -XX:-TieredCompilation \\
        -Xcomp \\
        com.sun.javatest.regtest.agent.MainWrapper /oracle/jdk_jdk/JTwork/sun/security/ssl/SSLSocketImpl/AsyncSSLSocketClose.d/main.0.jta
result: Error. Program `/oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk/bin/java' timed out (timeout set to 120000ms, elapsed time including timeout handling was 121513ms).

test result: Error. Program `/oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk/bin/java' timed out (timeout set to 120000ms, elapsed time including timeout handling was 121513ms).
Comments
Fix request [11u]: Request to backport this bugfix for Oracle parity (they already did it in 11.0.9). I think the fix is viable and important, however there is a small risk. The backport brings in changes from JDK-8221882 to use a new way of locking records via ReentrantLock. There is a chance I missed some place of synchronization where the new recordLock should be used. However, with potential further backports in that area I think it's better to be more close with the code to head. Testing shows no regressions, PR acked by mdoerr.
04-10-2021

Removed noreg label as the fix has JDK source code change and a test associated for it.
08-03-2021

URL: http://hg.openjdk.java.net/jdk/jdk13/rev/328d4a455e4b User: xuelei Date: 2019-06-14 19:19:35 +0000
14-06-2019

Could be caused by JDK-8221882, assigning to @xuelei to triage.
30-05-2019

SSLSocketBruceForceClose.java seems to have a similar timing issue: jtreg -jdk:/oracle/jdk_jdk/build/linux-x86_64-server-fastdebug/jdk/ -va -javaoptions:"-XX:-TieredCompilation -Xcomp" -J-Djavatest.maxOputSize=10000000 open/test/jdk/sun/security/ssl/SSLSocketImpl/SSLSocketBruceForceClose.java STDOUT: STDERR: =================================== loop 0 =================================== Starting client Accepting client requests Connecting to server at port 32905 Reading data from client Sending data to server ... client socket closed javax.net.ssl.SSLException: readHandshakeRecord at java.base/sun.security.ssl.SSLSocketImpl.readHandshakeRecord(SSLSocketImpl.java:1300) at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:436) at java.base/sun.security.ssl.SSLSocketImpl.ensureNegotiated(SSLSocketImpl.java:806) at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:897) at java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:297) at java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:339) at java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:188) at java.base/java.io.InputStreamReader.read(InputStreamReader.java:185) at java.base/java.io.BufferedReader.fill(BufferedReader.java:161) at java.base/java.io.BufferedReader.readLine(BufferedReader.java:326) at java.base/java.io.BufferedReader.readLine(BufferedReader.java:392) at SSLSocketBruceForceClose.test(SSLSocketBruceForceClose.java:76) at SSLSocketBruceForceClose.main(SSLSocketBruceForceClose.java:48) 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:567) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.base/java.lang.Thread.run(Thread.java:830) Suppressed: java.net.SocketException: Broken pipe (Write failed) at java.base/java.net.SocketOutputStream.socketWrite0(Native Method) at java.base/java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:108) at java.base/java.net.SocketOutputStream.write(SocketOutputStream.java:148) at java.base/java.net.Socket$SocketOutputStream.write(Socket.java:980) at java.base/sun.security.ssl.SSLSocketOutputRecord.encodeAlert(SSLSocketOutputRecord.java:82) at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:351) at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:263) at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:439) ... 17 more Caused by: java.net.SocketException: Connection reset by peer (Write failed) at java.base/java.net.SocketOutputStream.socketWrite0(Native Method) at java.base/java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:108) at java.base/java.net.SocketOutputStream.write(SocketOutputStream.java:148) at java.base/java.net.Socket$SocketOutputStream.write(Socket.java:980) at java.base/sun.security.ssl.SSLSocketOutputRecord.flush(SSLSocketOutputRecord.java:268) at java.base/sun.security.ssl.HandshakeOutStream.flush(HandshakeOutStream.java:89) at java.base/sun.security.ssl.CertificateMessage$T13CertificateProducer.onProduceCertificate(CertificateMessage.java:1006) at java.base/sun.security.ssl.CertificateMessage$T13CertificateProducer.produce(CertificateMessage.java:940) at java.base/sun.security.ssl.SSLHandshake.produce(SSLHandshake.java:436) at java.base/sun.security.ssl.ClientHello$T13ClientHelloConsumer.goServerHello(ClientHello.java:1225) at java.base/sun.security.ssl.ClientHello$T13ClientHelloConsumer.consume(ClientHello.java:1161) at java.base/sun.security.ssl.ClientHello$ClientHelloConsumer.onClientHello(ClientHello.java:852) at java.base/sun.security.ssl.ClientHello$ClientHelloConsumer.consume(ClientHello.java:813) at java.base/sun.security.ssl.SSLHandshake.consume(SSLHandshake.java:392) at java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:443) at java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:421) at java.base/sun.security.ssl.TransportContext.dispatch(TransportContext.java:177) at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:164) at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1383) at java.base/sun.security.ssl.SSLSocketImpl.readHandshakeRecord(SSLSocketImpl.java:1291) ... 18 more JavaTest Message: Test threw exception: javax.net.ssl.SSLException: readHandshakeRecord JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: javax.net.ssl.SSLException: readHandshakeRecord
27-05-2019