2018-08-05 Logging OpenSSL Connections

Unfortunately for me, using client certificates for authentication left my IRC service without any meaningful logging, as most of the per-user log messages in InspIRCd assumed that the client would make it past certificate verification. Since this is a rather esoteric feature, it was up to me to write the code that would enable this; in fact, I'd written a patch for this over a year ago, but had neglected what would happen in the rare event that the client presented a chain of certificates rather than just a single certificate, thus I had to revisit my old patch and extend its functionality. This required gathering some data in order to determine what a good log message might look like, actually implementing the code, and, of course, finding some unexpected functionality along the way.

Gathering Data

When in doubt it's usually a good idea to copy those who came before you, or at least get an idea of what they've done. In this case I decided to use the output from the OpenSSL s_client and s_server commands in order to see what might be worth logging. One problem I ran into is that s_server would silently fail to listen for connections because I had disabled IPv6 and needed to specify the -4 option in order to use only IPv4; furthermore, it turns out that s_server also uses the hidden -cert_chain option mentioned in a previous blog post. Amusingly enough, the output from s_server was worthless; s_client, however, did provide useful output, as shown in the following sample:

	 0 s:/CN=a
	   i:/CN=a
	 1 s:/CN=b
	   i:/CN=a

The output shows two certificates with their Distinguished Name (DN), in this example consisting only of the Common Name (denoted 'CN'), for both the Subject (denoted 's') and Issuer (denoted 'i') of the respective certificate; it shows how in this example Certificate Authority (CA) A signed client certificate B. Checking out the source for s_client showed the following code at work in apps/s_client.c:

        sk = SSL_get_peer_cert_chain(s);
        if (sk != NULL) {
            got_a_chain = 1;    /* we don't have it for SSL2 (yet) */

            BIO_printf(bio, "---\nCertificate chain\n");
            for (i = 0; i < sk_X509_num(sk); i++) {
                X509_NAME_oneline(X509_get_subject_name(sk_X509_value(sk, i)),
                                  buf, sizeof buf);
                BIO_printf(bio, "%2d s:%s\n", i, buf);
                X509_NAME_oneline(X509_get_issuer_name(sk_X509_value(sk, i)),
                                  buf, sizeof buf);
                BIO_printf(bio, "   i:%s\n", buf);
                if (c_showcerts)
                    PEM_write_bio_X509(bio, sk_X509_value(sk, i));
            }

This code, simple enough, detailed what functions would be necessary for my own needs.

Implementing

Connections needed to be logged in one of two places: during the handshake or during certificate validation in the case that the former succeeded.

Logging the Handshake

Error-checking in OpenSSL is rather tricky and weird. Errors are stored on a stack of errors that need to be cleared before calling the function that needs to be error-checked, thus the first function to invoke was ERR_clear_error(). After this I could then call the actual handshaking function SSL_do_handshake(), but what to do next depends on the return value from that function, of which there are three distinct possibilities, made more complicated by the fact that blocking and non-blocking IO need to be treated differently. If the return value is less than zero and one is using non-blocking IO then one needs to run SSL_get_error() and check for either SSL_ERROR_WANT_READ or SSL_ERROR_WANT_WRITE and then handle them as appropriate, otherwise there has been an error that needs to be logged; likewise, if the return value is zero then an error needed to be logged. Finally, if the return value is greater than zero then one can move onto logging client certificates without worrying about logging connection success. When logging an error, it's not clear to me whether it makes more sense to use ERR_get_error() or SSL_get_error() at this point; the former is more general than the latter, so I've been using it and it seems to be working fine. Once I had gotten through the return value maze and gotten an error number I could then convert it into a human-readable string by a call to ERR_error_string() and then finally log it. Example output from logged connection failures is as follows:

	OpenSSL handshake error 'error:1408A0C1:SSL routines:ssl3_get_client_hello:no shared cipher' for '71.6.146.185' port '6697'
	OpenSSL handshake error 'error:140760FC:SSL routines:SSL23_GET_CLIENT_HELLO:unknown protocol' for '71.6.146.185' port '6697'
	OpenSSL handshake error 'error:1408A10B:SSL routines:ssl3_get_client_hello:wrong version number' for '71.6.146.185' port '6697'
	OpenSSL handshake error 'error:1408A0C1:SSL routines:ssl3_get_client_hello:no shared cipher' for '71.6.146.185' port '6697'

The string returned by ERR_error_string() is the first single-quoted string in each of the above lines. With logging connection failures out of the way I could then move onto logging certificate verification.

Checking the Certificate

Before printing the certificate chain I prefer to print any certificate validation errors. In the OpenSSL 1.0.1 series this required an initial call to ERR_load_X509_strings() in order to load the error strings, but does not appear to be relevant to the 1.1.0 series. Once the error strings had been loaded I could then use SSL_get_peer_certificate() in order to see if a certificate was actually presented by the peer; I obviously cannot validate what is not there. Next I called SSL_get_verify_result() which returns X509_V_OK if the peer certificate is valid, otherwise it will return a value that can be passed to X509_verify_cert_error_string() in order to return a human-readable error string; some example error strings include:

	unable to verify the first certificate
	certificate revoked

Notice that the errors don't always make the situation clear, but they are far better than nothing.

Logging the peer certificate chain was slightly more involved than in the s_client code; this is because, in server mode, SSL_get_peer_cert_chain() does not present the peer certificate and thus a separate call to SSL_get_peer_certificate() is necessary. It also may not be immediately apparent how to use the strange STACK_OF(X509*) object returned by the function; the STACK_OF object is a special data type defined in OpenSSL via macros that allows access of OpenSSL objects through a, well, stack abstraction for that specific type, perhaps analogous to a C++ template, though I am no C++ aficionado. In the STACK_OF(X509*) case this meant using the functions sk_509_num() and sk_509_value() to return the length of the stack and the value in the stack, respectively. Once the certificate had been obtained I could call X509_get_subject_name() and X509_get_issuer_name() to return the subject and issuer names, respectively, followed by X509_NAME_oneline() to turn it into human-readable ASCII text. Doing that for each certificate gave me enough information to log the peer's certificate chain.

Idiosyncrasies and Miscellaneous

An interesting quirk I noticed when running my tests with s_client is that in certain circumstances OpenSSL appeared to automatically append the root certificate to the client certificate when sending its certificates to the server (though you shouldn't use the same certificate for signing and encryption). For example, the command openssl s_client -verify_return_error -cert leaf_ca/certs/leaf_ca.pem -key leaf_ca/private/leaf_ca.pem -connect 127.0.0.1:6697 -ign_eof produced the output:

	Valid peer certificate chain from '127.0.0.1' port '6697':
	 0 s:/CN=leaf_ca
	   i:/CN=root_ca

...while the same command with the Certificate Authority specified via CAfile, specifically, openssl s_client -verify_return_error -CAfile root_ca/certs/root_ca.pem -cert leaf_ca/certs/leaf_ca.pem -key leaf_ca/private/leaf_ca.pem -connect 127.0.0.1:6697 -ign_eof produced the output:

	Valid peer certificate chain from '127.0.0.1' port '6697':
	 0 s:/CN=leaf_ca
	   i:/CN=root_ca
	 1 s:/CN=root_ca
	   i:/CN=root_ca

Even stranger, this did not happen with the chain of trust A -> B -> C and the client passing certificates B and C via openssl s_client -verify_return_error -CAfile a/certs/a.pem -cert c/certs/c.pem -key c/private/c.pem -cert_chain b/certs/b.pem -connect 127.0.0.1:6697 -ign_eof:

	Valid peer certificate chain from '127.0.0.1' port '6697':
	 0 s:/CN=c
	   i:/CN=b
	 1 s:/CN=b
	   i:/CN=a

There doesn't appear to be any harm in this behavior as far as I can tell, but it is rather odd.

Slightly more annoying for me is how sending a certificate chain isn't cooperating with Certificate Revocation Lists (CRLs) in a way that I'd like. As mentioned in a previous blog post about CRLs, each certificate authority must have a CRL, even if it hasn't revoked any certificates. Well, this logic also applies when the client sends the CA in a chain, even if the server trusts said CA, thus a trust chain of A -> B -> C where the server has A and the client sends B -> C will fail unless the client sends a CRL for B. The problem is that I have no idea how to add B's CRL into the client's certificate chain. Perhaps I'll find out with more digging, perhaps it's not currently possible. At least I got the logging working, though.