JDK-8059588 : deadlock in java/io/PrintStream when verbose java.security.debug flags are set
  • Type: Bug
  • Component: security-libs
  • Sub-Component: javax.net.ssl
  • Affected Version: 7u51
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • Submitted: 2014-10-02
  • Updated: 2016-06-13
  • Resolved: 2015-03-27
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 7 JDK 8 JDK 9
7u91Fixed 8u60Fixed 9 b59Fixed
Description
User heavy load of 1000 HTTPS threads WebLogic 12.1.1 managed server running 
with full debug logging jstack reports: 

Deadlock Detection: 

Found one Java-level deadlock: 
============================= 

"[STUCK] ExecuteThread: '2' for queue: 'weblogic.kernel.Default 
(self-tuning)'": 
  waiting to lock Monitor@0x000000010521cfe8 (Object@0x00000006065d4320, a 
java/io/PrintStream), 
  which is held by "[ACTIVE] ExecuteThread: '4' for queue: 
'weblogic.kernel.Default (self-tuning) 
'" 
"[ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default 
(self-tuning)'": 
  waiting to lock Monitor@0x0000000105219418 (Object@0x0000000606664aa8, a 
sun/security/pkcs11/Se 
ssionManager), 
  which is held by "[STUCK] ExecuteThread: '2' for queue: 
'weblogic.kernel.Default (self-tuning)' 
" 

Found a total of 1 deadlock. 

----------------- t@1 ----------------- 
0xffffffff7eae75fc      __lwp_wait + 0x4 
0xffffffff7eade8d4      _thrp_join + 0x3c 
0xffffffff7eadea40      thr_join + 0x14 
0xffffffff75513408      ContinueInNewThread0 + 0x30 
0xffffffff7550617c      ContinueInNewThread + 0x94 
0xffffffff75513484      JVMInit + 0x28 
0xffffffff75501c70      JLI_Launch + 0x2d0 
0x0000000100000a00      main + 0x90 
0x000000010000093c      _start + 0x17c 
----------------- t@2 ----------------- 
0xffffffff7eae76b0      ___lwp_cond_wait + 0x4 
0xffffffff74df2b00      void os::PlatformEvent::park() + 0x100 
0xffffffff74dd2944      void ObjectMonitor::wait(long,bool,Thread*) + 0x32c 
0xffffffff74eff338      void ObjectSynchronizer::wait(Handle,long,Thread*) + 
0x160 
0xffffffff745b3794      JVM_MonitorWait + 0x2d0 
0xffffffff70410d6c      <interpreter> method entry point (kind = native) 
0xffffffff70410d10      <interpreter> method entry point (kind = native) 
0xffffffff70406f44      <interpreter> return entry points 
0xffffffff70406f44      <interpreter> return entry points 
0xffffffff70406f44      <interpreter> return entry points 
0xffffffff70406cb4      <interpreter> return entry points 
0xffffffff7040024c      <StubRoutines> 
0xffffffff74524700      void 
JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,T 
hread*) + 0x2a0 
0xffffffff74531a14      void 
JavaCalls::call(JavaValue*,methodHandle,JavaCallArguments*,Thread*) 
+ 0x3c 
0xffffffff745cf20c      jni_CallStaticVoidMethod + 0x630 
0xffffffff755023ec      JavaMain + 0x74c 
0xffffffff7eae2694      _lwp_start 
Locked ownable synchronizers: 
    - None 
