add support for the key_updated event for TLS key updates

internal/handshake/crypto_setup.go

@@ -14,6 +14,7 @@ import (
 	"github.com/lucas-clemente/quic-go/internal/protocol"
 	"github.com/lucas-clemente/quic-go/internal/qerr"
 	"github.com/lucas-clemente/quic-go/internal/utils"
+	"github.com/lucas-clemente/quic-go/qlog"
 	"github.com/marten-seemann/qtls"
 )
 
@@ -90,7 +91,8 @@ type cryptoSetup struct {
 
 	rttStats *congestion.RTTStats
 
-	logger utils.Logger
+	qlogger qlog.Tracer
+	logger  utils.Logger
 
 	perspective protocol.Perspective
 
@@ -132,6 +134,7 @@ func NewCryptoSetupClient(
 	tlsConf *tls.Config,
 	enable0RTT bool,
 	rttStats *congestion.RTTStats,
+	qlogger qlog.Tracer,
 	logger utils.Logger,
 ) (CryptoSetup, <-chan *TransportParameters /* ClientHello written. Receive nil for non-0-RTT */) {
 	cs, clientHelloWritten := newCryptoSetup(
@@ -143,6 +146,7 @@ func NewCryptoSetupClient(
 		tlsConf,
 		enable0RTT,
 		rttStats,
+		qlogger,
 		logger,
 		protocol.PerspectiveClient,
 	)
@@ -162,6 +166,7 @@ func NewCryptoSetupServer(
 	tlsConf *tls.Config,
 	enable0RTT bool,
 	rttStats *congestion.RTTStats,
+	qlogger qlog.Tracer,
 	logger utils.Logger,
 ) CryptoSetup {
 	cs, _ := newCryptoSetup(
@@ -173,6 +178,7 @@ func NewCryptoSetupServer(
 		tlsConf,
 		enable0RTT,
 		rttStats,
+		qlogger,
 		logger,
 		protocol.PerspectiveServer,
 	)
@@ -189,10 +195,16 @@ func newCryptoSetup(
 	tlsConf *tls.Config,
 	enable0RTT bool,
 	rttStats *congestion.RTTStats,
+	qlogger qlog.Tracer,
 	logger utils.Logger,
 	perspective protocol.Perspective,
 ) (*cryptoSetup, <-chan *TransportParameters /* ClientHello written. Receive nil for non-0-RTT */) {
 	initialSealer, initialOpener := NewInitialAEAD(connID, perspective)
+	if qlogger != nil {
+		now := time.Now()
+		qlogger.UpdatedKeyFromTLS(now, protocol.EncryptionInitial, protocol.PerspectiveClient)
+		qlogger.UpdatedKeyFromTLS(now, protocol.EncryptionInitial, protocol.PerspectiveServer)
+	}
 	extHandler := newExtensionHandler(tp.Marshal(), perspective)
 	cs := &cryptoSetup{
 		initialStream:          initialStream,
@@ -206,6 +218,7 @@ func newCryptoSetup(
 		ourParams:              tp,
 		paramsChan:             extHandler.TransportParameters(),
 		rttStats:               rttStats,
+		qlogger:                qlogger,
 		logger:                 logger,
 		perspective:            perspective,
 		handshakeDone:          make(chan struct{}),
@@ -226,6 +239,11 @@ func (h *cryptoSetup) ChangeConnectionID(id protocol.ConnectionID) {
 	initialSealer, initialOpener := NewInitialAEAD(id, h.perspective)
 	h.initialSealer = initialSealer
 	h.initialOpener = initialOpener
+	if h.qlogger != nil {
+		now := time.Now()
+		h.qlogger.UpdatedKeyFromTLS(now, protocol.EncryptionInitial, protocol.PerspectiveClient)
+		h.qlogger.UpdatedKeyFromTLS(now, protocol.EncryptionInitial, protocol.PerspectiveServer)
+	}
 }
 
 func (h *cryptoSetup) SetLargest1RTTAcked(pn protocol.PacketNumber) {
@@ -563,6 +581,9 @@ func (h *cryptoSetup) SetReadKey(encLevel qtls.EncryptionLevel, suite *qtls.Ciph
 		)
 		h.mutex.Unlock()
 		h.logger.Debugf("Installed 0-RTT Read keys (using %s)", qtls.CipherSuiteName(suite.ID))
+		if h.qlogger != nil {
+			h.qlogger.UpdatedKeyFromTLS(time.Now(), protocol.Encryption0RTT, h.perspective.Opposite())
+		}
 		return
 	case qtls.EncryptionHandshake:
 		h.readEncLevel = protocol.EncryptionHandshake
@@ -582,6 +603,9 @@ func (h *cryptoSetup) SetReadKey(encLevel qtls.EncryptionLevel, suite *qtls.Ciph
 		panic("unexpected read encryption level")
 	}
 	h.mutex.Unlock()
+	if h.qlogger != nil {
+		h.qlogger.UpdatedKeyFromTLS(time.Now(), h.readEncLevel, h.perspective.Opposite())
+	}
 	h.receivedReadKey <- struct{}{}
 }
 
@@ -598,6 +622,9 @@ func (h *cryptoSetup) SetWriteKey(encLevel qtls.EncryptionLevel, suite *qtls.Cip
 		)
 		h.mutex.Unlock()
 		h.logger.Debugf("Installed 0-RTT Write keys (using %s)", qtls.CipherSuiteName(suite.ID))
+		if h.qlogger != nil {
+			h.qlogger.UpdatedKeyFromTLS(time.Now(), protocol.Encryption0RTT, h.perspective)
+		}
 		return
 	case qtls.EncryptionHandshake:
 		h.writeEncLevel = protocol.EncryptionHandshake
@@ -621,6 +648,9 @@ func (h *cryptoSetup) SetWriteKey(encLevel qtls.EncryptionLevel, suite *qtls.Cip
 		panic("unexpected write encryption level")
 	}
 	h.mutex.Unlock()
+	if h.qlogger != nil {
+		h.qlogger.UpdatedKeyFromTLS(time.Now(), h.writeEncLevel, h.perspective)
+	}
 	h.receivedWriteKey <- struct{}{}
 }
 

internal/handshake/crypto_setup_test.go

@@ -95,6 +95,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 			tlsConf,
 			false,
 			&congestion.RTTStats{},
+			nil,
 			utils.DefaultLogger.WithPrefix("server"),
 		)
 		qtlsConf := server.(*cryptoSetup).tlsConf
@@ -127,6 +128,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 			testdata.GetTLSConfig(),
 			false,
 			&congestion.RTTStats{},
+			nil,
 			utils.DefaultLogger.WithPrefix("server"),
 		)
 
@@ -165,6 +167,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 			testdata.GetTLSConfig(),
 			false,
 			&congestion.RTTStats{},
+			nil,
 			utils.DefaultLogger.WithPrefix("server"),
 		)
 
@@ -206,6 +209,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 			serverConf,
 			false,
 			&congestion.RTTStats{},
+			nil,
 			utils.DefaultLogger.WithPrefix("server"),
 		)
 
@@ -240,6 +244,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 			serverConf,
 			false,
 			&congestion.RTTStats{},
+			nil,
 			utils.DefaultLogger.WithPrefix("server"),
 		)
 
@@ -334,6 +339,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 				clientConf,
 				enable0RTT,
 				&congestion.RTTStats{},
+				nil,
 				utils.DefaultLogger.WithPrefix("client"),
 			)
 
@@ -356,6 +362,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 				serverConf,
 				enable0RTT,
 				&congestion.RTTStats{},
+				nil,
 				utils.DefaultLogger.WithPrefix("server"),
 			)
 
