diff --git a/internal/handshake/crypto_setup.go b/internal/handshake/crypto_setup.go index d912810e..3b094c9f 100644 --- a/internal/handshake/crypto_setup.go +++ b/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, diff --git a/internal/handshake/updatable_aead.go b/internal/handshake/updatable_aead.go index 94877953..96a9f27e 100644 --- a/internal/handshake/updatable_aead.go +++ b/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() } diff --git a/internal/handshake/updatable_aead_test.go b/internal/handshake/updatable_aead_test.go index 28b26571..a7266d62 100644 --- a/internal/handshake/updatable_aead_test.go +++ b/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) - server = newUpdatableAEAD(rttStats, utils.DefaultLogger) + client = newUpdatableAEAD(rttStats, nil, utils.DefaultLogger) + server = newUpdatableAEAD(rttStats, nil, utils.DefaultLogger) client.SetReadKey(cs, trafficSecret2) client.SetWriteKey(cs, trafficSecret1) server.SetReadKey(cs, trafficSecret1) diff --git a/qlog/event.go b/qlog/event.go index 30a76531..75a91731 100644 --- a/qlog/event.go +++ b/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)) } diff --git a/qlog/qlog.go b/qlog/qlog.go index 2d0f20c6..989617f6 100644 --- a/qlog/qlog.go +++ b/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, + }, + }) +} diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go index 03230deb..a25afce2 100644 --- a/qlog/qlog_test.go +++ b/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{}) - Expect(events).To(HaveLen(1)) - ev := events[0].([]interface{}) - Expect(ev).To(HaveLen(4)) - return time.Unix(0, int64(1e6*ev[0].(float64))), ev[1].(string), ev[2].(string), ev[3].(map[string]interface{}) + for _, e := range trace["events"].([]interface{}) { + ev := e.([]interface{}) + Expect(ev).To(HaveLen(4)) + entries = append(entries, entry{ + 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() - Expect(t).To(BeTemporally("~", now, time.Millisecond)) - Expect(category).To(Equal("transport")) - Expect(eventName).To(Equal("connection_started")) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Category).To(Equal("transport")) + 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() - Expect(t).To(BeTemporally("~", now, time.Millisecond)) - Expect(category).To(Equal("transport")) - Expect(eventName).To(Equal("packet_sent")) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Category).To(Equal("transport")) + 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() - Expect(t).To(BeTemporally("~", now, time.Millisecond)) - Expect(category).To(Equal("transport")) - Expect(eventName).To(Equal("packet_received")) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Category).To(Equal("transport")) + 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() - Expect(t).To(BeTemporally("~", now, time.Millisecond)) - Expect(category).To(Equal("transport")) - Expect(eventName).To(Equal("packet_received")) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Category).To(Equal("transport")) + 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() - Expect(t).To(BeTemporally("~", now, time.Millisecond)) - Expect(category).To(Equal("recovery")) - Expect(eventName).To(Equal("metrics_updated")) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Category).To(Equal("recovery")) + 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() - Expect(t).To(BeTemporally("~", now, time.Millisecond)) - Expect(category).To(Equal("recovery")) - Expect(eventName).To(Equal("packet_lost")) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", now, time.Millisecond)) + Expect(entry.Category).To(Equal("recovery")) + 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() - Expect(t).To(BeTemporally("~", now, time.Millisecond)) - Expect(category).To(Equal("security")) - Expect(eventName).To(Equal("key_updated")) + entry := exportAndParseSingle() + 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("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) - t, category, eventName, ev := exportAndParse() - Expect(t).To(BeTemporally("~", now, time.Millisecond)) - Expect(category).To(Equal("recovery")) - Expect(eventName).To(Equal("metrics_updated")) - Expect(ev).To(HaveKeyWithValue("pto_count", float64(42))) + tracer.UpdatedKey(now, 1337, true) + entries := exportAndParse() + Expect(entries).To(HaveLen(2)) + var keyTypes []string + for _, entry := range entries { + 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")) }) }) }) diff --git a/qlog/types.go b/qlog/types.go index 1c9580dd..60f03b76 100644 --- a/qlog/types.go +++ b/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") + } +} diff --git a/qlog/types_test.go b/qlog/types_test.go index ed3f5990..e045c115 100644 --- a/qlog/types_test.go +++ b/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")) + }) })