From 35271a33733f0755ad1647aa04b69f525319fc70 Mon Sep 17 00:00:00 2001 From: Christopher Wood Date: Wed, 9 Dec 2020 17:50:40 -0800 Subject: [PATCH] crypto/tls: CF events crypto/tls: Add experimental intra-handshake timing support Extend the experimental Event API with two new event instances: one for client and server intra-handshake state machine durations, respectively. Each event records elapsed timestamps (durations) for relevant events during the course of a connection, such as reading and writing handshake messages of interest. This will be useful for recording intra-stack costs of TLS extensions such as ECH and KEMTLS. crypto/tls: Consolidate CF-specific logic * Rename EXP_Event to CFEvent. * Move CFEvent implementations to tls_cf.go. * Add CFControl parameter to Config. This value will be used to propagate Cloudflare-internal logic from the TLS configuration to HTTP requests. --- src/crypto/tls/common.go | 24 +++++ src/crypto/tls/conn.go | 8 ++ src/crypto/tls/handshake_client.go | 19 ++-- src/crypto/tls/handshake_client_tls13.go | 21 ++++ src/crypto/tls/handshake_server.go | 5 +- src/crypto/tls/handshake_server_tls13.go | 22 ++++ src/crypto/tls/metrics_test.go | 132 +++++++++++++++++++++++ src/crypto/tls/tls_cf.go | 96 +++++++++++++++++ src/crypto/tls/tls_cf_test.go | 19 ++++ src/crypto/tls/tls_test.go | 4 +- 10 files changed, 340 insertions(+), 10 deletions(-) create mode 100644 src/crypto/tls/metrics_test.go create mode 100644 src/crypto/tls/tls_cf_test.go diff --git a/src/crypto/tls/common.go b/src/crypto/tls/common.go index b2580d232bc..df320dc3d29 100644 --- a/src/crypto/tls/common.go +++ b/src/crypto/tls/common.go @@ -277,6 +277,13 @@ type ConnectionState struct { // RFC 7627, and https://mitls.org/pages/attacks/3SHAKE#channelbindings. TLSUnique []byte + // CFControl is used to pass additional TLS configuration information to + // HTTP requests. + // + // NOTE: This feature is used to implement Cloudflare-internal features. + // This feature is unstable and applications MUST NOT depend on it. + CFControl interface{} + // ekm is a closure exposed via ExportKeyingMaterial. ekm func(label string, context []byte, length int) ([]byte, error) } @@ -689,6 +696,21 @@ type Config struct { // used for debugging. KeyLogWriter io.Writer + // CFEventHandler, if set, is called by the client and server at various + // points during the handshake to handle specific events. This is used + // primarily for collecting metrics. + // + // NOTE: This feature is used to implement Cloudflare-internal features. + // This feature is unstable and applications MUST NOT depend on it. + CFEventHandler func(event CFEvent) + + // CFControl is used to pass additional TLS configuration information to + // HTTP requests via ConnectionState. + // + // NOTE: This feature is used to implement Cloudflare-internal features. + // This feature is unstable and applications MUST NOT depend on it. + CFControl interface{} + // mutex protects sessionTicketKeys and autoSessionTicketKeys. mutex sync.RWMutex // sessionTicketKeys contains zero or more ticket keys. If set, it means the @@ -778,6 +800,8 @@ func (c *Config) Clone() *Config { DynamicRecordSizingDisabled: c.DynamicRecordSizingDisabled, Renegotiation: c.Renegotiation, KeyLogWriter: c.KeyLogWriter, + CFEventHandler: c.CFEventHandler, + CFControl: c.CFControl, sessionTicketKeys: c.sessionTicketKeys, autoSessionTicketKeys: c.autoSessionTicketKeys, } diff --git a/src/crypto/tls/conn.go b/src/crypto/tls/conn.go index 72ad52c194b..1fda8b24e43 100644 --- a/src/crypto/tls/conn.go +++ b/src/crypto/tls/conn.go @@ -1335,6 +1335,7 @@ func (c *Conn) Close() error { if err := c.conn.Close(); err != nil { return err } + return alertErr } @@ -1424,6 +1425,7 @@ func (c *Conn) connectionStateLocked() ConnectionState { state.VerifiedChains = c.verifiedChains state.SignedCertificateTimestamps = c.scts state.OCSPResponse = c.ocspResponse + state.CFControl = c.config.CFControl if !c.didResume && c.vers != VersionTLS13 { if c.clientFinishedIsFirst { state.TLSUnique = c.clientFinished[:] @@ -1469,3 +1471,9 @@ func (c *Conn) VerifyHostname(host string) error { func (c *Conn) handshakeComplete() bool { return atomic.LoadUint32(&c.handshakeStatus) == 1 } + +func (c *Conn) handleCFEvent(event CFEvent) { + if c.config.CFEventHandler != nil { + c.config.CFEventHandler(event) + } +} diff --git a/src/crypto/tls/handshake_client.go b/src/crypto/tls/handshake_client.go index 773bd4fed10..258123c11c7 100644 --- a/src/crypto/tls/handshake_client.go +++ b/src/crypto/tls/handshake_client.go @@ -141,6 +141,8 @@ func (c *Conn) clientHandshake() (err error) { c.config = defaultConfig() } + handshakeTimings := createTLS13ClientHandshakeTimingInfo(c.config.Time) + // This may be a renegotiation handshake, in which case some fields // need to be reset. c.didResume = false @@ -170,6 +172,8 @@ func (c *Conn) clientHandshake() (err error) { return err } + handshakeTimings.WriteClientHello = handshakeTimings.elapsedTime() + msg, err := c.readHandshake() if err != nil { return err @@ -199,13 +203,14 @@ func (c *Conn) clientHandshake() (err error) { if c.vers == VersionTLS13 { hs := &clientHandshakeStateTLS13{ - c: c, - serverHello: serverHello, - hello: hello, - ecdheParams: ecdheParams, - session: session, - earlySecret: earlySecret, - binderKey: binderKey, + c: c, + serverHello: serverHello, + hello: hello, + ecdheParams: ecdheParams, + session: session, + earlySecret: earlySecret, + binderKey: binderKey, + handshakeTimings: handshakeTimings, } // In TLS 1.3, session tickets are delivered after the handshake. diff --git a/src/crypto/tls/handshake_client_tls13.go b/src/crypto/tls/handshake_client_tls13.go index daa5d97fd35..ee7fa39107d 100644 --- a/src/crypto/tls/handshake_client_tls13.go +++ b/src/crypto/tls/handshake_client_tls13.go @@ -32,6 +32,8 @@ type clientHandshakeStateTLS13 struct { transcript hash.Hash masterSecret []byte trafficSecret []byte // client_application_traffic_secret_0 + + handshakeTimings CFEventTLS13ClientHandshakeTimingInfo } // handshake requires hs.c, hs.hello, hs.serverHello, hs.ecdheParams, and, @@ -98,6 +100,7 @@ func (hs *clientHandshakeStateTLS13) handshake() error { return err } + c.handleCFEvent(hs.handshakeTimings) atomic.StoreUint32(&c.handshakeStatus, 1) return nil @@ -285,6 +288,10 @@ func (hs *clientHandshakeStateTLS13) processHelloRetryRequest() error { func (hs *clientHandshakeStateTLS13) processServerHello() error { c := hs.c + defer func() { + hs.handshakeTimings.ProcessServerHello = hs.handshakeTimings.elapsedTime() + }() + if bytes.Equal(hs.serverHello.random, helloRetryRequestRandom) { c.sendAlert(alertUnexpectedMessage) return errors.New("tls: server sent two HelloRetryRequest messages") @@ -406,6 +413,8 @@ func (hs *clientHandshakeStateTLS13) readServerParameters() error { c.clientProtocol = encryptedExtensions.alpnProtocol } + hs.handshakeTimings.ReadEncryptedExtensions = hs.handshakeTimings.elapsedTime() + return nil } @@ -455,6 +464,8 @@ func (hs *clientHandshakeStateTLS13) readServerCertificate() error { } hs.transcript.Write(certMsg.marshal()) + hs.handshakeTimings.ReadCertificate = hs.handshakeTimings.elapsedTime() + c.scts = certMsg.certificate.SignedCertificateTimestamps c.ocspResponse = certMsg.certificate.OCSPStaple @@ -495,6 +506,8 @@ func (hs *clientHandshakeStateTLS13) readServerCertificate() error { hs.transcript.Write(certVerify.marshal()) + hs.handshakeTimings.ReadCertificateVerify = hs.handshakeTimings.elapsedTime() + return nil } @@ -512,6 +525,8 @@ func (hs *clientHandshakeStateTLS13) readServerFinished() error { return unexpectedMessageError(finished, msg) } + hs.handshakeTimings.ReadServerFinished = hs.handshakeTimings.elapsedTime() + expectedMAC := hs.suite.finishedHash(c.in.trafficSecret, hs.transcript) if !hmac.Equal(expectedMAC, finished.verifyData) { c.sendAlert(alertDecryptError) @@ -571,6 +586,8 @@ func (hs *clientHandshakeStateTLS13) sendClientCertificate() error { return err } + hs.handshakeTimings.WriteCertificate = hs.handshakeTimings.elapsedTime() + // If we sent an empty certificate message, skip the CertificateVerify. if len(cert.Certificate) == 0 { return nil @@ -609,6 +626,8 @@ func (hs *clientHandshakeStateTLS13) sendClientCertificate() error { return err } + hs.handshakeTimings.WriteCertificateVerify = hs.handshakeTimings.elapsedTime() + return nil } @@ -624,6 +643,8 @@ func (hs *clientHandshakeStateTLS13) sendClientFinished() error { return err } + hs.handshakeTimings.WriteClientFinished = hs.handshakeTimings.elapsedTime() + c.out.setTrafficSecret(hs.suite, hs.trafficSecret) if !c.config.SessionTicketsDisabled && c.config.ClientSessionCache != nil { diff --git a/src/crypto/tls/handshake_server.go b/src/crypto/tls/handshake_server.go index 0df9970278b..b6f51ec8cc4 100644 --- a/src/crypto/tls/handshake_server.go +++ b/src/crypto/tls/handshake_server.go @@ -47,8 +47,9 @@ func (c *Conn) serverHandshake() error { if c.vers == VersionTLS13 { hs := serverHandshakeStateTLS13{ - c: c, - clientHello: clientHello, + c: c, + clientHello: clientHello, + handshakeTimings: createTLS13ServerHandshakeTimingInfo(c.config.Time), } return hs.handshake() } diff --git a/src/crypto/tls/handshake_server_tls13.go b/src/crypto/tls/handshake_server_tls13.go index c2c288aed43..05e2a1c31a9 100644 --- a/src/crypto/tls/handshake_server_tls13.go +++ b/src/crypto/tls/handshake_server_tls13.go @@ -37,6 +37,8 @@ type serverHandshakeStateTLS13 struct { trafficSecret []byte // client_application_traffic_secret_0 transcript hash.Hash clientFinished []byte + + handshakeTimings CFEventTLS13ServerHandshakeTimingInfo } func (hs *serverHandshakeStateTLS13) handshake() error { @@ -75,6 +77,7 @@ func (hs *serverHandshakeStateTLS13) handshake() error { return err } + c.handleCFEvent(hs.handshakeTimings) atomic.StoreUint32(&c.handshakeStatus, 1) return nil @@ -233,6 +236,9 @@ GroupSelection: } c.serverName = hs.clientHello.serverName + + hs.handshakeTimings.ProcessClientHello = hs.handshakeTimings.elapsedTime() + return nil } @@ -534,6 +540,8 @@ func (hs *serverHandshakeStateTLS13) sendServerParameters() error { return err } + hs.handshakeTimings.WriteServerHello = hs.handshakeTimings.elapsedTime() + if err := hs.sendDummyChangeCipherSpec(); err != nil { return err } @@ -577,6 +585,8 @@ func (hs *serverHandshakeStateTLS13) sendServerParameters() error { return err } + hs.handshakeTimings.WriteEncryptedExtensions = hs.handshakeTimings.elapsedTime() + return nil } @@ -619,6 +629,8 @@ func (hs *serverHandshakeStateTLS13) sendServerCertificate() error { return err } + hs.handshakeTimings.WriteCertificate = hs.handshakeTimings.elapsedTime() + certVerifyMsg := new(certificateVerifyMsg) certVerifyMsg.hasSignatureAlgorithm = true certVerifyMsg.signatureAlgorithm = hs.sigAlg @@ -651,6 +663,8 @@ func (hs *serverHandshakeStateTLS13) sendServerCertificate() error { return err } + hs.handshakeTimings.WriteCertificateVerify = hs.handshakeTimings.elapsedTime() + return nil } @@ -666,6 +680,8 @@ func (hs *serverHandshakeStateTLS13) sendServerFinished() error { return err } + hs.handshakeTimings.WriteServerFinished = hs.handshakeTimings.elapsedTime() + // Derive secrets that take context through the server Finished. hs.masterSecret = hs.suite.extract(nil, @@ -803,6 +819,8 @@ func (hs *serverHandshakeStateTLS13) readClientCertificate() error { } } + hs.handshakeTimings.ReadCertificate = hs.handshakeTimings.elapsedTime() + if len(certMsg.certificate.Certificate) != 0 { msg, err = c.readHandshake() if err != nil { @@ -838,6 +856,8 @@ func (hs *serverHandshakeStateTLS13) readClientCertificate() error { hs.transcript.Write(certVerify.marshal()) } + hs.handshakeTimings.ReadCertificateVerify = hs.handshakeTimings.elapsedTime() + // If we waited until the client certificates to send session tickets, we // are ready to do it now. if err := hs.sendSessionTickets(); err != nil { @@ -866,6 +886,8 @@ func (hs *serverHandshakeStateTLS13) readClientFinished() error { return errors.New("tls: invalid client finished hash") } + hs.handshakeTimings.ReadClientFinished = hs.handshakeTimings.elapsedTime() + c.in.setTrafficSecret(hs.suite, hs.trafficSecret) return nil diff --git a/src/crypto/tls/metrics_test.go b/src/crypto/tls/metrics_test.go new file mode 100644 index 00000000000..10b09d1510a --- /dev/null +++ b/src/crypto/tls/metrics_test.go @@ -0,0 +1,132 @@ +// Copyright 2020 Cloudflare, Inc. All rights reserved. Use of this source code +// is governed by a BSD-style license that can be found in the LICENSE file. + +package tls + +import ( + "crypto/x509" + "fmt" + "io" + "io/ioutil" + "testing" + "time" +) + +type testTimingInfo struct { + serverTimingInfo CFEventTLS13ServerHandshakeTimingInfo + clientTimingInfo CFEventTLS13ClientHandshakeTimingInfo +} + +func (t testTimingInfo) isMonotonicallyIncreasing() bool { + serverIsMonotonicallyIncreasing := + t.serverTimingInfo.ProcessClientHello < t.serverTimingInfo.WriteServerHello && + t.serverTimingInfo.WriteServerHello < t.serverTimingInfo.WriteEncryptedExtensions && + t.serverTimingInfo.WriteEncryptedExtensions < t.serverTimingInfo.WriteCertificate && + t.serverTimingInfo.WriteCertificate < t.serverTimingInfo.WriteCertificateVerify && + t.serverTimingInfo.WriteCertificateVerify < t.serverTimingInfo.WriteServerFinished && + t.serverTimingInfo.WriteServerFinished < t.serverTimingInfo.ReadCertificate && + t.serverTimingInfo.ReadCertificate < t.serverTimingInfo.ReadCertificateVerify && + t.serverTimingInfo.ReadCertificateVerify < t.serverTimingInfo.ReadClientFinished + + clientIsMonotonicallyIncreasing := + t.clientTimingInfo.WriteClientHello < t.clientTimingInfo.ProcessServerHello && + t.clientTimingInfo.ProcessServerHello < t.clientTimingInfo.ReadEncryptedExtensions && + t.clientTimingInfo.ReadEncryptedExtensions < t.clientTimingInfo.ReadCertificate && + t.clientTimingInfo.ReadCertificate < t.clientTimingInfo.ReadCertificateVerify && + t.clientTimingInfo.ReadCertificateVerify < t.clientTimingInfo.ReadServerFinished && + t.clientTimingInfo.ReadServerFinished < t.clientTimingInfo.WriteCertificate && + t.clientTimingInfo.WriteCertificate < t.clientTimingInfo.WriteCertificateVerify && + t.clientTimingInfo.WriteCertificateVerify < t.clientTimingInfo.WriteClientFinished + + return (serverIsMonotonicallyIncreasing && clientIsMonotonicallyIncreasing) +} + +func (r *testTimingInfo) eventHandler(event CFEvent) { + switch e := event.(type) { + case CFEventTLS13ServerHandshakeTimingInfo: + r.serverTimingInfo = e + case CFEventTLS13ClientHandshakeTimingInfo: + r.clientTimingInfo = e + } +} + +func runHandshake(t *testing.T, clientConfig, serverConfig *Config) (timingState testTimingInfo, err error) { + const sentinel = "SENTINEL\n" + c, s := localPipe(t) + errChan := make(chan error) + + clientConfig.CFEventHandler = timingState.eventHandler + serverConfig.CFEventHandler = timingState.eventHandler + + go func() { + cli := Client(c, clientConfig) + err := cli.Handshake() + if err != nil { + errChan <- fmt.Errorf("client: %v", err) + c.Close() + return + } + defer cli.Close() + buf, err := ioutil.ReadAll(cli) + if err != nil { + t.Errorf("failed to call cli.Read: %v", err) + } + if got := string(buf); got != sentinel { + t.Errorf("read %q from TLS connection, but expected %q", got, sentinel) + } + errChan <- nil + }() + + server := Server(s, serverConfig) + err = server.Handshake() + if err == nil { + if _, err := io.WriteString(server, sentinel); err != nil { + t.Errorf("failed to call server.Write: %v", err) + } + if err := server.Close(); err != nil { + t.Errorf("failed to call server.Close: %v", err) + } + err = <-errChan + } else { + s.Close() + <-errChan + } + + return +} + +func TestTLS13HandshakeTiming(t *testing.T) { + issuer, err := x509.ParseCertificate(testRSACertificateIssuer) + if err != nil { + panic(err) + } + rootCAs := x509.NewCertPool() + rootCAs.AddCert(issuer) + + const serverName = "example.golang" + + baseConfig := &Config{ + Time: time.Now, + Rand: zeroSource{}, + Certificates: make([]Certificate, 1), + MaxVersion: VersionTLS13, + RootCAs: rootCAs, + ClientCAs: rootCAs, + ClientAuth: RequireAndVerifyClientCert, + ServerName: serverName, + } + baseConfig.Certificates[0].Certificate = [][]byte{testRSACertificate} + baseConfig.Certificates[0].PrivateKey = testRSAPrivateKey + + clientConfig := baseConfig.Clone() + serverConfig := baseConfig.Clone() + + ts, err := runHandshake(t, clientConfig, serverConfig) + if err != nil { + t.Fatalf("Handshake failed: %v", err) + } + + if !ts.isMonotonicallyIncreasing() { + t.Fatalf("Timing information is not monotonic") + } +} diff --git a/src/crypto/tls/tls_cf.go b/src/crypto/tls/tls_cf.go index 23317df541c..770d70e17fc 100644 --- a/src/crypto/tls/tls_cf.go +++ b/src/crypto/tls/tls_cf.go @@ -1,3 +1,6 @@ +// Copyright 2021 Cloudflare, Inc. All rights reserved. Use of this source code +// is governed by a BSD-style license that can be found in the LICENSE file. + package tls import ( @@ -5,6 +8,7 @@ import ( circlSign "circl/sign" "circl/sign/eddilithium3" + "time" ) // To add a signature scheme from Circl @@ -45,3 +49,95 @@ func init() { SignatureScheme(cs.scheme.(circlPki.TLSScheme).TLSIdentifier())) } } + +// CFEvent is a value emitted at various points in the handshake that is +// handled by the callback Config.CFEventHandler. +type CFEvent interface { + Name() string +} + +// CFEventTLS13ClientHandshakeTimingInfo carries intra-stack time durations for +// TLS 1.3 client-state machine changes. It can be used for tracking metrics +// during a connection. Some durations may be sensitive, such as the amount of +// time to process a particular handshake message, so this event should only be +// used for experimental purposes. +type CFEventTLS13ClientHandshakeTimingInfo struct { + timer func() time.Time + start time.Time + WriteClientHello time.Duration + ProcessServerHello time.Duration + ReadEncryptedExtensions time.Duration + ReadCertificate time.Duration + ReadCertificateVerify time.Duration + ReadServerFinished time.Duration + WriteCertificate time.Duration + WriteCertificateVerify time.Duration + WriteClientFinished time.Duration +} + +// Name is required by the CFEvent interface. +func (e CFEventTLS13ClientHandshakeTimingInfo) Name() string { + return "TLS13ClientHandshakeTimingInfo" +} + +func (e CFEventTLS13ClientHandshakeTimingInfo) elapsedTime() time.Duration { + if e.timer == nil { + return 0 + } + return e.timer().Sub(e.start) +} + +func createTLS13ClientHandshakeTimingInfo(timerFunc func() time.Time) CFEventTLS13ClientHandshakeTimingInfo { + timer := time.Now + if timerFunc != nil { + timer = timerFunc + } + + return CFEventTLS13ClientHandshakeTimingInfo{ + timer: timer, + start: timer(), + } +} + +// CFEventTLS13ServerHandshakeTimingInfo carries intra-stack time durations +// for TLS 1.3 state machine changes. It can be used for tracking metrics during a +// connection. Some durations may be sensitive, such as the amount of time to +// process a particular handshake message, so this event should only be used +// for experimental purposes. +type CFEventTLS13ServerHandshakeTimingInfo struct { + timer func() time.Time + start time.Time + ProcessClientHello time.Duration + WriteServerHello time.Duration + WriteEncryptedExtensions time.Duration + WriteCertificate time.Duration + WriteCertificateVerify time.Duration + WriteServerFinished time.Duration + ReadCertificate time.Duration + ReadCertificateVerify time.Duration + ReadClientFinished time.Duration +} + +// Name is required by the CFEvent interface. +func (e CFEventTLS13ServerHandshakeTimingInfo) Name() string { + return "TLS13ServerHandshakeTimingInfo" +} + +func (e CFEventTLS13ServerHandshakeTimingInfo) elapsedTime() time.Duration { + if e.timer == nil { + return 0 + } + return e.timer().Sub(e.start) +} + +func createTLS13ServerHandshakeTimingInfo(timerFunc func() time.Time) CFEventTLS13ServerHandshakeTimingInfo { + timer := time.Now + if timerFunc != nil { + timer = timerFunc + } + + return CFEventTLS13ServerHandshakeTimingInfo{ + timer: timer, + start: timer(), + } +} diff --git a/src/crypto/tls/tls_cf_test.go b/src/crypto/tls/tls_cf_test.go new file mode 100644 index 00000000000..53c3becf3df --- /dev/null +++ b/src/crypto/tls/tls_cf_test.go @@ -0,0 +1,19 @@ +package tls + +import ( + "testing" +) + +type testCFControl struct { + flags uint64 +} + +// Check that CFControl is correctly propagated from Config to ConnectionState. +func TestPropagateCFControl(t *testing.T) { + want := uint64(23) + s := Server(nil, &Config{CFControl: &testCFControl{want}}) + got := s.ConnectionState().CFControl.(*testCFControl).flags + if got != want { + t.Errorf("failed to propagate CFControl: got %v; want %v", got, want) + } +} diff --git a/src/crypto/tls/tls_test.go b/src/crypto/tls/tls_test.go index 9995538871e..ba7c1743148 100644 --- a/src/crypto/tls/tls_test.go +++ b/src/crypto/tls/tls_test.go @@ -789,7 +789,7 @@ func TestCloneNonFuncFields(t *testing.T) { switch fn := typ.Field(i).Name; fn { case "Rand": f.Set(reflect.ValueOf(io.Reader(os.Stdin))) - case "Time", "GetCertificate", "GetConfigForClient", "VerifyPeerCertificate", "VerifyConnection", "GetClientCertificate": + case "Time", "GetCertificate", "GetConfigForClient", "VerifyPeerCertificate", "VerifyConnection", "GetClientCertificate", "CFEventHandler": // DeepEqual can't compare functions. If you add a // function field to this list, you must also change // TestCloneFuncFields to ensure that the func field is @@ -826,6 +826,8 @@ func TestCloneNonFuncFields(t *testing.T) { f.Set(reflect.ValueOf(RenegotiateOnceAsClient)) case "mutex", "autoSessionTicketKeys", "sessionTicketKeys": continue // these are unexported fields that are handled separately + case "CFControl": + f.Set(reflect.ValueOf(&testCFControl{23})) default: t.Errorf("all fields must be accounted for, but saw unknown field %q", fn) }