Merge pull request #2765 from lucas-clemente/log-key-retirements

log when an old 1-RTT key is retired

internal/handshake/updatable_aead.go

@@ -150,6 +150,9 @@ func (a *updatableAEAD) Open(dst, src []byte, rcvTime time.Time, pn protocol.Pac
 	if a.prevRcvAEAD != nil && rcvTime.After(a.prevRcvAEADExpiry) {
 		a.prevRcvAEAD = nil
 		a.prevRcvAEADExpiry = time.Time{}
+		if a.tracer != nil {
+			a.tracer.DroppedKey(a.keyPhase - 1)
+		}
 	}
 	binary.BigEndian.PutUint64(a.nonceBuf[len(a.nonceBuf)-8:], uint64(pn))
 	if kp != a.keyPhase.Bit() {

internal/handshake/updatable_aead_test.go

@@ -195,6 +195,7 @@ var _ = Describe("Updatable AEAD", func() {
 							encrypted1 := client.Seal(nil, msg, 0x44, ad)
 							Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseZero))
 							serverTracer.EXPECT().UpdatedKey(protocol.KeyPhase(1), true)
+							serverTracer.EXPECT().DroppedKey(protocol.KeyPhase(0))
 							_, err = server.Open(nil, encrypted1, now, 0x44, protocol.KeyPhaseOne, ad)
 							Expect(err).ToNot(HaveOccurred())
 							Expect(server.KeyPhase()).To(Equal(protocol.KeyPhaseOne))

internal/mocks/logging/connection_tracer.go

@@ -87,6 +87,18 @@ func (mr *MockConnectionTracerMockRecorder) DroppedEncryptionLevel(arg0 interfac
 	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "DroppedEncryptionLevel", reflect.TypeOf((*MockConnectionTracer)(nil).DroppedEncryptionLevel), arg0)
 }
 
+// DroppedKey mocks base method
+func (m *MockConnectionTracer) DroppedKey(arg0 protocol.KeyPhase) {
+	m.ctrl.T.Helper()
+	m.ctrl.Call(m, "DroppedKey", arg0)
+}
+
+// DroppedKey indicates an expected call of DroppedKey
+func (mr *MockConnectionTracerMockRecorder) DroppedKey(arg0 interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "DroppedKey", reflect.TypeOf((*MockConnectionTracer)(nil).DroppedKey), arg0)
+}
+
 // DroppedPacket mocks base method
 func (m *MockConnectionTracer) DroppedPacket(arg0 protocol.PacketType, arg1 protocol.ByteCount, arg2 logging.PacketDropReason) {
 	m.ctrl.T.Helper()

logging/interface.go

@@ -111,6 +111,7 @@ type ConnectionTracer interface {
 	UpdatedKeyFromTLS(EncryptionLevel, Perspective)
 	UpdatedKey(generation KeyPhase, remote bool)
 	DroppedEncryptionLevel(EncryptionLevel)
+	DroppedKey(generation KeyPhase)
 	SetLossTimer(TimerType, EncryptionLevel, time.Time)
 	LossTimerExpired(TimerType, EncryptionLevel)
 	LossTimerCanceled()

logging/mock_connection_tracer_test.go

@@ -86,6 +86,18 @@ func (mr *MockConnectionTracerMockRecorder) DroppedEncryptionLevel(arg0 interfac
 	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "DroppedEncryptionLevel", reflect.TypeOf((*MockConnectionTracer)(nil).DroppedEncryptionLevel), arg0)
 }
 
+// DroppedKey mocks base method
+func (m *MockConnectionTracer) DroppedKey(arg0 protocol.KeyPhase) {
+	m.ctrl.T.Helper()
+	m.ctrl.Call(m, "DroppedKey", arg0)
+}
+
+// DroppedKey indicates an expected call of DroppedKey
+func (mr *MockConnectionTracerMockRecorder) DroppedKey(arg0 interface{}) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "DroppedKey", reflect.TypeOf((*MockConnectionTracer)(nil).DroppedKey), arg0)
+}
+
 // DroppedPacket mocks base method
 func (m *MockConnectionTracer) DroppedPacket(arg0 protocol.PacketType, arg1 protocol.ByteCount, arg2 PacketDropReason) {
 	m.ctrl.T.Helper()

logging/multiplex.go

@@ -162,6 +162,12 @@ func (m *connTracerMultiplexer) DroppedEncryptionLevel(encLevel EncryptionLevel)
 	}
 }
 
