crypto/x509: FetchPEMRoots on macOS takes 20 seconds when there are a lot of trust settings

[tbodt]

Repro steps

First run this test program:

package main

import (
    "encoding/pem"
    "crypto/x509"
)

func main() {
	const certPEM = `
-----BEGIN CERTIFICATE-----
MIIDujCCAqKgAwIBAgIIE31FZVaPXTUwDQYJKoZIhvcNAQEFBQAwSTELMAkGA1UE
BhMCVVMxEzARBgNVBAoTCkdvb2dsZSBJbmMxJTAjBgNVBAMTHEdvb2dsZSBJbnRl
cm5ldCBBdXRob3JpdHkgRzIwHhcNMTQwMTI5MTMyNzQzWhcNMTQwNTI5MDAwMDAw
WjBpMQswCQYDVQQGEwJVUzETMBEGA1UECAwKQ2FsaWZvcm5pYTEWMBQGA1UEBwwN
TW91bnRhaW4gVmlldzETMBEGA1UECgwKR29vZ2xlIEluYzEYMBYGA1UEAwwPbWFp
bC5nb29nbGUuY29tMFkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEfRrObuSW5T7q
5CnSEqefEmtH4CCv6+5EckuriNr1CjfVvqzwfAhopXkLrq45EQm8vkmf7W96XJhC
7ZM0dYi1/qOCAU8wggFLMB0GA1UdJQQWMBQGCCsGAQUFBwMBBggrBgEFBQcDAjAa
BgNVHREEEzARgg9tYWlsLmdvb2dsZS5jb20wCwYDVR0PBAQDAgeAMGgGCCsGAQUF
BwEBBFwwWjArBggrBgEFBQcwAoYfaHR0cDovL3BraS5nb29nbGUuY29tL0dJQUcy
LmNydDArBggrBgEFBQcwAYYfaHR0cDovL2NsaWVudHMxLmdvb2dsZS5jb20vb2Nz
cDAdBgNVHQ4EFgQUiJxtimAuTfwb+aUtBn5UYKreKvMwDAYDVR0TAQH/BAIwADAf
BgNVHSMEGDAWgBRK3QYWG7z2aLV29YG2u2IaulqBLzAXBgNVHSAEEDAOMAwGCisG
AQQB1nkCBQEwMAYDVR0fBCkwJzAloCOgIYYfaHR0cDovL3BraS5nb29nbGUuY29t
L0dJQUcyLmNybDANBgkqhkiG9w0BAQUFAAOCAQEAH6RYHxHdcGpMpFE3oxDoFnP+
gtuBCHan2yE2GRbJ2Cw8Lw0MmuKqHlf9RSeYfd3BXeKkj1qO6TVKwCh+0HdZk283
TZZyzmEOyclm3UGFYe82P/iDFt+CeQ3NpmBg+GoaVCuWAARJN/KfglbLyyYygcQq
0SgeDh8dRKUiaW3HQSoYvTvdTuqzwK4CXsr3b5/dAOY8uMuG/IAR3FgwTbZ1dtoW
RvOTa8hYiU6A475WuZKyEHcwnGYe57u2I2KbMgcKjPniocj4QzgYsVAVKW3IwaOh
yE+vPxsiUkvQHdO2fojCkY8jg70jxM+gu59tPDNbw3Uh/2Ij310FgTHsnGQMyA==
-----END CERTIFICATE-----`
    block, _ := pem.Decode([]byte(certPEM));
    if block == nil {
        panic("failed to parse cert")
    }
    cert, err := x509.ParseCertificate(block.Bytes)
    if err != nil {
        panic("failed to parse cert: " + err.Error())
    }
    if _, err := cert.Verify(x509.VerifyOptions{}); err != nil {
        panic("failed to verify cert: " + err.Error())
    }
}

Observe that it takes a fraction of a second.

Then set up a new macOS VM, download my trust settings from https://gist.githubusercontent.com/tbodt/57539144e5e1841d956706d0bece86a2/raw/37221140760d6af8556d8dcbdb66ab373cb4933f/trust.xml and import them using security trust-settings-import. Run the program again.

What did you expect to see?

The program should run in a fraction of a second.

What did you see instead?

The program takes 20 seconds.

When I run it on my computer and not in the testing VM, it takes 140 seconds, probably because I actually have the certificates that correspond to the trust settings. This causes it to always exceed the 30 second TLS connection timeout, which means any go program that uses https doesn't work.

What version of Go are you using (go version)?

go version go1.8 darwin/amd64

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/tbodt/go"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.8/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.8/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/5g/6q3kyyzs1xsg3kdy58zbg9940000gn/T/go-build077841286=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

[tbodt]

I would suggest using the system's certificate verification instead. This ends up moving the two minutes of work into the trustd daemon, which then creates a long-lived cache which every program can use.

Of course, the root issue is that this takes two minutes. I've had no luck getting Apple to talk to me about that.

[bradfitz]

To confirm, we're not talking about the cross-compiled CGO_ENABLED=0 code path, right?

[tbodt]

Yes, we're talking about the codepath with cgo. I'm not sure if the no-cgo codepath would be faster.

[adg]

I am encountering the 20 second delay only with cgo disabled. The first call to security trust-settings-export is what takes up the time. See upspin/upspin#413.

[adg]