@@ -409,6 +416,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 				&tls.Config{InsecureSkipVerify: true},
 				false,
 				&congestion.RTTStats{},
+				nil,
 				utils.DefaultLogger.WithPrefix("client"),
 			)
 
@@ -450,6 +458,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 				clientConf,
 				false,
 				&congestion.RTTStats{},
+				nil,
 				utils.DefaultLogger.WithPrefix("client"),
 			)
 
@@ -473,6 +482,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 				serverConf,
 				false,
 				&congestion.RTTStats{},
+				nil,
 				utils.DefaultLogger.WithPrefix("server"),
 			)
 
@@ -505,6 +515,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 					clientConf,
 					false,
 					&congestion.RTTStats{},
+					nil,
 					utils.DefaultLogger.WithPrefix("client"),
 				)
 
@@ -523,6 +534,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 					serverConf,
 					false,
 					&congestion.RTTStats{},
+					nil,
 					utils.DefaultLogger.WithPrefix("server"),
 				)
 
@@ -562,6 +574,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 					clientConf,
 					false,
 					&congestion.RTTStats{},
+					nil,
 					utils.DefaultLogger.WithPrefix("client"),
 				)
 
@@ -580,6 +593,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 					serverConf,
 					false,
 					&congestion.RTTStats{},
+					nil,
 					utils.DefaultLogger.WithPrefix("server"),
 				)
 
