Log details for client certificate failures

Currently, debugging client certificate verification failures is
mostly limited to looking at the TLS alert code on the client side.
For simple deployments, sometimes it's enough to see "sslv3 alert
certificate revoked" and know exactly what needs to be fixed, but if
you add any more complexity (multiple CA layers, misconfigured CA
certificates, etc.), trying to debug what happened based on the TLS
alert alone can be an exercise in frustration.

Luckily, the server has more information about exactly what failed in
the chain, and we already have the requisite callback implemented as a
stub.  We fill that in, collect the data, and pass the constructed
error message back to the main code via a static variable.  This lets
us add our error details directly to the final "could not accept SSL
connection" log message, as opposed to issuing intermediate LOGs.

It ends up looking like

    LOG:  connection received: host=localhost port=43112
    LOG:  could not accept SSL connection: certificate verify failed
    DETAIL:  Client certificate verification failed at depth 1: unable to get local issuer certificate.
            Failed certificate data (unverified): subject "/CN=Test CA for PostgreSQL SSL regression test client certs", serial number 2315134995201656577, issuer "/CN=Test root CA for PostgreSQL SSL regression test suite".

The length of the Subject and Issuer strings is limited to prevent
malicious client certs from spamming the logs.  In case the truncation
makes things ambiguous, the certificate's serial number is also
logged.

Author: Jacob Champion <pchampion@vmware.com>
Discussion: https://www.postgresql.org/message-id/flat/d13c4a5787c2a3f83705124f0391e0738c796751.camel@vmware.com

6 files changed, 101 insertions, 4 deletions

