Let's Encrypt certificate validation too slow on Linux

[ccic]

After the fix of https://github.com/dotnet/corefx/issues/35086, X509Chain build sees a big perf improvement, but for Let's Encrypt certificate, it is still too slow.

using System;
using System.Diagnostics;
using System.Linq;
using System.Security.Cryptography.X509Certificates;

namespace x509perf
{
    public class TestLetsEncrypt
    {
        private static readonly byte[] s_testLetsEncryptCertBytes = Convert.FromBase64String(@"MIILoQIBAzCCC2cGCSqGSIb3DQEHAaCCC1gEggtUMIILUDCCBgcGCSqGSIb3DQEHBqCCBfgwggX0AgEAMIIF7QYJKoZIhvcNAQcBMBwGCiqGSIb3DQEMAQYwDgQIIYhr1K5Dm8kCAggAgIIFwB6uJ/MzNM9va1naRU8UoU4jzslvwqMfWZoCPzKK1TmfyrIiBd4g9WBnzHq2VQ837L2apmv/rHPLkWcF+H/PKlA42wU86QSmSGCv81HLzDdU38F45VG92hu3nd6xWT+ngp+SUFB/WTpDkDtMgyUGy9ZOJr2llOfbj12QzEmWgs55QY3kcbbnIlcGiL2MoWVUR6qPWEkpw6y04nKrh6OJYXaaThyvuAS9qfWHcobHahCCnC5YcfzfPngEspbsIYTgBq5kDKjZolMqdiH+vvnes6gQdV+1tGpGEWFkzpkyYtIeZVIAbxHKX8ID3ZOqhcMpURniitM03/mpuvCFsFUwGpCI4VSYoz16GqKBRGDvc+mcKqCd1QKuHawjfLmpCRtAMKxtCfUJxLCqZ8NqDXNLxxik+yRHlqSSC3epT2pBkEdSKXx8o9E5EEPYwZNdbAA3ZIFzv6SNzhmkQs5GmoArgxN+Onp3gL3h7/fsrwqblugYGUsLRlvlcuw80P2j6zmEDCsVNBNs2DtaWB7xBRedYS5r1JByakWMBN0R8TjxHEOtvsx52omNcx2iEoFH16cVpuF+YcEuHI17i04QvxVChLlRQ8sEYcg25F7RDHALVKfsoj6aEetXsaFcKeLLTFJLXVe+voxc95eSrZl36zsTREihpYqjJOaEKnxY7C1joQpnixie9hKSkD4kQ1qtz4m5Jej4N/a8Zynv1C0YPKfOjj6ggZGby9cOFNjIt9NEwdlZoXIY7QpfazRDE6JKtnEEx6/VVVB9e6tMAk2lPe41vQ0CQouZk2m/GEyAd/54IbHKKisVWnD/m2QUnoFyb9ATKbWPnXf6DUG7MA71On7DT060jJj2SxMgRMcgnd5Dn55DhKcHXP1sMv/4KTRUEIJfqj4qqq2wu+JsMeVnoHtSJuHnUfcXz8Z91xMK2jRnM8Vrm1VVwg0HrXbp7vllJcEoAbSGOk6+cxvGkxTtoEU4LiduFOHHBQ/Fr1X79qZs1pMMuK75Qk3YUdQr4fd+pNH1gW4k5NpJx/VrktZlDzA3wkI01LMyyOkBt+qL9eiIJd9RlPT/NZLui5OtCZVQZcQWLbtaVH2zGh6BXG0/TxgCGgzNzXNJ7IPrl8DNPIyeuad6J5Yzo+gtso5d96oz94xub5rm9fCnIKGvptmFLBtA2KMiB77gHXSDPlQW2/4uYjHBqz1CUz5CHdQSktcihiVep/dq51N1INbAmJd7Ph4qmvDNUhyXoSda44hIoJjrJcKNHIZG3TAza/XmdaM/OINu93nc09+P5Mjh6kUOJlzBZYFdVieAveX6SK5XZ/6YF6sOBFga5DBdqMdnPwj2T+GC7FneadFi2bSDWvimOU80qKijO9iexCVjzh+J7E8novtWXZOGgocdYcmz4Z8UmXwG5GdLjH2/SiwJ4GEMReUILgbGtTp6FOTZ58hp0XEnzFpbXo7w5VvP/Gcupqjicn4KcP6bkeCIVid6c1UDNttEbAhvz35wkqR9gOI+gwoD1ynQxPkDJijTy1vhGdLb+DCDDAmOzI7KeQYUz8esFe3jOLGJseoiE7/VB/Uqo0JcL/gYbfPqV1IlnT0XO+Bam8tcf8XjCTUvEL7bjzCAGB5k7nF/8BFm1nQdV6UiCqwyOdGWNdarNpgBmC5DW6HVOtm+q0rIPIqF53mjfPtBKRNiUGaqd6I5U1TZvNyI7IVl0XIeJKpK4SvSEHWNyCxSgvTLqalm4xH8HusmdXH1U1vSzjjSFI5wpBpsK1RJqrLX7vcycYz3R8eLJGQWhFwaLAry5kFxMTXgeOouI6sZMcVLn6MF5x2Q0rXMoXarRMS/mfGS+n4DUsDXcTMaP/ovImqB/Y2Qg0fvkqn0T7sHGgrZIqyJRNvXXKcr8xOXiVGtX1vSDF8naUzPIeuq8nrjlKhBYh9P1b4fFx0G7DOaaT99EovJDHqaBq57xy5wG9QMT5nCMIIFQQYJKoZIhvcNAQcBoIIFMgSCBS4wggUqMIIFJgYLKoZIhvcNAQwKAQKgggTuMIIE6jAcBgoqhkiG9w0BDAEDMA4ECF2w3jv50/WKAgIIAASCBMiiHC/GRrCZWDllMpcz5SJfzD/p1/T6uIpn0ExvYgL3RpMEi4jmDOEVdgltdYQcqYos+iSBCPW0IpDcZtjL4LYO6RbItAd5HihqU9A9RFUi3Ps7y0PMxwaDZizSTBv8xtjT/EObhOxYqWiO0FBTf+g38ubuuY4aS7XvqVSL+mHDg0MpIaB92psAg4dp+61qZ08VQJgHeQ1dFz2qSCq6hFZtBKjV8JScecl5H/rhkR9AUImYGM4pOBMKjlZfMiwjtKFzV7NotlhzOSjJezk5sTgQO/WOQ+LwasIdeX9uHad0V7Ed9OxROBR8+Y67tFyPj/iQS+/G+KGEatmW607LOjroDcYVpxpOahfvl64b8eyXqCcg7hGMQqFNinxptQ2tD8ChpYucYJG3hPUe742NPKg3h58dtUKNW4jfuoB4uOEmrvYvHwsvX0uUKvssomOMng+aS1Mjr012NQ634TSmDU3maNtyhq6g4w4hQFUsMipu/gC5+sQHCaum0NdGtvvht1dXQcE6QE27CNIVVwgkcMxKHjoIlSSlfNYppqFe0idgX0+Z2AJ8vTTRNrIgCGYxQ604Wqdsw6D7Ss8S31P++KkoVddDeMoB1WvkLhPXGXlB9pkxSDRVPayOp/7ymTX7zw/tfmsPsGu83M3miNL3naOO1IrZjxPwH5w/qqEoAeSN7HJOZ8wQzBQev1yAKrYkIXj3iS/qZ5R3aoxp8Duq3gGQhlH4wqDrmaNstuggDcPGKUdm3NbJXbUskbAI1R4GCiz6D8Y1Zmz3lmgBa+mBM8Fn1eRkQoCKOp1xTKewfc/kxC7tl1U3RixROmSof+dPQeG5c/WU2QV0XFaqVRQpfiBfu+oYqFsIdKWeSq7J9dfRM930cCB/k9scvSe5udHDSlbKFtnoVXig9j6EtK/FU2WJBbdffaxGUtmNrH1YWAKWCgVszVK9uYuEdr27oPcxuFg/NiDno3mX7Zqd1FPVKGxC3BP1TIebN4SvS0nOYcAgh3Gqf/pMdEFlkIfo840VYQk9ejlJ4boeHulI6Z+fn7J21lfxzJ2Gao4D/e+PulffH352KMFUWGH/zn7H1g6S9Xgb1IT2NO5joRRQbpguuBkWrb4OxGJoTgiaeDP5hNffxteO+s2lzCPf3y42VL4IBIitv0gF2jxBWJBjEnjg+X/w9OCR3qg35AB+GCjpu8yN5xrR451faRXABbsJLiBgtV7TWkW2AOM9tzWYyazYOuKqImKubedF8gMdpD7eMHY9JYbz3Ef1w036+MAk1qMO7HxSzrlWSFQuhrHeEnP4gxNBm9imBc5k/1KTZS+E7taQLZFmynUegMHH0tenccPGsChtZFJQRiILVkEamCl3mLRhFTtZ/N8cz7xfD5wwLW98Qm7X97AGgeZTEciEqAkKE35FTTbhZTyFHnIfS/fbISVGFWigZmqTfBPrEuqF3yQ0EgFYRUXsK0HeCjcRSbp6v3YERmZC2rnmKkU9oebztxO8LLTqNu5jYU0QKT1EzS8dzDfaamR1t7Bd+Xol/ezS2oCh3db1+bA3QqSyDRsHJyZ2eEUJH/C5yJlxPDLjf9JrI4R2eTg7qL5fDRHZ9caMJf/zGU3U//h+Ka4vxKIyBMrZxb0TFRcd1AQxJTAjBgkqhkiG9w0BCRUxFgQUhMkdBLqBr8Z45KxBw42Pk/U+6lMwMTAhMAkGBSsOAwIaBQAEFG+ms9ZjBQulvwaBgYqdQ+umc9grBAgUIceZtaaZcgICCAA=");