@@ -691,6 +705,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 					clientConf,
 					true,
 					&congestion.RTTStats{},
+					nil,
 					utils.DefaultLogger.WithPrefix("client"),
 				)
 
@@ -709,6 +724,7 @@ var _ = Describe("Crypto Setup TLS", func() {
 					serverConf,
 					true,
 					&congestion.RTTStats{},
+					nil,
 					utils.DefaultLogger.WithPrefix("server"),
 				)
 

qlog/event.go

@@ -196,3 +196,20 @@ func (e eventPacketLost) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.StringKey("packet_number", toString(int64(e.PacketNumber)))
 	enc.StringKey("trigger", e.Trigger.String())
 }
+
+type eventKeyUpdated struct {
+	Trigger    string
+	KeyType    keyType
+	Generation uint64
+	// we don't log the keys here, so we don't need `old` and `new`.
+}
+
+func (e eventKeyUpdated) Category() category { return categorySecurity }
+func (e eventKeyUpdated) Name() string       { return "key_updated" }
+func (e eventKeyUpdated) IsNil() bool        { return false }
+
+func (e eventKeyUpdated) MarshalJSONObject(enc *gojay.Encoder) {
+	enc.StringKey("trigger", e.Trigger)
+	enc.StringKey("key_type", e.KeyType.String())
+	enc.Uint64KeyOmitEmpty("generation", e.Generation)
+}

qlog/qlog.go

@@ -21,6 +21,7 @@ type Tracer interface {
 	ReceivedPacket(t time.Time, hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, frames []wire.Frame)
 	UpdatedMetrics(t time.Time, rttStats *congestion.RTTStats, cwnd protocol.ByteCount, bytesInFLight protocol.ByteCount, packetsInFlight int)
 	LostPacket(time.Time, protocol.EncryptionLevel, protocol.PacketNumber, PacketLossReason)
+	UpdatedKeyFromTLS(time.Time, protocol.EncryptionLevel, protocol.Perspective)
 }
 
 type tracer struct {
@@ -159,3 +160,13 @@ func (t *tracer) LostPacket(time time.Time, encLevel protocol.EncryptionLevel, p
 		},
 	})
 }
+
+func (t *tracer) UpdatedKeyFromTLS(time time.Time, encLevel protocol.EncryptionLevel, pers protocol.Perspective) {
+	t.events = append(t.events, event{
+		Time: time,
+		eventDetails: eventKeyUpdated{
+			Trigger: "tls",
+			KeyType: encLevelToKeyType(encLevel, pers),
+		},
+	})
+}

qlog/qlog_test.go

@@ -263,5 +263,19 @@ var _ = Describe("Tracer", func() {
 			Expect(ev).To(HaveKeyWithValue("packet_number", "42"))
 			Expect(ev).To(HaveKeyWithValue("trigger", "reordering_threshold"))
 		})
+
+		It("records TLS key updates", func() {
+			now := time.Now()
+			tracer.UpdatedKeyFromTLS(now, protocol.EncryptionHandshake, protocol.PerspectiveClient)
+			t, category, eventName, ev := exportAndParse()
+			Expect(t).To(BeTemporally("~", now, time.Millisecond))
+			Expect(category).To(Equal("security"))
+			Expect(eventName).To(Equal("key_updated"))
+			Expect(ev).To(HaveKeyWithValue("key_type", "client_handshake_secret"))
+			Expect(ev).To(HaveKeyWithValue("trigger", "tls"))
+			Expect(ev).ToNot(HaveKey("generation"))
+			Expect(ev).ToNot(HaveKey("old"))
+			Expect(ev).ToNot(HaveKey("new"))
+		})
 	})
 })

qlog/types.go

@@ -110,3 +110,68 @@ func (r PacketLossReason) String() string {
 		panic("unknown loss reason")
 	}
 }
