This discussion is archived
4 Replies Latest reply: Oct 17, 2011 2:27 PM by 894392 RSS

RMI over SSL occassionally has unacceptable delays

894392 Newbie
Currently Being Moderated
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 (RMI over SSL - handshake failure

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.
  • 1. Re: RMI over SSL occassionally has unacceptable delays
    EJP Guru
    Currently Being Moderated
    This all looks normal apart from the handshake times. Have a look at the RMI system properties linked from the RMI Home Page. You could try increasing the DGC intervals so that TCP connections remain in use for longer. I would also investigate your DNS configuration, this could be causing all the delays.
  • 2. Re: RMI over SSL occassionally has unacceptable delays
    894392 Newbie
    Currently Being Moderated
    I was curious about why I would get the periodic close() calls, and also about why the ServerHello might be timing out. Any further insight?

    Thanks for the other suggestions, I will look at them in more detail. Would the DNS configuration still come into play even if we were connecting purely to the IP address? Do the domain names in the cert chain(s) possibly get resolved every time?

    Edited by: 891389 on Oct 14, 2011 12:37 PM
  • 3. Re: RMI over SSL occassionally has unacceptable delays
    EJP Guru
    Currently Being Moderated
    I was curious about why I would get the periodic close() calls
    Because RMI does connection pooling, which you can also control via those system properties, and part of that is closing idle connections.
    and also about why the ServerHello might be timing out. Any further insight?
    Network problems?
    Would the DNS configuration still come into play even if we were connecting purely to the IP address?
    Yes because Java does reverse DNS lookups when opening sockets.
    Do the domain names in the cert chain(s) possibly get resolved every time?
    No.
  • 4. Re: RMI over SSL occassionally has unacceptable delays
    894392 Newbie
    Currently Being Moderated
    Would the DNS configuration still come into play even if we were connecting purely to the IP address?
    Yes because Java does reverse DNS lookups when opening sockets.

    I read the discussion at http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=5092063 - and while that is an interesting aspect (we are using 1.5 on the server), my initial impression is that we would be seeing the same behavior either with or without SSL being enabled, correct? And it wasn't 100% clear to me whether or not this problem is only seen on Windows, but our server platform is Linux.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points