Intermittent SSL handshake error with Apache HTTP Server

Question

I am seeing intermittent SSL handshake errors with Java clients and browsers accessing a site through an Apache HTTP server. This happens rarely, but it breaks builds and impacts user experience every day. The server is configured to establish a secure connection, but to not require a certificate from the client.

I've turned on SSL debug output on both a Java test client and the server (see below). What I am observing is that whenever the handshake exception occurs the server seems to have sent a request for a client certificate. I do not understand why it would ever do so, and why this only happens sporadically. When it does send the certificate request, the error occurs almost always, however I have also captured requests where this succeeded (maybe 1% of the time, with 99% failing).

The client uses Java 8 (1.8.0_31-b13), the Apache HTTP server version is 2.2.19.

Here are snippets from the logs:

1) Apache config excerpt

SSLProtocol ALL -SSLv2 -SSLv3
SSLCertificateFile <path-to-pem1>
SSLCertificateChainFile <path-to-pem2>
SSLCACertificateFile <path-to-pem3>
SSLVerifyDepth 10
SSLVerifyClient none

The .pem files are world-readable.

2) Client log (severly abbreviated)

*** ClientHello, TLSv1.2
***
*** ServerHello, TLSv1
***
*** Certificate chain
***
*** Diffie-Hellman ServerKeyExchange
*** CertificateRequest
*** ServerHelloDone
*** Certificate chain
***
*** ClientKeyExchange, DH
*** Finished
***
...
main, WRITE: TLSv1 Handshake, length = 48
main, waiting for close_notify or alert: state 1
main, Exception while waiting for close java.net.SocketException: Software caused connection abort: recv failed
main, handling exception: java.net.SocketException: Software caused connection abort: recv failed
%% Invalidated:  [Session-1, TLS_DHE_RSA_WITH_AES_128_CBC_SHA]
main, SEND TLSv1 ALERT:  fatal, description = unexpected_message
...
main, WRITE: TLSv1 Alert, length = 32
main, Exception sending alert: java.net.SocketException: Software caused connection abort: socket write error
main, called closeSocket()

3) Server log (abbreviated)

[info] [client x.x.x.x] Connection to child 1 established (server XXX:443)
[info] Seeding PRNG with 0 bytes of entropy
[debug] ssl_engine_kernel.c(1866): OpenSSL: Handshake: start
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: before/accept initialization
[debug] ssl_engine_io.c(1897): OpenSSL: read 11/11 bytes from BIO#82f6820 [mem: 82c5290] (BIO dump follows)
[debug] ssl_engine_io.c(1830): +-------------------------------------------------------------------------+
[debug] ssl_engine_io.c(1869): | 0000: XX XX XX XX XX XX XX XX-XX XX XX                 ...........      |
[debug] ssl_engine_io.c(1875): +-------------------------------------------------------------------------+
[debug] ssl_engine_io.c(1897): OpenSSL: read 245/245 bytes from BIO#82f6820 [mem: 82c529b] (BIO dump follows)
[debug] ssl_engine_io.c(1830): +-------------------------------------------------------------------------+
[debug] ssl_engine_io.c(1869): | 0000: XX XX XX XX XX XX XX XX-XX XX XX XX XX XX XX XX  ................ |
...
[debug] ssl_engine_io.c(1869): | 00f0: XX XX XX XX XX                                   .....            |
[debug] ssl_engine_io.c(1875): +-------------------------------------------------------------------------+
[debug] ssl_engine_kernel.c(1987): [client x.x.x.x] SSL virtual host for servername XXX found
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 read client hello A
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 write server hello A
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 write certificate A
[debug] ssl_engine_kernel.c(1274): [client x.x.x.x] handing out temporary 1024 bit DH key
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 write key exchange A
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 write certificate request A
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 flush data
[debug] ssl_engine_io.c(1897): OpenSSL: read 5/5 bytes from BIO#82f6820 [mem: 82c5290] (BIO dump follows)
[debug] ssl_engine_io.c(1830): +-------------------------------------------------------------------------+
[debug] ssl_engine_io.c(1869): | 0000: 16 03 01 00 8d                                   .....            |
[debug] ssl_engine_io.c(1875): +-------------------------------------------------------------------------+
[debug] ssl_engine_io.c(1897): OpenSSL: read 141/141 bytes from BIO#82f6820 [mem: 82c5295] (BIO dump follows)
[debug] ssl_engine_io.c(1830): +-------------------------------------------------------------------------+
[debug] ssl_engine_io.c(1869): | 0000: XX XX XX XX XX XX XX XX-XX XX XX XX XX XX XX XX  ................ |
...
[debug] ssl_engine_io.c(1869): | 0080: XX XX XX XX XX XX XX XX-XX XX XX XX XX           .............    |
[debug] ssl_engine_io.c(1875): +-------------------------------------------------------------------------+
[debug] ssl_engine_kernel.c(1884): OpenSSL: Write: SSLv3 read client certificate B
[debug] ssl_engine_kernel.c(1903): OpenSSL: Exit: error in SSLv3 read client certificate B
[debug] ssl_engine_kernel.c(1903): OpenSSL: Exit: error in SSLv3 read client certificate B
[info] [client x.x.x.x] SSL library error 1 in handshake (server XXX:443)
[info] SSL Library Error: 336105671 error:140890C7:SSL routines:SSL3_GET_CLIENT_CERTIFICATE:peer did not return a certificate No CAs known to server for verification?
[info] [client x.x.x.x] Connection closed to child 1 with abortive shutdown (server XXX:443)