        private static X509Certificate2 GetServerLetsEncryptCertificate()
        {
            var certCollection = new X509Certificate2Collection();
            certCollection.Import(s_testLetsEncryptCertBytes, "123456", X509KeyStorageFlags.DefaultKeySet);
            return certCollection.Cast<X509Certificate2>().First(c => c.HasPrivateKey);
        }

        public static void TestLetsEncryptCert()
        {
            const int Iters = 1000;
            var k = 0;
            var sw = new Stopwatch();
            using (X509Certificate2 originalCert = GetServerLetsEncryptCertificate())
            {
                while (k < 5)
                {
                    Console.Write($"{Iters} iterations: ");
                    sw.Restart();
                    for (int i = 0; i < Iters; i++)
                    {
                        using (var chain = new X509Chain())
                        using (var cert = new X509Certificate2(originalCert))
                        {
                            chain.Build(cert);
                        }
                    }
                    sw.Stop();
                    Console.WriteLine(sw.Elapsed);
                    k++;
                }
            }
        }

        static void Main()
        {
            TestLetsEncryptCert();
        }
    }
}

On windows, the output:
1000 iterations: 00:00:00.2156929
1000 iterations: 00:00:00.1387840
1000 iterations: 00:00:00.1537569
1000 iterations: 00:00:00.1433948
1000 iterations: 00:00:00.1191109

