crypto/tls: add Config.CFEventHandler to expose intra-handshake timing

Add basic support for handshake metrics:

* Adds a `CFEventHandler()` callback to `Config` which can be called at
  various points during the handshake to respond to various events.
* Use this callback to expose 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.

Author: Christopher Wood

src/crypto/tls/common.go

@@ -737,6 +737,14 @@ 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.
 	//
@@ -834,6 +842,7 @@ 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,

src/crypto/tls/conn.go

@@ -1542,3 +1542,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)
+	}
+}

src/crypto/tls/handshake_client.go

@@ -149,6 +149,8 @@ func (c *Conn) clientHandshake(ctx context.Context) (err error) {
 		c.config = defaultConfig()
 	}
 
+	hsTimings := createTLS13ClientHandshakeTimingInfo(c.config.Time)
+
 	// This may be a renegotiation handshake, in which case some fields
 	// need to be reset.
 	c.didResume = false
@@ -178,6 +180,8 @@ func (c *Conn) clientHandshake(ctx context.Context) (err error) {
 		return err
 	}
 
+	hsTimings.WriteClientHello = hsTimings.elapsedTime()
+
 	msg, err := c.readHandshake()
 	if err != nil {
 		return err
@@ -215,6 +219,7 @@ func (c *Conn) clientHandshake(ctx context.Context) (err error) {
 			session:     session,
 			earlySecret: earlySecret,
 			binderKey:   binderKey,
+			hsTimings:   hsTimings,
 		}
 
 		// In TLS 1.3, session tickets are delivered after the handshake.

src/crypto/tls/handshake_client_tls13.go

@@ -34,6 +34,8 @@ type clientHandshakeStateTLS13 struct {
 	transcript    hash.Hash
 	masterSecret  []byte
 	trafficSecret []byte // client_application_traffic_secret_0
+
+	hsTimings CFEventTLS13ClientHandshakeTimingInfo
 }
 
 // handshake requires hs.c, hs.hello, hs.serverHello, hs.ecdheParams, and,
@@ -100,6 +102,7 @@ func (hs *clientHandshakeStateTLS13) handshake() error {
 		return err
 	}
 
+	c.handleCFEvent(hs.hsTimings)
 	atomic.StoreUint32(&c.handshakeStatus, 1)
 
 	return nil
@@ -287,6 +290,10 @@ func (hs *clientHandshakeStateTLS13) processHelloRetryRequest() error {
 func (hs *clientHandshakeStateTLS13) processServerHello() error {
 	c := hs.c
 
+	defer func() {
+		hs.hsTimings.ProcessServerHello = hs.hsTimings.elapsedTime()
+	}()
+
 	if bytes.Equal(hs.serverHello.random, helloRetryRequestRandom) {
 		c.sendAlert(alertUnexpectedMessage)
 		return errors.New("tls: server sent two HelloRetryRequest messages")
@@ -402,6 +409,8 @@ func (hs *clientHandshakeStateTLS13) readServerParameters() error {
 	}
 	c.clientProtocol = encryptedExtensions.alpnProtocol
 
+	hs.hsTimings.ReadEncryptedExtensions = hs.hsTimings.elapsedTime()
+
 	return nil
 }
 
@@ -451,6 +460,8 @@ func (hs *clientHandshakeStateTLS13) readServerCertificate() error {
 	}
 	hs.transcript.Write(certMsg.marshal())
 
+	hs.hsTimings.ReadCertificate = hs.hsTimings.elapsedTime()
+
 	c.scts = certMsg.certificate.SignedCertificateTimestamps
 	c.ocspResponse = certMsg.certificate.OCSPStaple
 
@@ -491,6 +502,8 @@ func (hs *clientHandshakeStateTLS13) readServerCertificate() error {
 
 	hs.transcript.Write(certVerify.marshal())
 
+	hs.hsTimings.ReadCertificateVerify = hs.hsTimings.elapsedTime()
+
 	return nil
 }
 
@@ -508,6 +521,8 @@ func (hs *clientHandshakeStateTLS13) readServerFinished() error {
 		return unexpectedMessageError(finished, msg)
 	}
 
+	hs.hsTimings.ReadServerFinished = hs.hsTimings.elapsedTime()
+
 	expectedMAC := hs.suite.finishedHash(c.in.trafficSecret, hs.transcript)
 	if !hmac.Equal(expectedMAC, finished.verifyData) {
 		c.sendAlert(alertDecryptError)
@@ -568,6 +583,8 @@ func (hs *clientHandshakeStateTLS13) sendClientCertificate() error {
 		return err
 	}
 
+	hs.hsTimings.WriteCertificate = hs.hsTimings.elapsedTime()
+
 	// If we sent an empty certificate message, skip the CertificateVerify.
 	if len(cert.Certificate) == 0 {
 		return nil
@@ -606,6 +623,8 @@ func (hs *clientHandshakeStateTLS13) sendClientCertificate() error {
 		return err
 	}
 
+	hs.hsTimings.WriteCertificateVerify = hs.hsTimings.elapsedTime()
+
 	return nil
 }
 
@@ -621,6 +640,8 @@ func (hs *clientHandshakeStateTLS13) sendClientFinished() error {
 		return err
 	}
 
+	hs.hsTimings.WriteClientFinished = hs.hsTimings.elapsedTime()
+
 	c.out.setTrafficSecret(hs.suite, hs.trafficSecret)
 
 	if !c.config.SessionTicketsDisabled && c.config.ClientSessionCache != nil {

src/crypto/tls/handshake_server.go

@@ -52,6 +52,7 @@ func (c *Conn) serverHandshake(ctx context.Context) error {
 			c:           c,
 			ctx:         ctx,
 			clientHello: clientHello,
+			hsTimings:   createTLS13ServerHandshakeTimingInfo(c.config.Time),
 		}
 		return hs.handshake()
 	}

src/crypto/tls/handshake_server_tls13.go

@@ -40,6 +40,8 @@ type serverHandshakeStateTLS13 struct {
 	trafficSecret   []byte // client_application_traffic_secret_0
 	transcript      hash.Hash
 	clientFinished  []byte
+
+	hsTimings CFEventTLS13ServerHandshakeTimingInfo
 }
 
 func (hs *serverHandshakeStateTLS13) handshake() error {
@@ -78,6 +80,7 @@ func (hs *serverHandshakeStateTLS13) handshake() error {
 		return err
 	}
 
+	c.handleCFEvent(hs.hsTimings)
 	atomic.StoreUint32(&c.handshakeStatus, 1)
 
 	return nil
@@ -219,6 +222,9 @@ GroupSelection:
 	}
 
 	c.serverName = hs.clientHello.serverName
+
+	hs.hsTimings.ProcessClientHello = hs.hsTimings.elapsedTime()
+
 	return nil
 }
 
@@ -520,6 +526,8 @@ func (hs *serverHandshakeStateTLS13) sendServerParameters() error {
 		return err
 	}
 
+	hs.hsTimings.WriteServerHello = hs.hsTimings.elapsedTime()
+
 	if err := hs.sendDummyChangeCipherSpec(); err != nil {
 		return err
 	}
@@ -564,6 +572,8 @@ func (hs *serverHandshakeStateTLS13) sendServerParameters() error {
 		return err
 	}
 
+	hs.hsTimings.WriteEncryptedExtensions = hs.hsTimings.elapsedTime()
+
 	return nil
 }
 
@@ -606,6 +616,8 @@ func (hs *serverHandshakeStateTLS13) sendServerCertificate() error {
 		return err
 	}
 
+	hs.hsTimings.WriteCertificate = hs.hsTimings.elapsedTime()
+
 	certVerifyMsg := new(certificateVerifyMsg)
 	certVerifyMsg.hasSignatureAlgorithm = true
 	certVerifyMsg.signatureAlgorithm = hs.sigAlg
@@ -638,6 +650,8 @@ func (hs *serverHandshakeStateTLS13) sendServerCertificate() error {
 		return err
 	}
 
+	hs.hsTimings.WriteCertificateVerify = hs.hsTimings.elapsedTime()
+
 	return nil
 }
 
@@ -653,6 +667,8 @@ func (hs *serverHandshakeStateTLS13) sendServerFinished() error {
 		return err
 	}
 
+	hs.hsTimings.WriteServerFinished = hs.hsTimings.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.hsTimings.ReadCertificate = hs.hsTimings.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.hsTimings.ReadCertificateVerify = hs.hsTimings.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.hsTimings.ReadClientFinished = hs.hsTimings.elapsedTime()
+
 	c.in.setTrafficSecret(hs.suite, hs.trafficSecret)
 
 	return nil

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")
+	}
+}