In good cases we consistently see no "*** CertificateRequest" on the client and output like this on the server

[debug] ssl_engine_kernel.c(1987): [client x.x.x.x] SSL virtual host for servername XXX found
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 read client hello A
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 write server hello A
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 write certificate A
[debug] ssl_engine_kernel.c(1274): [client x.x.x.x] handing out temporary 1024 bit DH key
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 write key exchange A
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 write server done A
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 flush data
[debug] ssl_engine_io.c(1897): OpenSSL: read 5/5 bytes from BIO#82d82d8 [mem: 82c8790] (BIO dump follows)
[debug] ssl_engine_io.c(1830): +-------------------------------------------------------------------------+
[debug] ssl_engine_io.c(1869): | 0000: 16 03 01 00 86                                   .....            |
[debug] ssl_engine_io.c(1875): +-------------------------------------------------------------------------+
[debug] ssl_engine_io.c(1897): OpenSSL: read 134/134 bytes from BIO#82d82d8 [mem: 82c8795] (BIO dump follows)
[debug] ssl_engine_io.c(1830): +-------------------------------------------------------------------------+
[debug] ssl_engine_io.c(1869): | 0000: XX XX XX XX XX XX XX XX-XX XX XX XX XX XX XX XX  ................ |
...
[debug] ssl_engine_io.c(1869): | 0080: XX XX XX XX XX XX                                ......           |
[debug] ssl_engine_io.c(1875): +-------------------------------------------------------------------------+
[debug] ssl_engine_kernel.c(1874): OpenSSL: Loop: SSLv3 read client key exchange A

Java client code outline:

URL url = new URL("https://...");
HttpsURLConnection connection = (HttpsURLConnection) url.openConnection();
connection.setRequestProperty("Authorization", "Basic " + DatatypeConverter.printBase64Binary((user + ":" + pass).getBytes(Charset.forName("UTF-8"))));
connection.setReadTimeout(60*1000);
connection.setUseCaches(false);
connection.connect();

Run with

java -Djavax.net.ssl.trustStore=... -Djavax.net.ssl.trustStoreType=jks -Djavax.net.ssl.trustStorePassword=... -Djavax.net.debug=all ...

Questions:

1. What makes the server send the certificate request, causing the ouput "*** CertificateRequest" on the client?
2. Is the setting "SSLVerifyClient none" not preventing the certificate request?
3. Any suggestions on what to look at next?

Update: I noticed that the Java client never shows the error when Java 6 is used. The problem occurs with Java 7 and 8, and in Chrome, Internet Explorer and Firefox. This seems to point to an issue with TLSv1.1 or TLSv1.2 (see also https://serverfault.com/questions/513961/how-to-disable-tls-1-1-1-2-in-apache "OpenSSL v1.0.1 has some known issues with TLSv1.2"). I will try to at least check if disabling TLSv1.1/2 in the Java client will make the problem go away.

Answer 1

What makes the server send the certificate request, causing the ouput "*** CertificateRequest" on the client?

A call to SSL_CTX_set_client_CA_list at the server. Its a list of distinguished names. Also see the SSL_CTX_set_client_CA_list man page.

The server will also need to call SSL_CTX_load_verify_locations to establish the trust in the CAs. Also see SSL_CTX_load_verify_locations man page.

---

Is the setting "SSLVerifyClient none" not preventing the certificate request?

Possibly. From the SSL_CTX_set_verify man page, you need SSL_VERIFY_PEER and possibly SSL_VERIFY_FAIL_IF_NO_PEER_CERT.

---

Any suggestions on what to look at next?

You should show your relevant Java code.

You should state the OpenSSL version used by the server and the client.

Answer 2

What makes the server send the certificate request, causing the ouput "*** CertificateRequest" on the client?

Somewhere you have SSLVerifyClient set to 'optional' or higher, possibly in a .htaccess file, which is why you can't find it in the configuration files. This overrides `SSLVerifyClient none' set globally.

Answer 3

After long and tedious debugging and analysis I would like to report the findings. The problem is related to the first ClientHello message of the TLS handshake as sent by the client.

Java 7 and Java 8 clients (and probably all modern browsers) use the "Server Name Indication" (SNI) extension. The problem only occurs when this extension is used. Java 6 clients don't send it, and the problem never occurred there. The problem occurred with TLSv1 and TLSv1.2 - we never observed TLSv1.1 requests so I cannot comment.

For Java 7 and 8 clients to prevent the issue we can set -Djsse.enableSNIExtension=false which stops the client sending the SNI extension.

We will try to change the httpd.conf configuration (and included files) to see if we can get the server to behave well. I may post information if we're successful, i.e. if there is a server-side workaround for this. The above mentioned Java switch is a client-side workaround which is at least good enough for our nightly builds.