On Ubuntu 16.04 or 18.04 (either local VM or Azure VM has the same output), the output:
1000 iterations: 00:05:21.7863637
1000 iterations: 00:05:19.6759851

I use iftop command on Ubuntu to check the tcp traffic, and found it connects "apps.digsigtrust.com" when perf test running. This website in fact is "https://www.identrust.com".

It looks like the fix of https://github.com/dotnet/corefx/issues/35086 does not help for this case.

[vcsjones]

Since you posted the private key for the certificate, I just revoked the certificate out of abundance of caution. The private key should not be necessary to reproduce issues with chain building.

@ccic if you are using this certificate you should use certbot to replace the certificate (or whatever issued the original certificate)

Here is an unrevoked Let's Encrypt certificate (from my own website) that still reproduces the issue and does not contain the certificate's private key:

        private static readonly byte[] s_testLetsEncryptCertBytes = Convert.FromBase64String(@"
MIIEmDCCA4CgAwIBAgISA32Enk2w0aJsvUKWPPDrrgNbMA0GCSqGSIb3DQEBCwUA
MEoxCzAJBgNVBAYTAlVTMRYwFAYDVQQKEw1MZXQncyBFbmNyeXB0MSMwIQYDVQQD
ExpMZXQncyBFbmNyeXB0IEF1dGhvcml0eSBYMzAeFw0xOTA0MTkxNTU3MTNaFw0x
OTA3MTgxNTU3MTNaMBcxFTATBgNVBAMTDHZjc2pvbmVzLmNvbTBZMBMGByqGSM49
AgEGCCqGSM49AwEHA0IABHJu+1gvkYL7LhDPB8GeKLA1tXqUnE/vkZcLo/vqhMpC
30as5PISXh/aEWTk2TAj95QlsIV6D6sakWSEx8GDQ+WjggJ0MIICcDAOBgNVHQ8B
Af8EBAMCB4AwHQYDVR0lBBYwFAYIKwYBBQUHAwEGCCsGAQUFBwMCMAwGA1UdEwEB
/wQCMAAwHQYDVR0OBBYEFF2+C68iJ8ZxQ9FfxXfbsic34GIwMB8GA1UdIwQYMBaA
FKhKamMEfd265tE5t6ZFZe/zqOyhMG8GCCsGAQUFBwEBBGMwYTAuBggrBgEFBQcw
AYYiaHR0cDovL29jc3AuaW50LXgzLmxldHNlbmNyeXB0Lm9yZzAvBggrBgEFBQcw
AoYjaHR0cDovL2NlcnQuaW50LXgzLmxldHNlbmNyeXB0Lm9yZy8wFwYDVR0RBBAw
DoIMdmNzam9uZXMuY29tMBEGCCsGAQUFBwEYBAUwAwIBBTBMBgNVHSAERTBDMAgG
BmeBDAECATA3BgsrBgEEAYLfEwEBATAoMCYGCCsGAQUFBwIBFhpodHRwOi8vY3Bz
LmxldHNlbmNyeXB0Lm9yZzCCAQQGCisGAQQB1nkCBAIEgfUEgfIA8AB2AHR+2oMx
rTMQkSGcziVPQnDCv/1eQiAIxjc1eeYQe8xWAAABajaH2MsAAAQDAEcwRQIgEPE4
uYY+ipw2YNUX38HXPKxs+9tnQWhpIrzx30o0E/ICIQDWxBf+rhpfhdHx6SOMLd+P
d50bQnBolHbW4ySOSQRKegB2AGPy283oO8wszwtyhCdXazOkjWF3j711pjixx2hU
S9iNAAABajaH10sAAAQDAEcwRQIhANTQht8HHmDuV++8NtgPrG18uvk+EuDchtrd
mz6p0jkRAiALCO5De6hDGCaV3VqIG1YsOcBwPzVInaf31/n8NTHy3jANBgkqhkiG
9w0BAQsFAAOCAQEASPSgXJdXwZqLX3O4GjNVhBKXzRkVLyn52CYugQGp4p61Htup
Oa+f/AJaRG1yabtTpKcPjVJNbLmiaa1twMZ2bNu7Vj6BLRSo/ABQa3D/3l8A4gyW
3PO44lr3Ny9/E2rS9pG2NfA3zwTfwvs9nlkl9kT62P3qT8EG8SP5CCKxv1zpNAib
AVRoA9ExnKh+sOiXVEVvNMg91g3mJ9frnhGiZYhioLVfDjZ3vmNO5pDnTVILm58V
ne0baFsKKRVEqMxZz4gXly01jR3r2avjaMc8gAoaZMZpffoXd7DPSrfZeAL1uqwp
YFVtlkylIjAerA4YTdmacuQwwbV8t9JocERlkQ==");

        private static X509Certificate2 GetServerLetsEncryptCertificate()
        {
            return new X509Certificate2(s_testLetsEncryptCertBytes);
        }

[vcsjones]

As for the issue itself, I see very slow chain building on netcoreapp2.2, but ~2 seconds per-1000 iteration on 3.0-preview5 on Ubuntu 18.04. The performance issue seems to have been mostly addressed with dotnet/corefx#35367, I believe.

$HOME/dotnet-preview/dotnet run
1000 iterations: 00:00:02.4664053
1000 iterations: 00:00:02.3980268
1000 iterations: 00:00:02.3803434
1000 iterations: 00:00:02.3754681
1000 iterations: 00:00:02.3644791

@ccic can you confirm if the performance is improved on the latest 3.0 preview for you?

/cc @bartonjs

[bartonjs]

My best guess is that you have the cross-signed intermediate somewhere in your system, and either don't have the Let's Encrypt root, or OpenSSL is preferring the alternate/failing chain. (And you don't trust the DST Root CA X3 cert)

You could examine all the certificates from X509Store(StoreName.CertificateAuthority, StoreLocation.CurrentUser) to see if that's where the "bad" intermediate is coming from... and from that store you can remove it. If it's in the LocalMachine version of that store it came from /etc/ssl/certs (or whatever your distro uses).

[ccic]

After creating a new Ubuntu 18.04, install dotnet core 2.2, and dotnet core 3.0 preview nightly, I saw the issue disappeared and get the following data with dotnet core 3.0 preview nightly

1000 iterations: 00:00:01.4288970
1000 iterations: 00:00:01.2398440
1000 iterations: 00:00:01.2450654
1000 iterations: 00:00:01.2414768
1000 iterations: 00:00:01.3235624

After diagnostic by using "strace", I found it found CRL in /home/honzhan/.dotnet/corefx/cryptography/crls/2e5ac55d.crl, so it run very fast.

But on my other VMs, there is no such file, and it tries to download CRL from other sites:

stat("/home/hongjiang/.dotnet/corefx/cryptography/x509stores/disallowed", 0x7fff27e3ea30) = -1 ENOENT (No such file or directory)
lstat("/home/hongjiang/.dotnet/corefx/cryptography/x509stores/disallowed", 0x7fff27e3ea40) = -1 ENOENT (No such file or directory)
lstat("/usr/local/ssl/cert.pem", 0x7fff27e3e9f0) = -1 ENOENT (No such file or directory)
lstat("/usr/local/ssl/certs", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/home/hongjiang/.dotnet/corefx/cryptography/x509stores/root", 0x7fff27e3ea10) = -1 ENOENT (No such file or directory)
lstat("/home/hongjiang/.dotnet/corefx/cryptography/x509stores/ca", 0x7fff27e3ea10) = -1 ENOENT (No such file or directory)
lstat("/home/hongjiang/.dotnet/corefx/cryptography/x509stores/my", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=554, ...}) = 0
recvmsg(45, 0x7fff27e3dce0, 0) = -1 EAGAIN (Resource temporarily unavailable)
sendmsg(45, {msg_name(0)=NULL, msg_iov(1)=[{"GET / HTTP/1.1\r\nHost: cert.int-x"..., 53}], msg_controllen=0, msg_flags=0}, 0) = 53

[ccic]

Anyway, I found on windows it is ~10X faster than on Linux. Is it possible to improve further on Linux?

On windows with dotnet core 2.1.504
1000 iterations: 00:00:00.9194700
1000 iterations: 00:00:00.1349630
1000 iterations: 00:00:00.1310108
1000 iterations: 00:00:00.1288279
1000 iterations: 00:00:00.1361873

But on Linux with dotnet core 3.0.100-preview6-012026:
1000 iterations: 00:00:01.4288970
1000 iterations: 00:00:01.2398440
1000 iterations: 00:00:01.2450654
1000 iterations: 00:00:01.2414768
1000 iterations: 00:00:01.3235624

[bartonjs]

Is it possible to improve further on Linux?

Possibly, but there's not another known/suspected easy win... and given the time remaining in 3.0, and the outstanding bugs, there's not really time (for me) to look further in this release.

[ccic]

@bartonjs All right. I know you need to prioritize your tasks for 3.0.
When will the 3.0 preview 6 release? I'd like to try it on my service.

By the way, I'd like to share the lesson I learn for this issue. Somebody else may encounter the same issue.

Symptom:
x509 certificate verification is too slow, CPU usage is low (<5%), "iftop" indicates it downloads something from internet during running.

Reproduce process:
I want to upgrade openssl to 1.1.1, so I download the source code tar ball, build it and install it manually.
The CA path is changed after upgrade, but I did not notice that.

Before updating openssl

$ openssl version -d
OPENSSLDIR: "/usr/lib/ssl"
 
After updating openssl
 
$ openssl version -d
OPENSSLDIR: "/usr/local/ssl"

Fix: create a softlink for /usr/local/ssl/certs, and point to /etc/ssl/certs.

Diagnostic methods:

1. Find the process ID,
2. "strace -p $PID" to check what system calls it invoked during x509 certificate verification. You will see which system folders it scan to find CA certificates.

[wfurt]

is the slowdown possibly coming from accessing the filesystem? If so, can we cache and hook in file change notifier?

[ccic]

I used "perf record -g" to get the following profiling data. Any idea?

• 69.73% swapper [kernel.kallsyms] [k] native_safe_halt ?
• 3.26% x509 libcrypto.so.1.1 [.] X509_NAME_cmp ¦
• 2.70% x509 libcrypto.so.1.1 [.] __bn_sqrx8x_reduction ¦
• 1.55% x509 libcrypto.so.1.1 [.] bn_sqrx8x_internal ¦
• 1.31% x509 libcrypto.so.1.1 [.] bn_mulx4x_mont ¦
• 1.19% x509 libcrypto.so.1.1 [.] x509_object_cmp ¦
• 0.64% x509 libcrypto.so.1.1 [.] X509_subject_name_cmp ¦
• 0.53% x509 libc-2.27.so [.] cfree

[wfurt]

are you low on memory @ccic ? You can disable swap to take that out of picture.

[bartonjs]

If so, can we cache ... ?

We're already doing that (it was the change that moved the decimal point).