diff --git a/src/test/ssl/conf/client-long.config b/src/test/ssl/conf/client-long.config
new file mode 100644
index 00000000000..0e92a8fbfec
--- /dev/null
+++ b/src/test/ssl/conf/client-long.config
@@ -0,0 +1,14 @@
+# An OpenSSL format CSR config file for creating a client certificate with a
+# long Subject.
+
+[ req ]
+distinguished_name     = req_distinguished_name
+prompt                 = no
+
+[ req_distinguished_name ]
+# Common Names are 64 characters max
+CN                     = ssl-123456789012345678901234567890123456789012345678901234567890
+OU                     = Some Organizational Unit
+O                      = PostgreSQL Global Development Group
+
+# no extensions in client certs
diff --git a/src/test/ssl/ssl/client-long.crt b/src/test/ssl/ssl/client-long.crt
new file mode 100644
index 00000000000..a1db55b5c3e
--- /dev/null
+++ b/src/test/ssl/ssl/client-long.crt
@@ -0,0 +1,20 @@
+-----BEGIN CERTIFICATE-----
+MIIDWjCCAkICCCAiBRIUREYAMA0GCSqGSIb3DQEBCwUAMEIxQDA+BgNVBAMMN1Rl
+c3QgQ0EgZm9yIFBvc3RncmVTUUwgU1NMIHJlZ3Jlc3Npb24gdGVzdCBjbGllbnQg
+Y2VydHMwHhcNMjIwNTEyMjE0NDQ3WhcNNDkwOTI3MjE0NDQ3WjCBnDEsMCoGA1UE
+CgwjUG9zdGdyZVNRTCBHbG9iYWwgRGV2ZWxvcG1lbnQgR3JvdXAxITAfBgNVBAsM
+GFNvbWUgT3JnYW5pemF0aW9uYWwgVW5pdDFJMEcGA1UEAwxAc3NsLTEyMzQ1Njc4
+OTAxMjM0NTY3ODkwMTIzNDU2Nzg5MDEyMzQ1Njc4OTAxMjM0NTY3ODkwMTIzNDU2
+Nzg5MDCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBANgxmeHiVRuBTwlG
+Q1oM2M1ckQCI/o4hYcO9BYdxDYHiA7jy1WVenyj8BtUi5Aj9VDhpfiuewDarGQ5a
+TggD1pMjkw0MorBKBr9+1u1xGH/8Q3lkgU+OQXrPglo4IrVcqaoZFQ0nuMaVbieX
+0dDyTfsTaVQYYtqAtzhI/UGSIOhk2+lB9fP68jw9cLH0QYvR+qQ0IPG13I5zmSYP
+Mj0VYwMn9TF9/2sBOSRVgTVAcrYgOQLk3s/fGe66tmVBIWYcq65ygqD1+weu+Pax
+jPnwsefkdnf6JdYRG1F1Co7g52poPEYieAHfQOJ69sG0LYx0lBODC69qvSJ4WdCQ
+0zKw288CAwEAATANBgkqhkiG9w0BAQsFAAOCAQEArr5r1UxgUzPykmu5ZdL6y8TA
+ZbSQ1yBY0nhsRwRkDd66iPK9U6T6K2+pL8Vc6ioov9WOtHQ6ohP3gSavd40cHRmF
+auwIsZ4Wk0mjftpOuPFp1hyo8d/QYrbEm3qNe5qln5S9h8ipoYvFtf5zlK2KHJFz
+9ehZMZ1zGAERNCVM8UUQKyUuZB5GyrZlbslf6P/9Bsc54YUWxP2pr5r/RJ6DeXfI
+zAFfXT8AFVlClARA949gpX0LVrXryDN60CUJ88QJmYCQ3AtIgzYYeqcdYHTd8eS2
+9P5whDdU5NvROP+LjETeReJF4Bfyc2gM7zxZD2BDSf5exvnNqiy42/lR1b4szw==
+-----END CERTIFICATE-----
diff --git a/src/test/ssl/ssl/client-long.key b/src/test/ssl/ssl/client-long.key
new file mode 100644
index 00000000000..5b455a021f6
--- /dev/null
+++ b/src/test/ssl/ssl/client-long.key
@@ -0,0 +1,27 @@
+-----BEGIN RSA PRIVATE KEY-----
+MIIEpAIBAAKCAQEA2DGZ4eJVG4FPCUZDWgzYzVyRAIj+jiFhw70Fh3ENgeIDuPLV
+ZV6fKPwG1SLkCP1UOGl+K57ANqsZDlpOCAPWkyOTDQyisEoGv37W7XEYf/xDeWSB
+T45Bes+CWjgitVypqhkVDSe4xpVuJ5fR0PJN+xNpVBhi2oC3OEj9QZIg6GTb6UH1
+8/ryPD1wsfRBi9H6pDQg8bXcjnOZJg8yPRVjAyf1MX3/awE5JFWBNUBytiA5AuTe
+z98Z7rq2ZUEhZhyrrnKCoPX7B6749rGM+fCx5+R2d/ol1hEbUXUKjuDnamg8RiJ4
+Ad9A4nr2wbQtjHSUE4MLr2q9InhZ0JDTMrDbzwIDAQABAoIBADwJykpIqIny5xgU
+QzAG0U52nm4fnVGrQ5MwMxDh/HZNZes+xLRaCqk/FEasYdd9Qp5H7Zn/hDGqYlLy
+ESl4p2ZFQtkk4SlD5YvYladq+PrR+4sCtkZ5owWQCwsy+7CSAywRux7kIRRE+0pT
+hxkXsUBAq8eG3i0AAeHHo01KX4kptlJ5d1pFKKAPThTUHCT4VPHg8r59IdsNy6wC
++0E5ZRWsVUePy+ERuarX/um896hgbaiDJLFk02Orlc87+OBmRwO8J+KoUOEcAiTO
+OZqGGaDEn5Y2mEdp2cCmq7+Izcklaha6CPsoV8+O2HK8PKvBIQmlgbDmal4/RNqr
+JFqYz0ECgYEA+5z74Tmj+tzH57lcdMqVpndG39N8spBe8JbiFL16qOb6gRDytXjc
+hY6IQo4JStpJulnPBZ5JQSbSBgCOzYWJJVBnnwMJKjNCd1th4znjxxMOe4LiDTtw
+D3hQtzBU9FlI2sjWEUKf1xCyi9N41ApQC5eDWWd/0GN9+xAsxRjLL00CgYEA2/aH
+4kNVsBHQ7vmv+sNsWeIgKg7PC7hRjcCYQG9ylBbBnFtv5XJYicXwqorqngzJPoGw
+gB7iaSWL1UNAOSWRSFYe+woPpkY7n6Pbq211nzqV1avAdVrLylJwyE+EOQgTS30D
+8BHv0I714PMd/QLK5NSUEr1IRtCfLeMpcSg6YYsCgYEAv3O86KxeTMTvyy9s3WVE
+p4y8vhUDHi/iPbjhQBzJF3nhhJGrzE+xpGJG5jWDdpRQY15wuvqtDMkIKA8GmfWQ
+3Hao0gKSV6z3VzCOdEKZQeILNAnsDVt7shm/eRRqoB7L48XLtQh37UJESUbY+qb6
+L0fTZxTs2VjLBF1TY4mxGUUCgYEA1PLENKnJkA5/fowd8aA2CoKfbvgtPARyd9Bn
+1aHPhEzPnabsGm7sBl2qFAEvCFoKjkgR7sd3nCHsUUetKmYTU7uEfLcN1YSS/oct
+CLaMs92M53JCfZqsRrAvXc2VjX0i6Ocb49QJnph4tBHKC4MjmAuxWr8C9QPNxyfv
+nAw9EOcCgYBYzejUzp6xiv5YzpwIncIF0A5E6VITcsW+LOR/FZOUPso0X2hQoIEs
+wx8HjKCGfvX6628vnaWJC099hTmOzVwpEgik5zOmeAmZ//gt2I53Yg/loQUzH0CD
+iXxrg/4Up7Yxx897w11ukOZv2xwmAFO1o52Q8k7d5FiMfEIzAkS3Pg==
+-----END RSA PRIVATE KEY-----
diff --git a/src/test/ssl/sslfiles.mk b/src/test/ssl/sslfiles.mk
index cc023667af1..5f67aba795e 100644
--- a/src/test/ssl/sslfiles.mk
+++ b/src/test/ssl/sslfiles.mk
@@ -33,7 +33,7 @@ SERVERS := server-cn-and-alt-names \
 	server-multiple-alt-names \
 	server-no-names \
 	server-revoked
