qlog key updates

internal/handshake/crypto_setup.go

@@ -211,7 +211,7 @@ func newCryptoSetup(
 		initialSealer:          initialSealer,
 		initialOpener:          initialOpener,
 		handshakeStream:        handshakeStream,
-		aead:                   newUpdatableAEAD(rttStats, logger),
+		aead:                   newUpdatableAEAD(rttStats, qlogger, logger),
 		readEncLevel:           protocol.EncryptionInitial,
 		writeEncLevel:          protocol.EncryptionInitial,
 		runner:                 runner,

internal/handshake/updatable_aead.go

@@ -12,6 +12,7 @@ import (
 	"github.com/lucas-clemente/quic-go/internal/congestion"
 	"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/lucas-clemente/quic-go/internal/protocol"
 	"github.com/marten-seemann/qtls"
@@ -73,7 +74,8 @@ type updatableAEAD struct {
 
 	rttStats *congestion.RTTStats
 
-	logger utils.Logger
+	qlogger qlog.Tracer
+	logger  utils.Logger
 
 	// use a single slice to avoid allocations
 	nonceBuf []byte
@@ -82,7 +84,7 @@ type updatableAEAD struct {
 var _ ShortHeaderOpener = &updatableAEAD{}
 var _ ShortHeaderSealer = &updatableAEAD{}
 
-func newUpdatableAEAD(rttStats *congestion.RTTStats, logger utils.Logger) *updatableAEAD {
+func newUpdatableAEAD(rttStats *congestion.RTTStats, qlogger qlog.Tracer, logger utils.Logger) *updatableAEAD {
 	return &updatableAEAD{
 		firstPacketNumber:       protocol.InvalidPacketNumber,
 		largestAcked:            protocol.InvalidPacketNumber,
@@ -90,6 +92,7 @@ func newUpdatableAEAD(rttStats *congestion.RTTStats, logger utils.Logger) *updat
 		firstSentWithCurrentKey: protocol.InvalidPacketNumber,
 		keyUpdateInterval:       keyUpdateInterval,
 		rttStats:                rttStats,
+		qlogger:                 qlogger,
 		logger:                  logger,
 	}
 }
@@ -180,6 +183,9 @@ func (a *updatableAEAD) Open(dst, src []byte, rcvTime time.Time, pn protocol.Pac
 		}
 		a.rollKeys(rcvTime)
 		a.logger.Debugf("Peer updated keys to %s", a.keyPhase)
+		if a.qlogger != nil {
+			a.qlogger.UpdatedKey(rcvTime, a.keyPhase, true)
+		}
 		a.firstRcvdWithCurrentKey = pn
 		return dec, err
 	}
@@ -238,7 +244,11 @@ func (a *updatableAEAD) shouldInitiateKeyUpdate() bool {
 
 func (a *updatableAEAD) KeyPhase() protocol.KeyPhaseBit {
 	if a.shouldInitiateKeyUpdate() {
-		a.rollKeys(time.Now())
+		now := time.Now()
+		if a.qlogger != nil {
+			a.qlogger.UpdatedKey(now, a.keyPhase, false)
+		}
+		a.rollKeys(now)
 	}
 	return a.keyPhase.Bit()
 }

internal/handshake/updatable_aead_test.go

@@ -27,8 +27,8 @@ var _ = Describe("Updatable AEAD", func() {
 				rand.Read(trafficSecret1)
 				rand.Read(trafficSecret2)
 
-				client = newUpdatableAEAD(rttStats, utils.DefaultLogger)
+				client = newUpdatableAEAD(rttStats, nil, utils.DefaultLogger)
-				server = newUpdatableAEAD(rttStats, utils.DefaultLogger)
+				server = newUpdatableAEAD(rttStats, nil, utils.DefaultLogger)
 				client.SetReadKey(cs, trafficSecret2)
 				client.SetWriteKey(cs, trafficSecret1)
 				server.SetReadKey(cs, trafficSecret1)

qlog/event.go

@@ -210,9 +210,9 @@ func (e eventPacketLost) MarshalJSONObject(enc *gojay.Encoder) {
 }
 
 type eventKeyUpdated struct {
-	Trigger    string
+	Trigger    keyUpdateTrigger
 	KeyType    keyType
-	Generation uint64
+	Generation protocol.KeyPhase
 	// we don't log the keys here, so we don't need `old` and `new`.
 }
 
@@ -221,7 +221,7 @@ 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("trigger", e.Trigger.String())
 	enc.StringKey("key_type", e.KeyType.String())
-	enc.Uint64KeyOmitEmpty("generation", e.Generation)
+	enc.Uint64KeyOmitEmpty("generation", uint64(e.Generation))
 }

qlog/qlog.go

@@ -23,6 +23,7 @@ type Tracer interface {
 	LostPacket(time.Time, protocol.EncryptionLevel, protocol.PacketNumber, PacketLossReason)
 	UpdatedPTOCount(time.Time, uint32)
 	UpdatedKeyFromTLS(time.Time, protocol.EncryptionLevel, protocol.Perspective)
+	UpdatedKey(t time.Time, generation protocol.KeyPhase, remote bool)
 }
 
 type tracer struct {
@@ -162,19 +163,42 @@ 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),
-		},
-	})
-}
-
 func (t *tracer) UpdatedPTOCount(time time.Time, value uint32) {
 	t.events = append(t.events, event{
 		Time:         time,
 		eventDetails: eventUpdatedPTO{Value: value},
 	})
 }
+
+func (t *tracer) UpdatedKeyFromTLS(time time.Time, encLevel protocol.EncryptionLevel, pers protocol.Perspective) {
+	t.events = append(t.events, event{
+		Time: time,
+		eventDetails: eventKeyUpdated{
+			Trigger: keyUpdateTLS,
+			KeyType: encLevelToKeyType(encLevel, pers),
+		},
+	})
+}
+
+func (t *tracer) UpdatedKey(time time.Time, generation protocol.KeyPhase, remote bool) {
+	trigger := keyUpdateLocal
+	if remote {
+		trigger = keyUpdateRemote
+	}
+	t.events = append(t.events, event{
+		Time: time,
+		eventDetails: eventKeyUpdated{
+			Trigger:    trigger,
+			KeyType:    keyTypeClient1RTT,
+			Generation: generation,
+		},
+	})
+	t.events = append(t.events, event{
+		Time: time,
+		eventDetails: eventKeyUpdated{
+			Trigger:    trigger,
+			KeyType:    keyTypeServer1RTT,
+			Generation: generation,
+		},
+	})
+}

qlog/qlog_test.go

@@ -23,6 +23,13 @@ func nopWriteCloser(w io.Writer) io.WriteCloser {
 	return &nopWriteCloserImpl{Writer: w}
 }
 
+type entry struct {
+	Time     time.Time
+	Category string
+	Name     string
+	Event    map[string]interface{}
+}
+
 var _ = Describe("Tracer", func() {
 	var (
 		tracer Tracer
@@ -63,21 +70,34 @@ var _ = Describe("Tracer", func() {
 	})
 
 	Context("Events", func() {
-		exportAndParse := func() (time.Time, string /* category */, string /* event */, map[string]interface{}) {
+		exportAndParse := func() []entry {
 			Expect(tracer.Export()).To(Succeed())
 
 			m := make(map[string]interface{})
 			Expect(json.Unmarshal(buf.Bytes(), &m)).To(Succeed())
 			Expect(m).To(HaveKey("traces"))
+			var entries []entry
 			traces := m["traces"].([]interface{})
 			Expect(traces).To(HaveLen(1))
 			trace := traces[0].(map[string]interface{})
 			Expect(trace).To(HaveKey("events"))
-			events := trace["events"].([]interface{})
+			for _, e := range trace["events"].([]interface{}) {
-			Expect(events).To(HaveLen(1))
+				ev := e.([]interface{})
-			ev := events[0].([]interface{})
+				Expect(ev).To(HaveLen(4))
-			Expect(ev).To(HaveLen(4))
+				entries = append(entries, entry{
-			return time.Unix(0, int64(1e6*ev[0].(float64))), ev[1].(string), ev[2].(string), ev[3].(map[string]interface{})
+					Time:     time.Unix(0, int64(1e6*ev[0].(float64))),
+					Category: ev[1].(string),
+					Name:     ev[2].(string),
+					Event:    ev[3].(map[string]interface{}),
+				})
+			}
+			return entries
+		}
+
+		exportAndParseSingle := func() entry {
+			entries := exportAndParse()
+			Expect(entries).To(HaveLen(1))
+			return entries[0]
 		}
 
 		It("records connection starts", func() {
@@ -90,10 +110,11 @@ var _ = Describe("Tracer", func() {
 				protocol.ConnectionID{1, 2, 3, 4},
 				protocol.ConnectionID{5, 6, 7, 8},
 			)
-			t, category, eventName, ev := exportAndParse()
+			entry := exportAndParseSingle()
-			Expect(t).To(BeTemporally("~", now, time.Millisecond))
+			Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond))
-			Expect(category).To(Equal("transport"))
+			Expect(entry.Category).To(Equal("transport"))
-			Expect(eventName).To(Equal("connection_started"))
+			Expect(entry.Name).To(Equal("connection_started"))
+			ev := entry.Event
 			Expect(ev).To(HaveKeyWithValue("ip_version", "ipv4"))
 			Expect(ev).To(HaveKeyWithValue("src_ip", "192.168.13.37"))
 			Expect(ev).To(HaveKeyWithValue("src_port", float64(42)))
@@ -125,10 +146,11 @@ var _ = Describe("Tracer", func() {
 					&wire.StreamFrame{StreamID: 123, Offset: 1234, Data: []byte("foobar"), FinBit: true},
 				},
 			)
-			t, category, eventName, ev := exportAndParse()
+			entry := exportAndParseSingle()
-			Expect(t).To(BeTemporally("~", now, time.Millisecond))
+			Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond))
-			Expect(category).To(Equal("transport"))
+			Expect(entry.Category).To(Equal("transport"))
-			Expect(eventName).To(Equal("packet_sent"))
+			Expect(entry.Name).To(Equal("packet_sent"))
+			ev := entry.Event
 			Expect(ev).To(HaveKeyWithValue("packet_type", "handshake"))
 			Expect(ev).To(HaveKey("header"))
 			hdr := ev["header"].(map[string]interface{})
@@ -153,7 +175,8 @@ var _ = Describe("Tracer", func() {
 				&wire.AckFrame{AckRanges: []wire.AckRange{{Smallest: 1, Largest: 10}}},
 				[]wire.Frame{&wire.MaxDataFrame{ByteOffset: 987}},
 			)
-			_, _, _, ev := exportAndParse()
+			entry := exportAndParseSingle()
+			ev := entry.Event
 			Expect(ev).To(HaveKeyWithValue("packet_type", "1RTT"))
 			Expect(ev).To(HaveKey("header"))
 			Expect(ev).To(HaveKey("frames"))
@@ -183,10 +206,11 @@ var _ = Describe("Tracer", func() {
 					&wire.StreamFrame{StreamID: 123, Offset: 1234, Data: []byte("foobar"), FinBit: true},
 				},
 			)
-			t, category, eventName, ev := exportAndParse()
+			entry := exportAndParseSingle()
-			Expect(t).To(BeTemporally("~", now, time.Millisecond))
+			Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond))
-			Expect(category).To(Equal("transport"))
+			Expect(entry.Category).To(Equal("transport"))
-			Expect(eventName).To(Equal("packet_received"))
+			Expect(entry.Name).To(Equal("packet_received"))
+			ev := entry.Event
 			Expect(ev).To(HaveKeyWithValue("packet_type", "initial"))
 			Expect(ev).To(HaveKey("header"))
 			hdr := ev["header"].(map[string]interface{})
@@ -209,10 +233,11 @@ var _ = Describe("Tracer", func() {
 					Version:          protocol.VersionTLS,
 				},
 			)
-			t, category, eventName, ev := exportAndParse()
+			entry := exportAndParseSingle()
-			Expect(t).To(BeTemporally("~", now, time.Millisecond))
+			Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond))
-			Expect(category).To(Equal("transport"))
+			Expect(entry.Category).To(Equal("transport"))
-			Expect(eventName).To(Equal("packet_received"))
+			Expect(entry.Name).To(Equal("packet_received"))
+			ev := entry.Event
 			Expect(ev).To(HaveKeyWithValue("packet_type", "retry"))
 			Expect(ev).To(HaveKey("header"))
 			Expect(ev).ToNot(HaveKey("frames"))
@@ -237,10 +262,11 @@ var _ = Describe("Tracer", func() {
 				1234,
 				42,
 			)
-			t, category, eventName, ev := exportAndParse()
+			entry := exportAndParseSingle()
-			Expect(t).To(BeTemporally("~", now, time.Millisecond))
+			Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond))
-			Expect(category).To(Equal("recovery"))
+			Expect(entry.Category).To(Equal("recovery"))
-			Expect(eventName).To(Equal("metrics_updated"))
+			Expect(entry.Name).To(Equal("metrics_updated"))
+			ev := entry.Event
 			Expect(ev).To(HaveKeyWithValue("min_rtt", float64(15)))
 			Expect(ev).To(HaveKeyWithValue("latest_rtt", float64(25)))
 			Expect(ev).To(HaveKey("smoothed_rtt"))
@@ -255,22 +281,34 @@ var _ = Describe("Tracer", func() {
 		It("records lost packets", func() {
 			now := time.Now()
 			tracer.LostPacket(now, protocol.EncryptionHandshake, 42, PacketLossReorderingThreshold)
-			t, category, eventName, ev := exportAndParse()
+			entry := exportAndParseSingle()
-			Expect(t).To(BeTemporally("~", now, time.Millisecond))
+			Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond))
-			Expect(category).To(Equal("recovery"))
+			Expect(entry.Category).To(Equal("recovery"))
-			Expect(eventName).To(Equal("packet_lost"))
+			Expect(entry.Name).To(Equal("packet_lost"))
+			ev := entry.Event
 			Expect(ev).To(HaveKeyWithValue("packet_type", "handshake"))
 			Expect(ev).To(HaveKeyWithValue("packet_number", "42"))
 			Expect(ev).To(HaveKeyWithValue("trigger", "reordering_threshold"))
 		})
 
+		It("records PTO changes", func() {
+			now := time.Now()
+			tracer.UpdatedPTOCount(now, 42)
+			entry := exportAndParseSingle()
+			Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond))
+			Expect(entry.Category).To(Equal("recovery"))
+			Expect(entry.Name).To(Equal("metrics_updated"))
+			Expect(entry.Event).To(HaveKeyWithValue("pto_count", float64(42)))
+		})
+
 		It("records TLS key updates", func() {
 			now := time.Now()
 			tracer.UpdatedKeyFromTLS(now, protocol.EncryptionHandshake, protocol.PerspectiveClient)
-			t, category, eventName, ev := exportAndParse()
+			entry := exportAndParseSingle()
-			Expect(t).To(BeTemporally("~", now, time.Millisecond))
+			Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond))
-			Expect(category).To(Equal("security"))
+			Expect(entry.Category).To(Equal("security"))
-			Expect(eventName).To(Equal("key_updated"))
+			Expect(entry.Name).To(Equal("key_updated"))
+			ev := entry.Event
 			Expect(ev).To(HaveKeyWithValue("key_type", "client_handshake_secret"))
 			Expect(ev).To(HaveKeyWithValue("trigger", "tls"))
 			Expect(ev).ToNot(HaveKey("generation"))
@@ -278,14 +316,24 @@ var _ = Describe("Tracer", func() {
 			Expect(ev).ToNot(HaveKey("new"))
 		})
 
-		It("records PTO changes", func() {
+		It("records QUIC key udpates", func() {
 			now := time.Now()
-			tracer.UpdatedPTOCount(now, 42)
+			tracer.UpdatedKey(now, 1337, true)
-			t, category, eventName, ev := exportAndParse()
+			entries := exportAndParse()
-			Expect(t).To(BeTemporally("~", now, time.Millisecond))
+			Expect(entries).To(HaveLen(2))
-			Expect(category).To(Equal("recovery"))
+			var keyTypes []string
-			Expect(eventName).To(Equal("metrics_updated"))
+			for _, entry := range entries {
-			Expect(ev).To(HaveKeyWithValue("pto_count", float64(42)))
+				Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond))
+				Expect(entry.Category).To(Equal("security"))
+				Expect(entry.Name).To(Equal("key_updated"))
+				ev := entry.Event
+				Expect(ev).To(HaveKeyWithValue("generation", float64(1337)))
+				Expect(ev).To(HaveKeyWithValue("trigger", "remote_update"))
+				Expect(ev).To(HaveKey("key_type"))
+				keyTypes = append(keyTypes, ev["key_type"].(string))
+			}
+			Expect(keyTypes).To(ContainElement("server_1rtt_secret"))
+			Expect(keyTypes).To(ContainElement("client_1rtt_secret"))
 		})
 	})
 })

