We have a GUI "console" application that connects via RMI to a server. When we enable SSL for the connection, we occassionally experience unacceptable (45-60 sec) delays (on the RMI calls). This is not something that happens always, and is difficult to reproduce on demand - therefore it makes debugging it a little challenging. However, there are some things that we observe happening that could be related, and for which we don't have a full understanding.
There can actually be more than one connection through the same RMI object; for example, a background event polling thread in addition to the main GUI control activity. There is also the potential for more than one concurrent login session from the same GUI instance. It looks like for these extra connections that "sub-tunnels" get established over the main RMI connection.
The RMI registry is set up with the default Java 5 SSL socket factories:
<font face=courier>
sRmiRegistry = LocateRegistry.createRegistry(rmiPort, new SslRMIClientSocketFactory(), new SslRMIServerSocketFactory());
</font>
The client is running Java 6, although my reading indicates that both 5 and 6 implement the same version of TLS, so I am assuming these are compatible implementations.
I've enabled <font face=courier>javax.net.debug=ssl,handshake</font> on both the server and client sides. I've read through the discussion at http://download.oracle.com/javase/1.5.0/docs/guide/security/jsse/ReadDebug.html. When the very first connection is requested, I see the full handshake as described there. Sometimes this takes a matter of 5-10 seconds, but once in a while this can take up to 30-45 seconds. I've monitored the CPU on the server, and there seems to be plenty of processing bandwidth available, so I'm not sure what causes this delay. The one variable I do still have is the network itself, and I have read some discussions where the network can cause some problems (
2188634
Subsequent connections do not go through this entire handshake negotiation; I suspect that is as expected. What I see is like:
client:
<font face=courier>
Allow unsafe renegotiation: false
Allow legacy hello messages: true
Is initial handshake: true
Is secure renegotiation: false
%% Client cached [Session-1, SSL_RSA_WITH_RC4_128_MD5]
%% Try resuming [Session-1, SSL_RSA_WITH_RC4_128_MD5] from port 59650
*** ClientHello, TLSv1
RandomCookie: GMT: 1301751486 bytes = { 86, 25, 192, 23, 98, 10, 87, 73, 0, 230, 184, 209, 224, 163, 161, 147, 185, 60, 251, 37, 175, 189, 17, 181, 66, 232, 226, 155 }
Session ID: {78, 151, 39, 174, 136, 149, 114, 240, 114, 250, 163, 160, 165, 73, 14, 72, 37, 30, 133, 183, 60, 232, 180, 187, 163, 187, 150, 55, 151, 228, 94, 31}
Cipher Suites: [SSL_RSA_WITH_RC4_128_MD5, SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_WITH_DES_CBC_SHA, SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_RSA_EXPORT_WITH_RC4_40_MD5,
SSL_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
Compression Methods: { 0 }
***
AWT-EventQueue-0, WRITE: TLSv1 Handshake, length = 107
</font>
server:
<font face=courier>
RMI TCP Connection(3)-192.168.81.163, READ: TLSv1 Handshake, length = 107
*** ClientHello, TLSv1
RandomCookie: GMT: 1301751486 bytes = { 86, 25, 192, 23, 98, 10, 87, 73, 0, 230, 184, 209, 224, 163, 161, 147, 185, 60, 251, 37, 175, 189, 17, 181, 66, 232, 226, 155 }
Session ID: {78, 151, 39, 174, 136, 149, 114, 240, 114, 250, 163, 160, 165, 73, 14, 72, 37, 30, 133, 183, 60, 232, 180, 187, 163, 187, 150, 55, 151, 228, 94, 31}
Cipher Suites: [SSL_RSA_WITH_RC4_128_MD5, SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA,
SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_WITH_DES_CBC_SHA, SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_RSA_EXPORT_WITH_RC4_40_MD5,
SSL_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA, Unknown 0x0:0xff]
Compression Methods: { 0 }
***
%% Resuming [Session-1, SSL_RSA_WITH_RC4_128_MD5]
*** ServerHello, TLSv1
RandomCookie: GMT: 1301751494 bytes = { 209, 51, 102, 243, 27, 176, 48, 48, 82, 172, 64, 223, 85, 63, 100, 201, 201, 84, 200, 87, 188, 131, 158, 130, 74, 39, 123, 90 }
Session ID: {78, 151, 39, 174, 136, 149, 114, 240, 114, 250, 163, 160, 165, 73, 14, 72, 37, 30, 133, 183, 60, 232, 180, 187, 163, 187, 150, 55, 151, 228, 94, 31}
Cipher Suite: SSL_RSA_WITH_RC4_128_MD5
Compression Method: 0
***
Cipher suite: SSL_RSA_WITH_RC4_128_MD5
CONNECTION KEYGEN:
Client Nonce:
0000: 4E 97 27 BE 56 19 C0 17 62 0A 57 49 00 E6 B8 D1 N.'.V...b.WI....
0010: E0 A3 A1 93 B9 3C FB 25 AF BD 11 B5 42 E8 E2 9B .....<.%....B...
Server Nonce:
0000: 4E 97 27 C6 D1 33 66 F3 1B B0 30 30 52 AC 40 DF N.'..3f...00R.@.
0010: 55 3F 64 C9 C9 54 C8 57 BC 83 9E 82 4A 27 7B 5A U?d..T.W....J'.Z
Master Secret:
0000: 75 DE 95 15 50 5C 67 78 43 FD 24 A5 71 49 D1 4B u...P\gxC.$.qI.K
0010: 54 C7 08 E5 ED EA A3 A3 B3 42 9F E9 06 55 77 FB T........B...Uw.
0020: 31 01 92 6A BA FF 6F 2A 62 E0 EF B8 DC 5B 4D 99 1..j..o*b....[M.
Client MAC write Secret:
0000: EA 80 97 F9 59 17 05 E6 61 B8 5C A1 B7 43 5C FA ....Y...a.\..C\.
Server MAC write Secret:
0000: 80 CD 3B BE 71 C0 8A D9 BA A2 39 C6 91 D7 BE 0C ..;.q.....9.....
Client write key:
0000: 8C 87 2B 61 45 B5 38 A1 B7 AD CE E4 21 72 18 AC ..+aE.8.....!r..
Server write key:
0000: B9 6A 93 E2 90 61 50 A8 59 9A CC 8D A9 FC FA DC .j...aP.Y.......
... no IV for cipher
RMI TCP Connection(3)-192.168.81.163, WRITE: TLSv1 Handshake, length = 74
RMI TCP Connection(3)-192.168.81.163, WRITE: TLSv1 Change Cipher Spec, length = 1
*** Finished
verify_data: { 253, 15, 21, 26, 27, 85, 91, 155, 77, 235, 89, 149 }
***
RMI TCP Connection(3)-192.168.81.163, WRITE: TLSv1 Handshake, length = 32
RMI TCP Connection(3)-192.168.81.163, READ: TLSv1 Change Cipher Spec, length = 1
client:
AWT-EventQueue-0, READ: TLSv1 Handshake, length = 74
*** ServerHello, TLSv1
RandomCookie: GMT: 1301751494 bytes = { 209, 51, 102, 243, 27, 176, 48, 48, 82, 172, 64, 223, 85, 63, 100, 201, 201, 84, 200, 87, 188, 131, 158, 130, 74, 39, 123, 90 }
Session ID: {78, 151, 39, 174, 136, 149, 114, 240, 114, 250, 163, 160, 165, 73, 14, 72, 37, 30, 133, 183, 60, 232, 180, 187, 163, 187, 150, 55, 151, 228, 94, 31}
Cipher Suite: SSL_RSA_WITH_RC4_128_MD5
Compression Method: 0
***
Warning: No renegotiation indication extension in ServerHello
CONNECTION KEYGEN:
Client Nonce:
0000: 4E 97 27 BE 56 19 C0 17 62 0A 57 49 00 E6 B8 D1 N.'.V...b.WI....
0010: E0 A3 A1 93 B9 3C FB 25 AF BD 11 B5 42 E8 E2 9B .....<.%....B...
Server Nonce:
0000: 4E 97 27 C6 D1 33 66 F3 1B B0 30 30 52 AC 40 DF N.'..3f...00R.@.
0010: 55 3F 64 C9 C9 54 C8 57 BC 83 9E 82 4A 27 7B 5A U?d..T.W....J'.Z
Master Secret:
0000: 75 DE 95 15 50 5C 67 78 43 FD 24 A5 71 49 D1 4B u...P\gxC.$.qI.K
0010: 54 C7 08 E5 ED EA A3 A3 B3 42 9F E9 06 55 77 FB T........B...Uw.
0020: 31 01 92 6A BA FF 6F 2A 62 E0 EF B8 DC 5B 4D 99 1..j..o*b....[M.
Client MAC write Secret:
0000: EA 80 97 F9 59 17 05 E6 61 B8 5C A1 B7 43 5C FA ....Y...a.\..C\.
Server MAC write Secret:
0000: 80 CD 3B BE 71 C0 8A D9 BA A2 39 C6 91 D7 BE 0C ..;.q.....9.....
Client write key:
0000: 8C 87 2B 61 45 B5 38 A1 B7 AD CE E4 21 72 18 AC ..+aE.8.....!r..
Server write key:
0000: B9 6A 93 E2 90 61 50 A8 59 9A CC 8D A9 FC FA DC .j...aP.Y.......
... no IV used for this cipher
%% Server resumed [Session-1, SSL_RSA_WITH_RC4_128_MD5]
AWT-EventQueue-0, READ: TLSv1 Change Cipher Spec, length = 1
AWT-EventQueue-0, READ: TLSv1 Handshake, length = 32
*** Finished
verify_data: { 253, 15, 21, 26, 27, 85, 91, 155, 77, 235, 89, 149 }
***
AWT-EventQueue-0, WRITE: TLSv1 Change Cipher Spec, length = 1
*** Finished
verify_data: { 172, 220, 179, 57, 94, 246, 218, 98, 182, 126, 203, 62 }
***
AWT-EventQueue-0, WRITE: TLSv1 Handshake, length = 32
</font>
server:
<font face=courier>
RMI TCP Connection(3)-192.168.81.163, READ: TLSv1 Handshake, length = 32
*** Finished
verify_data: { 172, 220, 179, 57, 94, 246, 218, 98, 182, 126, 203, 62 }
***
</font>
I then see some socket timeouts set on the client:
<font face=courier>
AWT-EventQueue-0, setSoTimeout(60000) called
[...]
AWT-EventQueue-0, setSoTimeout(0) called
</font>
Periodically, when I see the above negotiation occur for a new connection, it looks like the client side might be timing out waiting for the ServerHello. I say this because I see a second ClientHello sent before the (first) ServerHello comes back. Eventually the ServerHello arrives, and a connection is established, but then a second ServerHello arrives sort of unexpectedly. It "feels like" the more connections I have open, the more frequently this occurs. Is this a problem? Is there a way to control the timeout values?
The other thing I see fairly regularly is the following exchange, with the client effectively sitting idle, other than polling loops:
client:
<font face=courier>
RMI Scheduler(0), called close()
RMI Scheduler(0), called closeInternal(true)
RMI Scheduler(0), SEND TLSv1 ALERT: warning, description = close_notify
RMI Scheduler(0), WRITE: TLSv1 Alert, length = 18
</font>
server:
<font face=courier>
RMI TCP Connection(1)-192.168.81.168, READ: TLSv1 Alert, length = 18
RMI TCP Connection(1)-192.168.81.168, RECV TLSv1 ALERT: warning, close_notify
RMI TCP Connection(1)-192.168.81.168, called closeInternal(false)
RMI TCP Connection(1)-192.168.81.168, SEND TLSv1 ALERT: warning, description = close_notify
RMI TCP Connection(1)-192.168.81.168, WRITE: TLSv1 Alert, length = 18
RMI TCP Connection(1)-192.168.81.168, called close()
RMI TCP Connection(1)-192.168.81.168, called closeInternal(true)
RMI TCP Connection(1)-192.168.81.168, called close()
RMI TCP Connection(1)-192.168.81.168, called closeInternal(true)
</font>
However, communication seems to continue on with no real delay. I think I've read somewhere that this could be due to an improperly configured socket (on the client side?), but it is curious because it happens long after the initial connection has been established.
I also see regular <font face=courier>RMI RenewClean</font> sequences, but they don't seem to have much of an impact either...
Any thoughts are greatly appreciated.