In fact, it takes 20 seconds for security trust-settings-export to report (visible with GODEBUG=x509roots=1):

crypto/x509: exec ["/usr/bin/security" "trust-settings-export" "/var/folders/2r/2wscqnf957d_75ltvpj_n4zc0035qk/T/x509trustpolicy813089759/user"]: exit status 1, SecTrustSettingsCreateExternalRepresentation: No Trust Settings were found.

I wonder if anyone else has observed this? Seems like a long time to determine that there are no trust settings.

[tbodt]

To make it take 20 seconds with cgo enabled, you need to import thousands of trust settings. I've provided a file that you can use with security trust-settings-import. I don't recommend doing this outside a VM, as it's not easy to delete those trust settings.

[adamdecaf]

On go version go1.10 darwin/amd64 with 168 trust policies applied (all but one CA as a test) I'm not seeing this take 20 seconds -- around 1.5s on the non-cgo path. This is on my 2013 macbook pro with Firefox and apps running (not an idle machine). #24084 might be a performance win here.

package main

import (
	"crypto/x509"
	"fmt"
	"time"
)

func main() {
	start := time.Now()
	certs, err := x509.SystemCertPool()
	end := time.Now()
	if err != nil {
		panic(err)
	}
	fmt.Printf("found %d certs in %v\n", len(certs.Subjects()), end.Sub(start))
}

$ security trust-settings-export -d trust.plist
...Trust Settings exported successfully.

$ grep '<integer>' trust.plist  | wc -l
     175

$ CGO_ENABLED=0 time go run main.go 
found 173 certs in 1.589059971s
        1.95 real         1.87 user         2.58 sys

$ CGO_ENABLED=0 time go run main.go 
found 173 certs in 1.60052905s
        1.94 real         1.88 user         2.59 sys

$ CGO_ENABLED=0 time go run main.go 
found 173 certs in 1.599523808s
        1.93 real         1.88 user         2.63 sys

$ CGO_ENABLED=0 time go run main.go 
found 173 certs in 1.586739973s
        1.93 real         1.86 user         2.56 sys

$ CGO_ENABLED=0 time go run main.go 
found 173 certs in 1.570033595s
        1.90 real         1.84 user         2.53 sys

$ CGO_ENABLED=0 time go run main.go 
found 173 certs in 1.5935134s
        1.94 real         1.87 user         2.59 sys

[davecheney]

The real time may be lower. In your example you are timing compiling, linking, and then running the binary.

…

On 25 Feb 2018, at 06:38, Adam Shannon ***@***.***> wrote: On go version go1.10 darwin/amd64 with 168 trust policies applied (all but one CA as a test) I'm not seeing this take 20 seconds -- around 1.5s on the non-cgo path. This is on my 2013 macbook pro with Firefox and apps running (not an idle machine). package main import ( "crypto/x509" "fmt" "time" ) func main() { start := time.Now() certs, err := x509.SystemCertPool() end := time.Now() if err != nil { panic(err) } fmt.Printf("found %d certs in %v\n", len(certs.Subjects()), end.Sub(start)) } $ security trust-settings-export -d trust.plist ...Trust Settings exported successfully. $ grep '<integer>' trust.plist | wc -l 175 $ CGO_ENABLED=0 time go run main.go found 173 certs in 1.589059971s 1.95 real 1.87 user 2.58 sys $ CGO_ENABLED=0 time go run main.go found 173 certs in 1.60052905s 1.94 real 1.88 user 2.59 sys $ CGO_ENABLED=0 time go run main.go found 173 certs in 1.599523808s 1.93 real 1.88 user 2.63 sys $ CGO_ENABLED=0 time go run main.go found 173 certs in 1.586739973s 1.93 real 1.86 user 2.56 sys $ CGO_ENABLED=0 time go run main.go found 173 certs in 1.570033595s 1.90 real 1.84 user 2.53 sys $ CGO_ENABLED=0 time go run main.go found 173 certs in 1.5935134s 1.94 real 1.87 user 2.59 sys — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or mute the thread.

[robert-nix]

I ran into this issue on 1.10.2 (darwin amd64 downloaded from golang.org) thanks to (unintended?) behavior of Blizzard's Battle.net app which created and added thousands of certificates to the System keychain.

This issue manifested for me in net/http returning a "TLS handshake timeout" error for any https connection. I've removed the certificates and connections are now succeeding.

[gopherbot]

Change https://golang.org/cl/227037 mentions this issue: crypto/x509: use Security.framework without cgo for roots on macOS

[FiloSottile]

I was too optimistic on closing this, I can still reproduce the extreme slowness with hundreds of roots, and it leads to net/http: TLS handshake timeout errors. Interestingly, when there are thousands of roots, even the security tool takes a long time to list them all, but not a long time to export the whole trust settings.

[leslie-qiwa]

I suffered a lot on this TLS handshake timeout failure. Is this issue related?

$ go get golang.org/x/oauth2
go: golang.org/x/net@v0.0.0-20190628185345-da137c7871d7: Get https://goproxy.io/golang.org/x/net/@v/v0.0.0-20190628185345-da137c7871d7.mod: net/http: TLS handshake timeout

When I run above program, it took

real	0m14.454s
user	0m13.519s
sys	0m0.360s

[gopherbot]

Change https://golang.org/cl/353132 mentions this issue: crypto/x509: use platform verifier on darwin