-CLIENTS := client client-dn client-revoked client_ext
+CLIENTS := client client-dn client-revoked client_ext client-long
 
 #
 # To add a new non-standard key, add it to SPECIAL_KEYS and then add a recipe
diff --git a/src/test/ssl/t/001_ssltests.pl b/src/test/ssl/t/001_ssltests.pl
index 707f4005af5..90ba5a75155 100644
--- a/src/test/ssl/t/001_ssltests.pl
+++ b/src/test/ssl/t/001_ssltests.pl
@@ -683,6 +683,10 @@ $node->connect_fails(
 	  . sslkey('client-revoked.key'),
 	"certificate authorization fails with revoked client cert",
 	expected_stderr => qr/SSL error: sslv3 alert certificate revoked/,
+	log_like => [
+		qr{Client certificate verification failed at depth 0: certificate revoked},
+		qr{Failed certificate data \(unverified\): subject "/CN=ssltestuser", serial number 2315134995201656577, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
+	],
 	# revoked certificates should not authenticate the user
 	log_unlike => [qr/connection authenticated:/],);
 
@@ -730,7 +734,35 @@ $node->connect_ok(
 $node->connect_fails(
 	$common_connstr . " " . "sslmode=require sslcert=ssl/client.crt",
 	"intermediate client certificate is missing",
-	expected_stderr => qr/SSL error: tlsv1 alert unknown ca/);
+	expected_stderr => qr/SSL error: tlsv1 alert unknown ca/,
+	log_like => [
+		qr{Client certificate verification failed at depth 0: unable to get local issuer certificate},
+		qr{Failed certificate data \(unverified\): subject "/CN=ssltestuser", serial number 2315134995201656576, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
+	]);
+
+$node->connect_fails(
+	"$common_connstr sslmode=require sslcert=ssl/client-long.crt " . sslkey('client-long.key'),
+	"logged client certificate Subjects are truncated if they're too long",
+	expected_stderr => qr/SSL error: tlsv1 alert unknown ca/,
+	log_like => [
+		qr{Client certificate verification failed at depth 0: unable to get local issuer certificate},
+		qr{Failed certificate data \(unverified\): subject "\.\.\./CN=ssl-123456789012345678901234567890123456789012345678901234567890", serial number 2315418733629425152, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
+	]);
+
+# Use an invalid cafile here so that the next test won't be able to verify the
+# client CA.
+switch_server_cert($node, certfile => 'server-cn-only', cafile => 'server-cn-only');
+
+# intermediate CA is provided but doesn't have a trusted root (checks error
+# logging for cert chain depths > 0)
+$node->connect_fails(
+	"$common_connstr sslmode=require sslcert=ssl/client+client_ca.crt",
+	"intermediate client certificate is untrusted",
+	expected_stderr => qr/SSL error: tlsv1 alert unknown ca/,
+	log_like => [
+		qr{Client certificate verification failed at depth 1: unable to get local issuer certificate},
+		qr{Failed certificate data \(unverified\): subject "/CN=Test CA for PostgreSQL SSL regression test client certs", serial number 2315134995201656577, issuer "/CN=Test root CA for PostgreSQL SSL regression test suite"},
+	]);
 
 # test server-side CRL directory
 switch_server_cert(
@@ -743,6 +775,10 @@ $node->connect_fails(
 	"$common_connstr user=ssltestuser sslcert=ssl/client-revoked.crt "
 	  . sslkey('client-revoked.key'),
 	"certificate authorization fails with revoked client cert with server-side CRL directory",
-	expected_stderr => qr/SSL error: sslv3 alert certificate revoked/);
+	expected_stderr => qr/SSL error: sslv3 alert certificate revoked/,
+	log_like => [
+		qr{Client certificate verification failed at depth 0: certificate revoked},
+		qr{Failed certificate data \(unverified\): subject "/CN=ssltestuser", serial number 2315134995201656577, issuer "/CN=Test CA for PostgreSQL SSL regression test client certs"},
+	]);
 
 done_testing();
diff --git a/src/test/ssl/t/SSL/Backend/OpenSSL.pm b/src/test/ssl/t/SSL/Backend/OpenSSL.pm
index aed6005b432..a43e64c04fb 100644
--- a/src/test/ssl/t/SSL/Backend/OpenSSL.pm
+++ b/src/test/ssl/t/SSL/Backend/OpenSSL.pm
@@ -88,7 +88,7 @@ sub init
 		"client.key",               "client-revoked.key",
 		"client-der.key",           "client-encrypted-pem.key",
 		"client-encrypted-der.key", "client-dn.key",
-		"client_ext.key");
+		"client_ext.key",           "client-long.key");
 	foreach my $keyfile (@keys)
 	{
 		copy("ssl/$keyfile", "$cert_tempdir/$keyfile")