logging: pass the packet number to ConnectionTracer.DroppedPacket (#4171)

In most cases the packet number is not known when a packet is dropped,
but it's useful to log the packet number when dropping a duplicate
packet.

qlog/event.go

@@ -243,15 +243,16 @@ func (e eventPacketBuffered) IsNil() bool        { return false }
 
 func (e eventPacketBuffered) MarshalJSONObject(enc *gojay.Encoder) {
 	//nolint:gosimple
-	enc.ObjectKey("header", packetHeaderWithType{PacketType: e.PacketType})
+	enc.ObjectKey("header", packetHeaderWithType{PacketType: e.PacketType, PacketNumber: protocol.InvalidPacketNumber})
 	enc.ObjectKey("raw", rawInfo{Length: e.PacketSize})
 	enc.StringKey("trigger", "keys_unavailable")
 }
 
 type eventPacketDropped struct {
-	PacketType logging.PacketType
-	PacketSize protocol.ByteCount
-	Trigger    packetDropReason
+	PacketType   logging.PacketType
+	PacketSize   protocol.ByteCount
+	PacketNumber logging.PacketNumber
+	Trigger      packetDropReason
 }
 
 func (e eventPacketDropped) Category() category { return categoryTransport }
@@ -259,7 +260,10 @@ func (e eventPacketDropped) Name() string       { return "packet_dropped" }
 func (e eventPacketDropped) IsNil() bool        { return false }
 
 func (e eventPacketDropped) MarshalJSONObject(enc *gojay.Encoder) {
-	enc.ObjectKey("header", packetHeaderWithType{PacketType: e.PacketType})
+	enc.ObjectKey("header", packetHeaderWithType{
+		PacketType:   e.PacketType,
+		PacketNumber: e.PacketNumber,
+	})
 	enc.ObjectKey("raw", rawInfo{Length: e.PacketSize})
 	enc.StringKey("trigger", e.Trigger.String())
 }

qlog/packet_header.go

@@ -110,14 +110,18 @@ func (h packetHeaderVersionNegotiation) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.StringKey("dcid", h.DestConnectionID.String())
 }
 
-// a minimal header that only outputs the packet type
+// a minimal header that only outputs the packet type, and potentially a packet number
 type packetHeaderWithType struct {
-	PacketType logging.PacketType
+	PacketType   logging.PacketType
+	PacketNumber logging.PacketNumber
 }
 
 func (h packetHeaderWithType) IsNil() bool { return false }
 func (h packetHeaderWithType) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.StringKey("packet_type", packetType(h.PacketType).String())
+	if h.PacketNumber != protocol.InvalidPacketNumber {
+		enc.Int64Key("packet_number", int64(h.PacketNumber))
+	}
 }
 
 // a minimal header that only outputs the packet type

qlog/qlog.go

@@ -106,8 +106,8 @@ func NewConnectionTracer(w io.WriteCloser, p protocol.Perspective, odcid protoco
 		BufferedPacket: func(pt logging.PacketType, size protocol.ByteCount) {
 			t.BufferedPacket(pt, size)
 		},
-		DroppedPacket: func(pt logging.PacketType, size protocol.ByteCount, reason logging.PacketDropReason) {
-			t.DroppedPacket(pt, size, reason)
+		DroppedPacket: func(pt logging.PacketType, pn logging.PacketNumber, size logging.ByteCount, reason logging.PacketDropReason) {
+			t.DroppedPacket(pt, pn, size, reason)
 		},
 		UpdatedMetrics: func(rttStats *utils.RTTStats, cwnd, bytesInFlight protocol.ByteCount, packetsInFlight int) {
 			t.UpdatedMetrics(rttStats, cwnd, bytesInFlight, packetsInFlight)
@@ -444,12 +444,13 @@ func (t *connectionTracer) BufferedPacket(pt logging.PacketType, size protocol.B
 	t.mutex.Unlock()
 }
 
-func (t *connectionTracer) DroppedPacket(pt logging.PacketType, size protocol.ByteCount, reason logging.PacketDropReason) {
+func (t *connectionTracer) DroppedPacket(pt logging.PacketType, pn logging.PacketNumber, size protocol.ByteCount, reason logging.PacketDropReason) {
 	t.mutex.Lock()
 	t.recordEvent(time.Now(), &eventPacketDropped{
-		PacketType: pt,
-		PacketSize: size,
-		Trigger:    packetDropReason(reason),
+		PacketType:   pt,
+		PacketNumber: pn,
+		PacketSize:   size,
+		Trigger:      packetDropReason(reason),
 	})
 	t.mutex.Unlock()
 }

qlog/qlog_test.go

@@ -616,7 +616,7 @@ var _ = Describe("Tracing", func() {
 			})
 
 			It("records dropped packets", func() {
-				tracer.DroppedPacket(logging.PacketTypeHandshake, 1337, logging.PacketDropPayloadDecryptError)
+				tracer.DroppedPacket(logging.PacketTypeRetry, protocol.InvalidPacketNumber, 1337, logging.PacketDropPayloadDecryptError)
 				entry := exportAndParseSingle()
 				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 				Expect(entry.Name).To(Equal("transport:packet_dropped"))
@@ -626,10 +626,26 @@ var _ = Describe("Tracing", func() {
 				Expect(ev).To(HaveKey("header"))
 				hdr := ev["header"].(map[string]interface{})
 				Expect(hdr).To(HaveLen(1))
-				Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake"))
+				Expect(hdr).To(HaveKeyWithValue("packet_type", "retry"))
 				Expect(ev).To(HaveKeyWithValue("trigger", "payload_decrypt_error"))
 			})
 
+			It("records dropped packets with a packet number", func() {
+				tracer.DroppedPacket(logging.PacketTypeHandshake, 42, 1337, logging.PacketDropDuplicate)
+				entry := exportAndParseSingle()
+				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+				Expect(entry.Name).To(Equal("transport:packet_dropped"))
+				ev := entry.Event
+				Expect(ev).To(HaveKey("raw"))
+				Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337)))
+				Expect(ev).To(HaveKey("header"))
+				hdr := ev["header"].(map[string]interface{})
+				Expect(hdr).To(HaveLen(2))
+				Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake"))
+				Expect(hdr).To(HaveKeyWithValue("packet_number", float64(42)))
+				Expect(ev).To(HaveKeyWithValue("trigger", "duplicate"))
+			})
+
 			It("records metrics updates", func() {
 				now := time.Now()
 				rttStats := utils.NewRTTStats()