log the size of buffered packets (#3571)

connection.go

@@ -2080,7 +2080,7 @@ func (s *connection) tryQueueingUndecryptablePacket(p *receivedPacket, pt loggin
 	}
 	s.logger.Infof("Queueing packet (%d bytes) for later decryption", p.Size())
 	if s.tracer != nil {
-		s.tracer.BufferedPacket(pt)
+		s.tracer.BufferedPacket(pt, p.Size())
 	}
 	s.undecryptablePackets = append(s.undecryptablePackets, p)
 }

connection_test.go

@@ -1043,7 +1043,7 @@ var _ = Describe("Connection", func() {
 			}
 			unpacker.EXPECT().UnpackLongHeader(gomock.Any(), gomock.Any(), gomock.Any()).Return(nil, handshake.ErrKeysNotYetAvailable)
 			packet := getPacket(hdr, nil)
-			tracer.EXPECT().BufferedPacket(logging.PacketTypeHandshake)
+			tracer.EXPECT().BufferedPacket(logging.PacketTypeHandshake, packet.Size())
 			Expect(conn.handlePacketImpl(packet)).To(BeFalse())
 			Expect(conn.undecryptablePackets).To(Equal([]*receivedPacket{packet}))
 		})
@@ -1147,7 +1147,7 @@ var _ = Describe("Connection", func() {
 					}),
 				)
 				gomock.InOrder(
-					tracer.EXPECT().BufferedPacket(gomock.Any()),
+					tracer.EXPECT().BufferedPacket(gomock.Any(), protocol.ByteCount(len(packet1.data))),
 					tracer.EXPECT().ReceivedLongHeaderPacket(gomock.Any(), protocol.ByteCount(len(packet2.data)), gomock.Any()),
 				)
 				packet1.data = append(packet1.data, packet2.data...)

logging/interface.go

@@ -126,7 +126,7 @@ type ConnectionTracer interface {
 	ReceivedRetry(*Header)
 	ReceivedLongHeaderPacket(hdr *ExtendedHeader, size ByteCount, frames []Frame)
 	ReceivedShortHeaderPacket(hdr *ShortHeader, size ByteCount, frames []Frame)
-	BufferedPacket(PacketType)
+	BufferedPacket(PacketType, ByteCount)
 	DroppedPacket(PacketType, ByteCount, PacketDropReason)
 	UpdatedMetrics(rttStats *RTTStats, cwnd, bytesInFlight ByteCount, packetsInFlight int)
 	AcknowledgedPacket(EncryptionLevel, PacketNumber)

logging/multiplex.go

@@ -134,9 +134,9 @@ func (m *connTracerMultiplexer) ReceivedShortHeaderPacket(hdr *ShortHeader, size
 	}
 }
 
-func (m *connTracerMultiplexer) BufferedPacket(typ PacketType) {
+func (m *connTracerMultiplexer) BufferedPacket(typ PacketType, size ByteCount) {
 	for _, t := range m.tracers {
-		t.BufferedPacket(typ)
+		t.BufferedPacket(typ, size)
 	}
 }
 

logging/multiplex_test.go

@@ -198,9 +198,9 @@ var _ = Describe("Tracing", func() {
 		})
 
 		It("traces the BufferedPacket event", func() {
-			tr1.EXPECT().BufferedPacket(PacketTypeHandshake)
-			tr2.EXPECT().BufferedPacket(PacketTypeHandshake)
-			tracer.BufferedPacket(PacketTypeHandshake)
+			tr1.EXPECT().BufferedPacket(PacketTypeHandshake, ByteCount(1337))
+			tr2.EXPECT().BufferedPacket(PacketTypeHandshake, ByteCount(1337))
+			tracer.BufferedPacket(PacketTypeHandshake, 1337)
 		})
 
 		It("traces the DroppedPacket event", func() {

logging/null_tracer.go

@@ -41,7 +41,7 @@ func (n NullConnectionTracer) ReceivedVersionNegotiationPacket(dest, src Arbitra
 func (n NullConnectionTracer) ReceivedRetry(*Header)                                        {}
 func (n NullConnectionTracer) ReceivedLongHeaderPacket(*ExtendedHeader, ByteCount, []Frame) {}
 func (n NullConnectionTracer) ReceivedShortHeaderPacket(*ShortHeader, ByteCount, []Frame)   {}
-func (n NullConnectionTracer) BufferedPacket(PacketType)                                    {}
+func (n NullConnectionTracer) BufferedPacket(PacketType, ByteCount)                         {}
 func (n NullConnectionTracer) DroppedPacket(PacketType, ByteCount, PacketDropReason)        {}
 
 func (n NullConnectionTracer) UpdatedMetrics(rttStats *RTTStats, cwnd, bytesInFlight ByteCount, packetsInFlight int) {

qlog/event.go

@@ -227,6 +227,7 @@ func (e eventVersionNegotiationReceived) MarshalJSONObject(enc *gojay.Encoder) {
 
 type eventPacketBuffered struct {
 	PacketType logging.PacketType
+	PacketSize protocol.ByteCount
 }
 
 func (e eventPacketBuffered) Category() category { return categoryTransport }
@@ -236,6 +237,7 @@ 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("raw", rawInfo{Length: e.PacketSize})
 	enc.StringKey("trigger", "keys_unavailable")
 }
 

qlog/qlog.go

@@ -354,9 +354,12 @@ func (t *connectionTracer) ReceivedVersionNegotiationPacket(dest, src logging.Ar
 	t.mutex.Unlock()
 }
 
-func (t *connectionTracer) BufferedPacket(pt logging.PacketType) {
+func (t *connectionTracer) BufferedPacket(pt logging.PacketType, size protocol.ByteCount) {
 	t.mutex.Lock()
-	t.recordEvent(time.Now(), &eventPacketBuffered{PacketType: pt})
+	t.recordEvent(time.Now(), &eventPacketBuffered{
+		PacketType: pt,
+		PacketSize: size,
+	})
 	t.mutex.Unlock()
 }
 

qlog/qlog_test.go

@@ -610,7 +610,7 @@ var _ = Describe("Tracing", func() {
 			})
 
 			It("records buffered packets", func() {
-				tracer.BufferedPacket(logging.PacketTypeHandshake)
+				tracer.BufferedPacket(logging.PacketTypeHandshake, 1337)
 				entry := exportAndParseSingle()
 				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
 				Expect(entry.Name).To(Equal("transport:packet_buffered"))
@@ -619,6 +619,8 @@ var _ = Describe("Tracing", func() {
 				hdr := ev["header"].(map[string]interface{})
 				Expect(hdr).To(HaveLen(1))
 				Expect(hdr).To(HaveKeyWithValue("packet_type", "handshake"))
+				Expect(ev).To(HaveKey("raw"))
+				Expect(ev["raw"].(map[string]interface{})).To(HaveKeyWithValue("length", float64(1337)))
 				Expect(ev).To(HaveKeyWithValue("trigger", "keys_unavailable"))
 			})