+func (m *connTracerMultiplexer) DroppedKey(generation KeyPhase) {
+	for _, t := range m.tracers {
+		t.DroppedKey(generation)
+	}
+}
+
 func (m *connTracerMultiplexer) SetLossTimer(typ TimerType, encLevel EncryptionLevel, exp time.Time) {
 	for _, t := range m.tracers {
 		t.SetLossTimer(typ, encLevel, exp)

logging/multiplex_test.go

@@ -213,6 +213,12 @@ var _ = Describe("Tracing", func() {
 			tracer.DroppedEncryptionLevel(EncryptionHandshake)
 		})
 
+		It("traces the DroppedKey event", func() {
+			tr1.EXPECT().DroppedKey(KeyPhase(123))
+			tr2.EXPECT().DroppedKey(KeyPhase(123))
+			tracer.DroppedKey(123)
+		})
+
 		It("traces the SetLossTimer event", func() {
 			now := time.Now()
 			tr1.EXPECT().SetLossTimer(TimerTypePTO, EncryptionHandshake, now)

metrics/metrics.go

@@ -214,6 +214,7 @@ func (t *connTracer) UpdatedPTOCount(value uint32) {
 func (t *connTracer) UpdatedKeyFromTLS(logging.EncryptionLevel, logging.Perspective)     {}
 func (t *connTracer) UpdatedKey(logging.KeyPhase, bool)                                  {}
 func (t *connTracer) DroppedEncryptionLevel(logging.EncryptionLevel)                     {}
+func (t *connTracer) DroppedKey(logging.KeyPhase)                                        {}
 func (t *connTracer) SetLossTimer(logging.TimerType, logging.EncryptionLevel, time.Time) {}
 func (t *connTracer) LossTimerExpired(logging.TimerType, logging.EncryptionLevel)        {}
 func (t *connTracer) LossTimerCanceled()                                                 {}

qlog/event.go

@@ -322,8 +322,13 @@ func (e eventKeyRetired) Name() string       { return "key_retired" }
 func (e eventKeyRetired) IsNil() bool        { return false }
 
 func (e eventKeyRetired) MarshalJSONObject(enc *gojay.Encoder) {
-	enc.StringKey("trigger", "tls")
+	if e.KeyType != keyTypeClient1RTT && e.KeyType != keyTypeServer1RTT {
+		enc.StringKey("trigger", "tls")
+	}
 	enc.StringKey("key_type", e.KeyType.String())
+	if e.KeyType == keyTypeClient1RTT || e.KeyType == keyTypeServer1RTT {
+		enc.Uint64Key("generation", uint64(e.Generation))
+	}
 }
 
 type eventTransportParameters struct {

qlog/qlog.go

@@ -365,6 +365,20 @@ func (t *connectionTracer) DroppedEncryptionLevel(encLevel protocol.EncryptionLe
 	t.mutex.Unlock()
 }
 
+func (t *connectionTracer) DroppedKey(generation protocol.KeyPhase) {
+	t.mutex.Lock()
+	now := time.Now()
+	t.recordEvent(now, &eventKeyRetired{
+		KeyType:    encLevelToKeyType(protocol.Encryption1RTT, protocol.PerspectiveServer),
+		Generation: generation,
+	})
+	t.recordEvent(now, &eventKeyRetired{
+		KeyType:    encLevelToKeyType(protocol.Encryption1RTT, protocol.PerspectiveClient),
+		Generation: generation,
+	})
+	t.mutex.Unlock()
+}
+
 func (t *connectionTracer) SetLossTimer(tt logging.TimerType, encLevel protocol.EncryptionLevel, timeout time.Time) {
 	t.mutex.Lock()
 	now := time.Now()

qlog/qlog_test.go

@@ -611,6 +611,25 @@ var _ = Describe("Tracing", func() {
 				Expect(keyTypes).To(ContainElement("client_initial_secret"))
 			})
 
+			It("records dropped keys", func() {
+				tracer.DroppedKey(42)
+				entries := exportAndParse()
+				Expect(entries).To(HaveLen(2))
+				var keyTypes []string
+				for _, entry := range entries {
+					Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+					Expect(entry.Category).To(Equal("security"))
+					Expect(entry.Name).To(Equal("key_retired"))
+					ev := entry.Event
+					Expect(ev).To(HaveKeyWithValue("generation", float64(42)))
+					Expect(ev).ToNot(HaveKey("trigger"))
+					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"))
+			})
+
 			It("records when the timer is set", func() {
 				timeout := time.Now().Add(137 * time.Millisecond)
 				tracer.SetLossTimer(logging.TimerTypePTO, protocol.EncryptionHandshake, timeout)