+
+type keyType uint8
+
+const (
+	keyTypeServerInitial keyType = iota
+	keyTypeClientInitial
+	keyTypeServerHandshake
+	keyTypeClientHandshake
+	keyTypeServer0RTT
+	keyTypeClient0RTT
+	keyTypeServer1RTT
+	keyTypeClient1RTT
+)
+
+func encLevelToKeyType(encLevel protocol.EncryptionLevel, pers protocol.Perspective) keyType {
+	if pers == protocol.PerspectiveServer {
+		switch encLevel {
+		case protocol.EncryptionInitial:
+			return keyTypeServerInitial
+		case protocol.EncryptionHandshake:
+			return keyTypeServerHandshake
+		case protocol.Encryption0RTT:
+			return keyTypeServer0RTT
+		case protocol.Encryption1RTT:
+			return keyTypeServer1RTT
+		default:
+			panic("unknown encryption level")
+		}
+	}
+	switch encLevel {
+	case protocol.EncryptionInitial:
+		return keyTypeClientInitial
+	case protocol.EncryptionHandshake:
+		return keyTypeClientHandshake
+	case protocol.Encryption0RTT:
+		return keyTypeClient0RTT
+	case protocol.Encryption1RTT:
+		return keyTypeClient1RTT
+	default:
+		panic("unknown encryption level")
+	}
+}
+
+func (t keyType) String() string {
+	switch t {
+	case keyTypeServerInitial:
+		return "server_initial_secret"
+	case keyTypeClientInitial:
+		return "client_initial_secret"
+	case keyTypeServerHandshake:
+		return "server_handshake_secret"
+	case keyTypeClientHandshake:
+		return "client_handshake_secret"
+	case keyTypeServer0RTT:
+		return "server_0rtt_secret"
+	case keyTypeClient0RTT:
+		return "client_0rtt_secret"
+	case keyTypeServer1RTT:
+		return "server_1rtt_secret"
+	case keyTypeClient1RTT:
+		return "client_1rtt_secret"
+	default:
+		panic("unknown key type")
+	}
+}

qlog/types_test.go

@@ -1,6 +1,7 @@
 package qlog
 
 import (
+	"github.com/lucas-clemente/quic-go/internal/protocol"
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
 )
@@ -21,4 +22,15 @@ var _ = Describe("Types", func() {
 		Expect(packetTypeRetry.String()).To(Equal("retry"))
 		Expect(packetTypeVersionNegotiation.String()).To(Equal("version_negotiation"))
 	})
+
+	It("has a string representation for the key type", func() {
+		Expect(encLevelToKeyType(protocol.EncryptionInitial, protocol.PerspectiveClient).String()).To(Equal("client_initial_secret"))
+		Expect(encLevelToKeyType(protocol.EncryptionInitial, protocol.PerspectiveServer).String()).To(Equal("server_initial_secret"))
+		Expect(encLevelToKeyType(protocol.EncryptionHandshake, protocol.PerspectiveClient).String()).To(Equal("client_handshake_secret"))
+		Expect(encLevelToKeyType(protocol.EncryptionHandshake, protocol.PerspectiveServer).String()).To(Equal("server_handshake_secret"))
+		Expect(encLevelToKeyType(protocol.Encryption0RTT, protocol.PerspectiveClient).String()).To(Equal("client_0rtt_secret"))
+		Expect(encLevelToKeyType(protocol.Encryption0RTT, protocol.PerspectiveServer).String()).To(Equal("server_0rtt_secret"))
+		Expect(encLevelToKeyType(protocol.Encryption1RTT, protocol.PerspectiveClient).String()).To(Equal("client_1rtt_secret"))
+		Expect(encLevelToKeyType(protocol.Encryption1RTT, protocol.PerspectiveServer).String()).To(Equal("server_1rtt_secret"))
+	})
 })

session.go

@@ -294,6 +294,7 @@ var newSession = func(
 		tlsConf,
 		enable0RTT,
 		s.rttStats,
+		qlogger,
 		logger,
 	)
 	s.cryptoStreamHandler = cs
@@ -402,6 +403,7 @@ var newClientSession = func(
 		tlsConf,
 		enable0RTT,
 		s.rttStats,
+		qlogger,
 		logger,
 	)
 	s.clientHelloWritten = clientHelloWritten