diff --git a/internal/handshake/updatable_aead.go b/internal/handshake/updatable_aead.go index dfad557a..e21430b3 100644 --- a/internal/handshake/updatable_aead.go +++ b/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() { diff --git a/internal/handshake/updatable_aead_test.go b/internal/handshake/updatable_aead_test.go index 985df248..1e8c92e2 100644 --- a/internal/handshake/updatable_aead_test.go +++ b/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)) diff --git a/internal/mocks/logging/connection_tracer.go b/internal/mocks/logging/connection_tracer.go index a91694e9..ddede4b6 100644 --- a/internal/mocks/logging/connection_tracer.go +++ b/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() diff --git a/logging/interface.go b/logging/interface.go index e9d4774e..d640cc7f 100644 --- a/logging/interface.go +++ b/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() diff --git a/logging/mock_connection_tracer_test.go b/logging/mock_connection_tracer_test.go index 24d994c8..b7684fa1 100644 --- a/logging/mock_connection_tracer_test.go +++ b/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() diff --git a/logging/multiplex.go b/logging/multiplex.go index 73e0c128..1dfc5283 100644 --- a/logging/multiplex.go +++ b/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) diff --git a/logging/multiplex_test.go b/logging/multiplex_test.go index dddb946f..56fc8b88 100644 --- a/logging/multiplex_test.go +++ b/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) diff --git a/metrics/metrics.go b/metrics/metrics.go index d13f4dd9..f764d025 100644 --- a/metrics/metrics.go +++ b/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() {} diff --git a/qlog/event.go b/qlog/event.go index a24b04ab..4883e770 100644 --- a/qlog/event.go +++ b/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 { diff --git a/qlog/qlog.go b/qlog/qlog.go index 96cada2c..7c013412 100644 --- a/qlog/qlog.go +++ b/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() diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go index 6d39d799..b62a07cc 100644 --- a/qlog/qlog_test.go +++ b/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)