----------------- t@3 ----------------- 
0xffffffff7eae76b0      ___lwp_cond_wait + 0x4 
0xffffffff74df2b00      void os::PlatformEvent::park() + 0x100 
0xffffffff74da0ebc      int Monitor::IWait(Thread*,long) + 0xa4 
0xffffffff74da1dd0      bool Monitor::wait(bool,long,bool) + 0x350 
0xffffffff745231f8      GCTask*GCTaskManager::get_task(unsigned) + 0xa8 
0xffffffff7461e598      void GCTaskThread::run() + 0x200 
0xffffffff74de765c      java_start + 0x35c 
0xffffffff7eae2694      _lwp_start 
----------------- t@4 ----------------- 
0xffffffff7eae76b0      ___lwp_cond_wait + 0x4 
0xffffffff74df2b00      void os::PlatformEvent::park() + 0x100 
0xffffffff74da0ebc      int Monitor::IWait(Thread*,long) + 0xa4 
0xffffffff74da1dd0      bool Monitor::wait(bool,long,bool) + 0x350 
0xffffffff745231f8      GCTask*GCTaskManager::get_task(unsigned) + 0xa8 
0xffffffff7461e598      void GCTaskThread::run() + 0x200 
0xffffffff74de765c      java_start + 0x35c 
0xffffffff7eae2694      _lwp_start 


The error does not occur if the debug options are off or if the SunPKCS11 
provider is removed from java.security. 

JAVA_OPTIONS="${SAVE_JAVA_OPTIONS} 
-Dweblogic.security.SSL.ignoreHostnameVerification=true -Dweblogic.nodem 
anager.sslHostNameVerificationEnabled=false   
-Dweblogic.security.SSL.enforceConstraints=off  -Dssl.debug=true 
-Dweblogic.StdoutDebugEnabled=true 
-Djavax.net.debug=ssl,handshake,record,keygen,session,defaultctx,sslctx,ses 
sioncache,keymanager,trustmanager -Dcom.oracle.security.ucrypto.debug=true   
-Djava.security.debug=all -Djsse.S 
SLEngine.acceptLargeFragments=true -Dweblogic.ssl.JSSEEnabled=true   
-Dweblogic.management.allowPasswordEcho=tr 
ue" 
 
Hang always occurs after this info is printed by verbose logging in JDK : 
==== 
Server write IV: 
0000: 8B DF 9B 59 E3 E5 3C 59                            ...Y..<Y 
Generating a random fake premaster secret 
[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default 
(self-tuning)', WRITE: TLSv1 Change Cipher Spec, length = 1 
CONNECTION KEYGEN: 
Client Nonce: 
0000: 54 1C 81 96 90 75 72 F8   38 72 56 BA 31 BB 1F 12  T....ur.8rV.1... 
0010: 9F D9 80 B0 3F 79 57 14   ED D3 80 AE 77 8D 36 1D  ....?yW.....w.6. 
Server Nonce: 
0000: 54 1C 81 9E 20 13 2A 9A   A7 A6 B9 FD 2A 14 3C 92  T... .*.....*.<. 
0010: B5 E2 65 11 D8 6E BB 6D   18 D2 DC 9E 9E 0F 26 33  ..e..n.m......&3 
Master Secret: 
 
==== 
# At this point the WLS managed server is hung. 

I suspect the "synchronized (System.out)" code found in 
sun/security/ssl/Handshaker.java is not good to have. 
Comments
I think I've traced the offending code to sun/security/pkcs11/SessionManager.java. There aren't too many places where we synchronize on the SessionManager Object. synchronized(this) { if (activeSessions.get() > maxActiveSessions) { maxActiveSessions = activeSessions.get(); if (maxActiveSessions % 10 == 0) { System.out.println("Open sessions: " + maxActiveSessions); } } } Thread A is running through above code. Meanwhile Thread B is in sun/security/ssl/Handshaker.java running through this code (we know the hang happens after printing "Master Secret:") System.out.println("Master Secret:"); printHex(dump, masterKey.getEncoded()); there's a potential for deadlock here - Handshaker has the System.out lock at this moment. If masterKey.getEncoded ends up needing a lock on SessionManager (haven't seen how that could happen yet) - then we've deadlock since SessionManager may want to print to System.out. Suggested fix would be to use a simple local lock in SessionManager for the debug printing.
12-12-2014