Why does SSL handshaking sometimes kill my CPU?

Question

We are running in to a very strange problem: we're using a modified version of the Selenium HTTP proxy (more akin to the BrowserMob Proxy) and finding that in some circumstances, which we can't reliably reproduce, CPU grinds to a halt when handling SSL connections.

A stack dump reveals that that the thread gets either stuck here:

"ProxyHandler$SslRelay3-1" prio=10 tid=0x09f9a400 nid=0x81f runnable [0xb2e69000]
   java.lang.Thread.State: RUNNABLE
    at java.math.BigInteger.multiply(BigInteger.java:1144)
    at java.math.BigInteger.lucasLehmerSequence(BigInteger.java:820)
    at java.math.BigInteger.passesLucasLehmer(BigInteger.java:750)
    at java.math.BigInteger.primeToCertainty(BigInteger.java:730)
    at java.math.BitSieve.retrieve(BitSieve.java:188)
    at java.math.BigInteger.largePrime(BigInteger.java:606)
    at java.math.BigInteger.<init>(BigInteger.java:511)
    at org.bouncycastle.crypto.generators.DHParametersHelper.generateSafePrimes(Unknown Source)
    at org.bouncycastle.crypto.generators.DHParametersGenerator.generateParameters(Unknown Source)
    at org.bouncycastle.jcajce.provider.asymmetric.dh.KeyPairGeneratorSpi.generateKeyPair(Unknown Source)
    at com.sun.net.ssl.internal.ssl.DHCrypt.<init>(DHCrypt.java:76)
    at com.sun.net.ssl.internal.ssl.ServerHandshaker.setupEphemeralDHKeys(ServerHandshaker.java:797)
    at com.sun.net.ssl.internal.ssl.ServerHandshaker.trySetCipherSuite(ServerHandshaker.java:702)
    at com.sun.net.ssl.internal.ssl.ServerHandshaker.chooseCipherSuite(ServerHandshaker.java:633)
    at com.sun.net.ssl.internal.ssl.ServerHandshaker.clientHello(ServerHandshaker.java:425)
    at com.sun.net.ssl.internal.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:139)
    at com.sun.net.ssl.internal.ssl.Handshaker.processLoop(Handshaker.java:516)
    at com.sun.net.ssl.internal.ssl.Handshaker.process_record(Handshaker.java:454)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:884)
    - locked <0x8a18f238> (a com.sun.net.ssl.internal.ssl.SSLSocketImpl)
    - locked <0x8a18f2c0> (a java.lang.Object)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1112)
    - locked <0x8a18f2c8> (a java.lang.Object)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:744)
    at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
    - locked <0x8a18f300> (a com.sun.net.ssl.internal.ssl.AppInputStream)
    at org.openqa.jetty.util.LineInput.fill(LineInput.java:477)
    at org.openqa.jetty.util.LineInput.fillLine(LineInput.java:555)
    at org.openqa.jetty.util.LineInput.readLineBuffer(LineInput.java:301)
    at org.openqa.jetty.util.LineInput.readLineBuffer(LineInput.java:285)
    at org.openqa.jetty.http.HttpRequest.readHeader(HttpRequest.java:239)
    at org.openqa.jetty.http.HttpConnection.readRequest(HttpConnection.java:866)
    at org.openqa.jetty.http.HttpConnection.handleNext(HttpConnection.java:912)
    at org.openqa.jetty.http.HttpConnection.handle(HttpConnection.java:837)
    at org.openqa.jetty.http.SocketListener.handleConnection(SocketListener.java:243)
    at org.openqa.jetty.util.ThreadedServer.handle(ThreadedServer.java:357)
    at org.openqa.jetty.util.ThreadPool$PoolThread.run(ThreadPool.java:534)

Multiple stack dumps reveal that generateSafePrimes() is continually running and each subsequent stack dump shows slightly different places in java.math.BigInteger that is running. However, it's hard to tell where exactly things are getting stuck or if there is a legit infinite loop (I doubt it though).

Investigating further, I was able to capture the relevant output with -Djavax.net.debug=ssl set, for both a working example and a broken example.

When things work, the handshaking happens almost instantly and we see this debug output, resulting in a proper Diffie-Hellman key exchange:

