diff --git a/internal/ackhandler/sent_packet_handler.go b/internal/ackhandler/sent_packet_handler.go index e63b115a..c04e5cbb 100644 --- a/internal/ackhandler/sent_packet_handler.go +++ b/internal/ackhandler/sent_packet_handler.go @@ -433,16 +433,23 @@ func (h *sentPacketHandler) hasOutstandingPackets() bool { } func (h *sentPacketHandler) setLossDetectionTimer() { - if lossTime, _ := h.getEarliestLossTimeAndSpace(); !lossTime.IsZero() { + oldAlarm := h.alarm // only needed in case qlog is enabled + if lossTime, encLevel := h.getEarliestLossTimeAndSpace(); !lossTime.IsZero() { // Early retransmit timer or time loss detection. h.alarm = lossTime + if h.qlogger != nil && h.alarm != oldAlarm { + h.qlogger.SetLossTimer(qlog.TimerTypeACK, encLevel, h.alarm) + } return } // Cancel the alarm if no packets are outstanding if !h.hasOutstandingPackets() && h.peerCompletedAddressValidation { - h.logger.Debugf("Canceling loss detection timer. No packets in flight.") h.alarm = time.Time{} + h.logger.Debugf("Canceling loss detection timer. No packets in flight.") + if h.qlogger != nil && !oldAlarm.IsZero() { + h.qlogger.LossTimerCanceled() + } return } @@ -455,6 +462,9 @@ func (h *sentPacketHandler) setLossDetectionTimer() { sentTime = time.Now() } h.alarm = sentTime.Add(h.rttStats.PTO(encLevel == protocol.Encryption1RTT) << h.ptoCount) + if h.qlogger != nil && h.alarm != oldAlarm { + h.qlogger.SetLossTimer(qlog.TimerTypePTO, encLevel, h.alarm) + } } func (h *sentPacketHandler) detectAndRemoveLostPackets(now time.Time, encLevel protocol.EncryptionLevel) ([]*Packet, error) { @@ -551,6 +561,9 @@ func (h *sentPacketHandler) onVerifiedLossDetectionTimeout() error { if h.logger.Debug() { h.logger.Debugf("Loss detection alarm fired in loss timer mode. Loss time: %s", earliestLossTime) } + if h.qlogger != nil { + h.qlogger.LossTimerExpired(qlog.TimerTypeACK, encLevel) + } // Early retransmit or time loss detection priorInFlight := h.bytesInFlight lostPackets, err := h.detectAndRemoveLostPackets(time.Now(), encLevel) @@ -569,6 +582,7 @@ func (h *sentPacketHandler) onVerifiedLossDetectionTimeout() error { } h.ptoCount++ if h.qlogger != nil { + h.qlogger.LossTimerExpired(qlog.TimerTypePTO, encLevel) h.qlogger.UpdatedPTOCount(h.ptoCount) } h.numProbesToSend += 2 @@ -701,7 +715,11 @@ func (h *sentPacketHandler) ResetForRetry() error { h.initialPackets = newPacketNumberSpace(h.initialPackets.pns.Pop()) h.appDataPackets = newPacketNumberSpace(h.appDataPackets.pns.Pop()) + oldAlarm := h.alarm h.alarm = time.Time{} + if h.qlogger != nil && !oldAlarm.IsZero() { + h.qlogger.LossTimerCanceled() + } return nil } diff --git a/qlog/event.go b/qlog/event.go index 77da6ec9..27ebf702 100644 --- a/qlog/event.go +++ b/qlog/event.go @@ -334,3 +334,45 @@ func (e eventTransportParameters) MarshalJSONObject(enc *gojay.Encoder) { enc.Int64KeyOmitEmpty("initial_max_streams_bidi", e.InitialMaxStreamsBidi) enc.Int64KeyOmitEmpty("initial_max_streams_uni", e.InitialMaxStreamsUni) } + +type eventLossTimerSet struct { + TimerType TimerType + EncLevel protocol.EncryptionLevel + Delta time.Duration +} + +func (e eventLossTimerSet) Category() category { return categoryRecovery } +func (e eventLossTimerSet) Name() string { return "loss_timer_updated" } +func (e eventLossTimerSet) IsNil() bool { return false } + +func (e eventLossTimerSet) MarshalJSONObject(enc *gojay.Encoder) { + enc.StringKey("event_type", "set") + enc.StringKey("timer_type", e.TimerType.String()) + enc.StringKey("packet_number_space", encLevelToPacketNumberSpace(e.EncLevel)) + enc.Float64Key("delta", milliseconds(e.Delta)) +} + +type eventLossTimerExpired struct { + TimerType TimerType + EncLevel protocol.EncryptionLevel +} + +func (e eventLossTimerExpired) Category() category { return categoryRecovery } +func (e eventLossTimerExpired) Name() string { return "loss_timer_updated" } +func (e eventLossTimerExpired) IsNil() bool { return false } + +func (e eventLossTimerExpired) MarshalJSONObject(enc *gojay.Encoder) { + enc.StringKey("event_type", "expired") + enc.StringKey("timer_type", e.TimerType.String()) + enc.StringKey("packet_number_space", encLevelToPacketNumberSpace(e.EncLevel)) +} + +type eventLossTimerCanceled struct{} + +func (e eventLossTimerCanceled) Category() category { return categoryRecovery } +func (e eventLossTimerCanceled) Name() string { return "loss_timer_updated" } +func (e eventLossTimerCanceled) IsNil() bool { return false } + +func (e eventLossTimerCanceled) MarshalJSONObject(enc *gojay.Encoder) { + enc.StringKey("event_type", "cancelled") +} diff --git a/qlog/qlog.go b/qlog/qlog.go index 4f4818c9..0fde46d2 100644 --- a/qlog/qlog.go +++ b/qlog/qlog.go @@ -34,6 +34,9 @@ type Tracer interface { UpdatedKeyFromTLS(protocol.EncryptionLevel, protocol.Perspective) UpdatedKey(generation protocol.KeyPhase, remote bool) DroppedEncryptionLevel(protocol.EncryptionLevel) + SetLossTimer(TimerType, protocol.EncryptionLevel, time.Time) + LossTimerExpired(TimerType, protocol.EncryptionLevel) + LossTimerCanceled() } type tracer struct { @@ -119,9 +122,9 @@ func (t *tracer) Export() error { return t.w.Close() } -func (t *tracer) recordEvent(details eventDetails) { +func (t *tracer) recordEvent(eventTime time.Time, details eventDetails) { t.events <- event{ - RelativeTime: time.Since(t.referenceTime), + RelativeTime: eventTime.Sub(t.referenceTime), eventDetails: details, } } @@ -136,7 +139,7 @@ func (t *tracer) StartedConnection(local, remote net.Addr, version protocol.Vers if !ok { return } - t.recordEvent(&eventConnectionStarted{ + t.recordEvent(time.Now(), &eventConnectionStarted{ SrcAddr: localAddr, DestAddr: remoteAddr, Version: version, @@ -154,7 +157,7 @@ func (t *tracer) ReceivedTransportParameters(tp *wire.TransportParameters) { } func (t *tracer) recordTransportParameters(owner owner, tp *wire.TransportParameters) { - t.recordEvent(&eventTransportParameters{ + t.recordEvent(time.Now(), &eventTransportParameters{ Owner: owner, OriginalConnectionID: tp.OriginalConnectionID, StatelessResetToken: tp.StatelessResetToken, @@ -187,7 +190,7 @@ func (t *tracer) SentPacket(hdr *wire.ExtendedHeader, packetSize protocol.ByteCo } header := *transformExtendedHeader(hdr) header.PacketSize = packetSize - t.recordEvent(&eventPacketSent{ + t.recordEvent(time.Now(), &eventPacketSent{ PacketType: PacketTypeFromHeader(&hdr.Header), Header: header, Frames: fs, @@ -201,7 +204,7 @@ func (t *tracer) ReceivedPacket(hdr *wire.ExtendedHeader, packetSize protocol.By } header := *transformExtendedHeader(hdr) header.PacketSize = packetSize - t.recordEvent(&eventPacketReceived{ + t.recordEvent(time.Now(), &eventPacketReceived{ PacketType: PacketTypeFromHeader(&hdr.Header), Header: header, Frames: fs, @@ -209,23 +212,23 @@ func (t *tracer) ReceivedPacket(hdr *wire.ExtendedHeader, packetSize protocol.By } func (t *tracer) ReceivedRetry(hdr *wire.Header) { - t.recordEvent(&eventRetryReceived{ + t.recordEvent(time.Now(), &eventRetryReceived{ Header: *transformHeader(hdr), }) } func (t *tracer) ReceivedStatelessReset(token *[16]byte) { - t.recordEvent(&eventStatelessResetReceived{ + t.recordEvent(time.Now(), &eventStatelessResetReceived{ Token: token, }) } func (t *tracer) BufferedPacket(packetType PacketType) { - t.recordEvent(&eventPacketBuffered{PacketType: packetType}) + t.recordEvent(time.Now(), &eventPacketBuffered{PacketType: packetType}) } func (t *tracer) DroppedPacket(packetType PacketType, size protocol.ByteCount, dropReason PacketDropReason) { - t.recordEvent(&eventPacketDropped{ + t.recordEvent(time.Now(), &eventPacketDropped{ PacketType: packetType, PacketSize: size, Trigger: dropReason, @@ -242,7 +245,7 @@ func (t *tracer) UpdatedMetrics(rttStats *congestion.RTTStats, cwnd, bytesInFlig BytesInFlight: bytesInFlight, PacketsInFlight: packetsInFlight, } - t.recordEvent(&eventMetricsUpdated{ + t.recordEvent(time.Now(), &eventMetricsUpdated{ Last: t.lastMetrics, Current: m, }) @@ -250,7 +253,7 @@ func (t *tracer) UpdatedMetrics(rttStats *congestion.RTTStats, cwnd, bytesInFlig } func (t *tracer) LostPacket(encLevel protocol.EncryptionLevel, pn protocol.PacketNumber, lossReason PacketLossReason) { - t.recordEvent(&eventPacketLost{ + t.recordEvent(time.Now(), &eventPacketLost{ PacketType: getPacketTypeFromEncryptionLevel(encLevel), PacketNumber: pn, Trigger: lossReason, @@ -258,11 +261,11 @@ func (t *tracer) LostPacket(encLevel protocol.EncryptionLevel, pn protocol.Packe } func (t *tracer) UpdatedPTOCount(value uint32) { - t.recordEvent(&eventUpdatedPTO{Value: value}) + t.recordEvent(time.Now(), &eventUpdatedPTO{Value: value}) } func (t *tracer) UpdatedKeyFromTLS(encLevel protocol.EncryptionLevel, pers protocol.Perspective) { - t.recordEvent(&eventKeyUpdated{ + t.recordEvent(time.Now(), &eventKeyUpdated{ Trigger: keyUpdateTLS, KeyType: encLevelToKeyType(encLevel, pers), }) @@ -273,12 +276,13 @@ func (t *tracer) UpdatedKey(generation protocol.KeyPhase, remote bool) { if remote { trigger = keyUpdateRemote } - t.recordEvent(&eventKeyUpdated{ + now := time.Now() + t.recordEvent(now, &eventKeyUpdated{ Trigger: trigger, KeyType: keyTypeClient1RTT, Generation: generation, }) - t.recordEvent(&eventKeyUpdated{ + t.recordEvent(now, &eventKeyUpdated{ Trigger: trigger, KeyType: keyTypeServer1RTT, Generation: generation, @@ -286,6 +290,27 @@ func (t *tracer) UpdatedKey(generation protocol.KeyPhase, remote bool) { } func (t *tracer) DroppedEncryptionLevel(encLevel protocol.EncryptionLevel) { - t.recordEvent(&eventKeyRetired{KeyType: encLevelToKeyType(encLevel, protocol.PerspectiveServer)}) - t.recordEvent(&eventKeyRetired{KeyType: encLevelToKeyType(encLevel, protocol.PerspectiveClient)}) + now := time.Now() + t.recordEvent(now, &eventKeyRetired{KeyType: encLevelToKeyType(encLevel, protocol.PerspectiveServer)}) + t.recordEvent(now, &eventKeyRetired{KeyType: encLevelToKeyType(encLevel, protocol.PerspectiveClient)}) +} + +func (t *tracer) SetLossTimer(tt TimerType, encLevel protocol.EncryptionLevel, timeout time.Time) { + now := time.Now() + t.recordEvent(now, &eventLossTimerSet{ + TimerType: tt, + EncLevel: encLevel, + Delta: timeout.Sub(now), + }) +} + +func (t *tracer) LossTimerExpired(tt TimerType, encLevel protocol.EncryptionLevel) { + t.recordEvent(time.Now(), &eventLossTimerExpired{ + TimerType: tt, + EncLevel: encLevel, + }) +} + +func (t *tracer) LossTimerCanceled() { + t.recordEvent(time.Now(), &eventLossTimerCanceled{}) } diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go index a0e0309a..7bbb597b 100644 --- a/qlog/qlog_test.go +++ b/qlog/qlog_test.go @@ -492,5 +492,46 @@ var _ = Describe("Tracer", func() { Expect(keyTypes).To(ContainElement("server_initial_secret")) Expect(keyTypes).To(ContainElement("client_initial_secret")) }) + + It("records when the timer is set", func() { + t := time.Now().Add(1337 * time.Millisecond) + tracer.SetLossTimer(TimerTypePTO, protocol.EncryptionHandshake, t) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) + Expect(entry.Category).To(Equal("recovery")) + Expect(entry.Name).To(Equal("loss_timer_updated")) + ev := entry.Event + Expect(ev).To(HaveLen(4)) + Expect(ev).To(HaveKeyWithValue("event_type", "set")) + Expect(ev).To(HaveKeyWithValue("timer_type", "pto")) + Expect(ev).To(HaveKeyWithValue("packet_number_space", "handshake")) + Expect(ev).To(HaveKey("delta")) + delta := time.Duration(ev["delta"].(float64)) * time.Millisecond + Expect(entry.Time.Add(delta)).To(BeTemporally("~", t, 2*time.Millisecond)) + }) + + It("records when the loss timer expires", func() { + tracer.LossTimerExpired(TimerTypeACK, protocol.Encryption1RTT) + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) + Expect(entry.Category).To(Equal("recovery")) + Expect(entry.Name).To(Equal("loss_timer_updated")) + ev := entry.Event + Expect(ev).To(HaveLen(3)) + Expect(ev).To(HaveKeyWithValue("event_type", "expired")) + Expect(ev).To(HaveKeyWithValue("timer_type", "ack")) + Expect(ev).To(HaveKeyWithValue("packet_number_space", "application_data")) + }) + + It("records when the timer is canceled", func() { + tracer.LossTimerCanceled() + entry := exportAndParseSingle() + Expect(entry.Time).To(BeTemporally("~", time.Now(), 10*time.Millisecond)) + Expect(entry.Category).To(Equal("recovery")) + Expect(entry.Name).To(Equal("loss_timer_updated")) + ev := entry.Event + Expect(ev).To(HaveLen(1)) + Expect(ev).To(HaveKeyWithValue("event_type", "cancelled")) + }) }) }) diff --git a/qlog/types.go b/qlog/types.go index a8dd7404..69afb19f 100644 --- a/qlog/types.go +++ b/qlog/types.go @@ -120,6 +120,19 @@ func (t PacketType) String() string { } } +func encLevelToPacketNumberSpace(encLevel protocol.EncryptionLevel) string { + switch encLevel { + case protocol.EncryptionInitial: + return "initial" + case protocol.EncryptionHandshake: + return "handshake" + case protocol.Encryption0RTT, protocol.Encryption1RTT: + return "application_data" + default: + panic("unknown encryption level") + } +} + type PacketLossReason uint8 const ( @@ -302,3 +315,24 @@ func (e transportError) String() string { return "" } } + +// TimerType is the type of the loss detection timer +type TimerType uint8 + +const ( + // TimerTypeACK is the timer type for the early retransmit timer + TimerTypeACK TimerType = iota + // TimerTypePTO is the timer type for the PTO retransmit timer + TimerTypePTO +) + +func (t TimerType) String() string { + switch t { + case TimerTypeACK: + return "ack" + case TimerTypePTO: + return "pto" + default: + panic("unknown timer type") + } +} diff --git a/qlog/types_test.go b/qlog/types_test.go index df2ea093..9dee5b09 100644 --- a/qlog/types_test.go +++ b/qlog/types_test.go @@ -56,6 +56,13 @@ var _ = Describe("Types", func() { Expect(keyUpdateLocal.String()).To(Equal("local_update")) }) + It("tells the packet number space from the encryption level", func() { + Expect(encLevelToPacketNumberSpace(protocol.EncryptionInitial)).To(Equal("initial")) + Expect(encLevelToPacketNumberSpace(protocol.EncryptionHandshake)).To(Equal("handshake")) + Expect(encLevelToPacketNumberSpace(protocol.Encryption0RTT)).To(Equal("application_data")) + Expect(encLevelToPacketNumberSpace(protocol.Encryption1RTT)).To(Equal("application_data")) + }) + It("has a string representation for the packet drop reason", func() { Expect(PacketDropKeyUnavailable.String()).To(Equal("key_unavailable")) Expect(PacketDropUnknownConnectionID.String()).To(Equal("unknown_connection_id")) @@ -103,4 +110,9 @@ var _ = Describe("Types", func() { Expect(transportError(1337).String()).To(BeEmpty()) }) }) + + It("has a string representation for the timer type", func() { + Expect(TimerTypeACK.String()).To(Equal("ack")) + Expect(TimerTypePTO.String()).To(Equal("pto")) + }) })