qlog/types.go

@@ -175,3 +175,24 @@ func (t keyType) String() string {
 		panic("unknown key type")
 	}
 }
+
+type keyUpdateTrigger uint8
+
+const (
+	keyUpdateTLS keyUpdateTrigger = iota
+	keyUpdateRemote
+	keyUpdateLocal
+)
+
+func (t keyUpdateTrigger) String() string {
+	switch t {
+	case keyUpdateTLS:
+		return "tls"
+	case keyUpdateRemote:
+		return "remote_update"
+	case keyUpdateLocal:
+		return "local_update"
+	default:
+		panic("unknown key update trigger")
+	}
+}

qlog/types_test.go

@@ -33,4 +33,10 @@ var _ = Describe("Types", func() {
 		Expect(encLevelToKeyType(protocol.Encryption1RTT, protocol.PerspectiveClient).String()).To(Equal("client_1rtt_secret"))
 		Expect(encLevelToKeyType(protocol.Encryption1RTT, protocol.PerspectiveServer).String()).To(Equal("server_1rtt_secret"))
 	})
+
+	It("has a string representation for the key update trigger", func() {
+		Expect(keyUpdateTLS.String()).To(Equal("tls"))
+		Expect(keyUpdateRemote.String()).To(Equal("remote_update"))
+		Expect(keyUpdateLocal.String()).To(Equal("local_update"))
+	})
 })