ProxyHandler$SslRelay3-9, setSoTimeout(10000) called
ProxyHandler$SslRelay3-9, READ: TLSv1 Handshake, length = 171
*** ClientHello, TLSv1
RandomCookie:  GMT: 1320359479 bytes = { 176, 253, 143, 106, 114, 151, 90, 1, 9, 53, 221, 254, 160, 42, 176, 239, 1, 222, 180, 41, 56, 115, 203, 185, 74, 68, 2, 27 }
Session ID:  {}
Cipher Suites: [Unknown 0x0:0xff, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x88, Unknown 0x0:0x87, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x84, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_RC4_128_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_RC4_128_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x45, Unknown 0x0:0x44, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_RC4_128_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_RC4_128_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x96, Unknown 0x0:0x41, SSL_RSA_WITH_RC4_128_MD5, SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_FIPS_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA]
Compression Methods:  { 0 }
Unsupported extension server_name, [host_name: REDACTED]
Extension elliptic_curves, curve names: {secp256r1, secp384r1, secp521r1}
Extension ec_point_formats, formats: [uncompressed]
Unsupported extension type_35, data: 
***
%% Created:  [Session-10, TLS_DHE_RSA_WITH_AES_128_CBC_SHA]
*** ServerHello, TLSv1
RandomCookie:  GMT: 1320359480 bytes = { 85, 189, 191, 119, 135, 205, 134, 161, 254, 164, 83, 102, 9, 149, 182, 59, 83, 201, 110, 233, 114, 168, 166, 192, 80, 250, 204, 121 }
Session ID:  {79, 179, 22, 56, 209, 63, 115, 246, 134, 192, 16, 222, 203, 184, 204, 251, 145, 49, 200, 163, 218, 68, 78, 13, 96, 106, 79, 11, 93, 61, 187, 48}
Cipher Suite: TLS_DHE_RSA_WITH_AES_128_CBC_SHA
Compression Method: 0
***
Cipher suite:  TLS_DHE_RSA_WITH_AES_128_CBC_SHA
*** Certificate chain
chain [0] = [
[
  Version: V3
  Subject: CN=REDACTED, OU=Test, O=CyberVillainsCA, L=Seattle, ST=Washington, C=US
  Signature Algorithm: SHA1withRSA, OID = 1.2.840.113549.1.1.5

  Key:  RSA Public Key
            modulus: 9fff00e7f363191e3d3dc0aa85a2791776ecab2d8365ab4026a5e051ff60b6ce11e484a6279f5e123559dfa44479797c7b04a97d1bcfa0e10479d616deeb48cd5c40890041786106a4e88b365585113b107a80be9b3bdf19672a3ffb40a7fac583cae69d262bad1a74ce888f84643733affdbd4f939178eb060f3a32a34345d7
    public exponent: 10001

  Validity: [From: Sun May 22 02:45:42 UTC 2011,
               To: Thu Apr 20 02:45:42 UTC 2017]
  Issuer: C=US, OU=CyberVillians Certification Authority, O=CyberVillians.com
  SerialNumber: [    01375389 64a8]

Certificate Extensions: 5
[1]: ObjectId: 2.5.29.14 Criticality=false
SubjectKeyIdentifier [
KeyIdentifier [
0000: D1 6A D0 8E B2 7E B4 90   C3 7C 30 D1 5B F2 70 71  .j........0.[.pq
0010: 94 B4 3F A8                                        ..?.
]
]

[2]: ObjectId: 2.5.29.35 Criticality=false
AuthorityKeyIdentifier [
KeyIdentifier [
0000: 0A BC 17 95 34 6B BC 87   1B 5B 4C FD F5 63 85 2D  ....4k...[L..c.-
0010: B4 8F F5 6C                                        ...l
]

]

[3]: ObjectId: 2.5.29.31 Criticality=false
CRLDistributionPoints [
  [DistributionPoint:
     [URIName: http://127.0.0.1:4444/selenium-server/sslSupport/blank_crl.pem]
]]

[4]: ObjectId: 2.5.29.37 Criticality=false
ExtendedKeyUsages [
  serverAuth
  clientAuth
  2.16.840.1.113730.4.1
  1.3.6.1.4.1.311.10.3.3
]

[5]: ObjectId: 2.5.29.19 Criticality=true
BasicConstraints:[
  CA:false
  PathLen: undefined
]

]
  Algorithm: [SHA1withRSA]
  Signature:
0000: 13 CA C0 80 2D BE AC 9D   3F 58 EF A9 C9 C4 E3 43  ....-...?X.....C
0010: FE ED 5A 14 0A 04 6B 67   ED 19 EF 8D C2 14 53 6D  ..Z...kg......Sm
0020: 1A 3F B8 99 8E 2B B1 0F   50 83 F1 5A 56 43 5F 8B  .?...+..P..ZVC_.
0030: 8B 0A EE 98 04 D7 32 FC   B9 FE 43 57 97 0B FC 46  ......2...CW...F
0040: 02 4E A4 8F F3 F0 65 BD   20 28 76 DB 29 16 B6 16  .N....e. (v.)...
0050: 3B 57 D3 B3 24 21 C5 AC   64 8E 95 C9 92 06 DC 95  ;W..$!..d.......
0060: F8 B4 62 74 8C 44 8D 96   83 94 0F 5C EE B0 A4 8B  ..bt.D.....\....
0070: 5A EA 1E 58 B2 A3 8B 0E   E1 79 5F 06 BF EE E3 A9  Z..X.....y_.....

]
***
*** Diffie-Hellman ServerKeyExchange
DH Modulus:  { 189, 165, 218, 21, 118, 110, 155, 89, 53, 21, 128, 88, 254, 47, 40, 106, 51, 167, 219, 167, 68, 153, 230, 233, 63, 125, 198, 5, 12, 230, 7, 156, 21, 89, 142, 17, 146, 200, 33, 197, 86, 116, 41, 212, 22, 176, 162, 138, 121, 124, 107, 57, 27, 209, 42, 131, 182, 254, 178, 211, 86, 112, 32, 222, 185, 43, 212, 180, 71, 200, 174, 22, 11, 172, 213, 135, 217, 124, 40, 120, 218, 170, 182, 151, 131, 89, 191, 59, 214, 52, 56, 119, 212, 5, 163, 107 }
DH Base:  { 173, 84, 126, 57, 69, 157, 241, 124, 0, 60, 149, 36, 136, 75, 82, 91, 142, 16, 240, 117, 1, 146, 23, 25, 218, 139, 127, 216, 27, 183, 252, 214, 189, 253, 2, 42, 125, 1, 73, 84, 49, 69, 80, 239, 179, 134, 236, 96, 175, 244, 36, 206, 203, 163, 251, 64, 83, 253, 74, 94, 114, 248, 210, 145, 130, 225, 252, 33, 56, 100, 6, 53, 163, 138, 154, 7, 142, 209, 10, 230, 107, 233, 77, 189, 151, 46, 115, 77, 93, 57, 47, 178, 121, 240, 183, 255 }
Server DH Public Key:  { 36, 153, 18, 99, 95, 39, 135, 103, 245, 21, 20, 161, 159, 246, 67, 6, 183, 101, 8, 62, 161, 21, 211, 95, 193, 13, 248, 152, 101, 138, 143, 247, 29, 176, 255, 165, 78, 140, 108, 243, 219, 222, 59, 181, 4, 71, 51, 164, 1, 80, 97, 70, 66, 189, 175, 19, 248, 11, 77, 84, 112, 134, 139, 222, 81, 12, 45, 173, 173, 102, 141, 195, 80, 244, 20, 251, 109, 246, 24, 194, 140, 201, 29, 251, 26, 191, 9, 201, 45, 107, 59, 28, 148, 25, 220, 215 }
Signed with a DSA or RSA public key
*** ServerHelloDone
ProxyHandler$SslRelay3-9, WRITE: TLSv1 Handshake, length = 1332

However, when things are broken things are very different and we never even get to attempt the DH exchange:

ProxyHandler$SslRelay3-1, setSoTimeout(10000) called
ProxyHandler$SslRelay3-1, READ: TLSv1 Handshake, length = 171
*** ClientHello, TLSv1
RandomCookie:  GMT: 1320358903 bytes = { 148, 198, 81, 98, 2, 66, 235, 221, 74, 170, 130, 205, 43, 139, 18, 60, 121, 148, 234, 153, 3, 89, 48, 153, 168, 196, 80, 54 }
Session ID:  {}
Cipher Suites: [Unknown 0x0:0xff, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x88, Unknown 0x0:0x87, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x84, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_RC4_128_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_RC4_128_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x45, Unknown 0x0:0x44, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_RC4_128_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_RC4_128_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x96, Unknown 0x0:0x41, SSL_RSA_WITH_RC4_128_MD5, SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_FIPS_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA]
Compression Methods:  { 0 }
Unsupported extension server_name, [host_name: REDACTED]
Extension elliptic_curves, curve names: {secp256r1, secp384r1, secp521r1}
Extension ec_point_formats, formats: [uncompressed]
Unsupported extension type_35, data: 
***
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
INFO 05/16 02:46:23 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:46:23 b.n.w.a.LoadTestTra~ - Collected 0 transactions
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
INFO 05/16 02:46:33 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:46:33 b.n.w.a.LoadTestTra~ - Collected 0 transactions
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
INFO 05/16 02:46:43 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:46:43 b.n.w.a.LoadTestTra~ - Collected 0 transactions
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
INFO 05/16 02:46:53 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:46:53 b.n.w.a.LoadTestTra~ - Collected 0 transactions
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
INFO 05/16 02:47:03 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:47:03 b.n.w.a.LoadTestTra~ - Collected 0 transactions
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
Acceptor [SSL: ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=35182]], setSoTimeout(10000) called
ProxyHandler$SslRelay2-0, setSoTimeout(10000) called
ProxyHandler$SslRelay2-0, READ: TLSv1 Handshake, length = 165
*** ClientHello, TLSv1
RandomCookie:  GMT: 1320359212 bytes = { 59, 24, 42, 178, 241, 201, 150, 61, 101, 15, 153, 40, 167, 176, 22, 250, 205, 245, 89, 8, 156, 34, 122, 161, 4, 99, 40, 108 }
Session ID:  {}
Cipher Suites: [Unknown 0x0:0xff, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x88, Unknown 0x0:0x87, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x84, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_RC4_128_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_RC4_128_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x45, Unknown 0x0:0x44, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_RC4_128_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_RC4_128_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x96, Unknown 0x0:0x41, SSL_RSA_WITH_RC4_128_MD5, SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_FIPS_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA]
Compression Methods:  { 0 }
Unsupported extension server_name, [host_name: sb-ssl.google.com]
Extension elliptic_curves, curve names: {secp256r1, secp384r1, secp521r1}
Extension ec_point_formats, formats: [uncompressed]
Unsupported extension type_35, data: 
***
Acceptor [SSL: ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=53331]], setSoTimeout(10000) called
ProxyHandler$SslRelay3-0, setSoTimeout(10000) called
ProxyHandler$SslRelay3-0, READ: TLSv1 Handshake, length = 171
*** ClientHello, TLSv1
RandomCookie:  GMT: 1320359212 bytes = { 124, 252, 208, 200, 213, 33, 188, 186, 19, 175, 247, 227, 126, 10, 57, 66, 29, 66, 230, 145, 66, 28, 210, 98, 167, 31, 240, 85 }
Session ID:  {}
Cipher Suites: [Unknown 0x0:0xff, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x88, Unknown 0x0:0x87, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, Unknown 0x0:0x84, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_RC4_128_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_RC4_128_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x45, Unknown 0x0:0x44, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_RC4_128_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_RC4_128_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, Unknown 0x0:0x96, Unknown 0x0:0x41, SSL_RSA_WITH_RC4_128_MD5, SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_FIPS_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA]
Compression Methods:  { 0 }
Unsupported extension server_name, [host_name: REDACTED]
Extension elliptic_curves, curve names: {secp256r1, secp384r1, secp521r1}
Extension ec_point_formats, formats: [uncompressed]
Unsupported extension type_35, data: 
***
INFO 05/16 02:47:13 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:47:13 b.n.w.a.LoadTestTra~ - Collected 0 transactions
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
INFO 05/16 02:47:23 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:47:23 b.n.w.a.LoadTestTra~ - Collected 0 transactions
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
INFO 05/16 02:47:33 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:47:33 b.n.w.a.LoadTestTra~ - Collected 0 transactions
INFO 05/16 02:47:43 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:47:43 b.n.w.a.LoadTestTra~ - Collected 0 transactions
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
INFO 05/16 02:47:53 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:47:53 b.n.w.a.LoadTestTra~ - Collected 0 transactions
INFO 05/16 02:48:03 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:48:03 b.n.w.a.LoadTestTra~ - Collected 0 transactions
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
Finalizer, called close()
Finalizer, called closeInternal(true)
INFO 05/16 02:48:13 b.n.w.a.LoadTestTra~ - Reported 0 slices representing 0 transactions
INFO 05/16 02:48:13 b.n.w.a.LoadTestTra~ - Collected 0 transactions
INFO 05/16 02:48:14 o.o.s.s.SeleniumDri~ - Got result: Timed out after 120000ms on session 5a7b389b01c041fcb3632c2f5056043b

That log spans a time range of 2 minutes, in which almost nothing happens. There is some additional SSL logging related to sb-ssl.google.com (which also blocks), but that can be ignored - it's just the Firefox browser checking in to Google's safe browsing API.

I should note: similar complaints had been levied against the Selenium proxy about a month ago, but they were resolved by upgrading to the latest version of BouncyCastle. However, we are finding that the problem occasionally still happens and we can't figure out why.

I'm hoping the StackOverflow family can shed some light on why sometimes the thread gets stuck in org.bouncycastle.crypto.generators.DHParametersHelper.generateSafePrimes and other times the logging shows that we proceed directly to this key line right away:

%% Created:  [Session-10, TLS_DHE_RSA_WITH_AES_128_CBC_SHA]

Thanks for any insight!

Edit: I should add that we're using Java 1.6.0_18-b07 on Linux (32bit and 64bit are affected), Selenium 2.21, and BouncyCastle 1.47.

Edit #2: I just confirmed that this problem doesn't exist when using Java 7.

Answer 1

So check the full comment thread, but basically after a lot of debugging I discovered that upgrading to Java 7 resolved the issue. Not sure what the original issue was with Java 6, but we're just going to go ahead with Java 7. I hope this helps someone in the future!