quic: fix packet size logging

The qlog schema puts packet sizes as part of a "raw" field
of type RawInfo, not in the packet_sent/packet_received event.
Move to the correct location.

Change-Id: I4308d4bdb961cf83e29af014b60f50ed029cb915
Reviewed-on: https://go-review.googlesource.com/c/net/+/550797
LUCI-TryBot-Result: Go LUCI <[email protected]>
Reviewed-by: Jonathan Amsterdam <[email protected]>

Author: neild

internal/quic/conn_send.go

@@ -76,7 +76,7 @@ func (c *Conn) maybeSend(now time.Time) (next time.Time) {
 				logSentPacket(c, packetTypeInitial, pnum, p.srcConnID, p.dstConnID, c.w.payload())
 			}
 			if c.logEnabled(QLogLevelPacket) && len(c.w.payload()) > 0 {
-				c.logPacketSent(packetTypeInitial, pnum, p.srcConnID, p.dstConnID, c.w.payload())
+				c.logPacketSent(packetTypeInitial, pnum, p.srcConnID, p.dstConnID, c.w.packetLen(), c.w.payload())
 			}
 			sentInitial = c.w.finishProtectedLongHeaderPacket(pnumMaxAcked, c.keysInitial.w, p)
 			if sentInitial != nil {
@@ -108,7 +108,7 @@ func (c *Conn) maybeSend(now time.Time) (next time.Time) {
 				logSentPacket(c, packetTypeHandshake, pnum, p.srcConnID, p.dstConnID, c.w.payload())
 			}
 			if c.logEnabled(QLogLevelPacket) && len(c.w.payload()) > 0 {
-				c.logPacketSent(packetTypeHandshake, pnum, p.srcConnID, p.dstConnID, c.w.payload())
+				c.logPacketSent(packetTypeHandshake, pnum, p.srcConnID, p.dstConnID, c.w.packetLen(), c.w.payload())
 			}
 			if sent := c.w.finishProtectedLongHeaderPacket(pnumMaxAcked, c.keysHandshake.w, p); sent != nil {
 				c.idleHandlePacketSent(now, sent)
@@ -139,7 +139,7 @@ func (c *Conn) maybeSend(now time.Time) (next time.Time) {
 				logSentPacket(c, packetType1RTT, pnum, nil, dstConnID, c.w.payload())
 			}
 			if c.logEnabled(QLogLevelPacket) && len(c.w.payload()) > 0 {
-				c.logPacketSent(packetType1RTT, pnum, nil, dstConnID, c.w.payload())
+				c.logPacketSent(packetType1RTT, pnum, nil, dstConnID, c.w.packetLen(), c.w.payload())
 			}
 			if sent := c.w.finish1RTTPacket(pnum, pnumMaxAcked, dstConnID, &c.keysAppData); sent != nil {
 				c.idleHandlePacketSent(now, sent)

internal/quic/packet_writer.go

@@ -47,6 +47,11 @@ func (w *packetWriter) datagram() []byte {
 	return w.b
 }
 
+// packet returns the size of the current packet.
+func (w *packetWriter) packetLen() int {
+	return len(w.b[w.pktOff:]) + aeadOverhead
+}
+
 // payload returns the payload of the current packet.
 func (w *packetWriter) payload() []byte {
 	return w.b[w.payOff:]

internal/quic/qlog.go

@@ -148,8 +148,6 @@ func (c *Conn) logConnectionClosed() {
 }
 
 func (c *Conn) logLongPacketReceived(p longPacket, pkt []byte) {
-	pnumLen := 1 + int(pkt[0]&0x03)
-	length := pnumLen + len(p.payload)
 	var frames slog.Attr
 	if c.logEnabled(QLogLevelFrame) {
 		frames = c.packetFramesAttr(p.payload)
@@ -162,7 +160,9 @@ func (c *Conn) logLongPacketReceived(p longPacket, pkt []byte) {
 			slog.Uint64("flags", uint64(pkt[0])),
 			slogHexstring("scid", p.srcConnID),
 			slogHexstring("dcid", p.dstConnID),
-			slog.Int("length", length),
+		),
+		slog.Group("raw",
+			slog.Int("length", len(pkt)),
 		),
 		frames,
 	)
@@ -180,14 +180,16 @@ func (c *Conn) log1RTTPacketReceived(p shortPacket, pkt []byte) {
 			slog.String("packet_type", packetType1RTT.qlogString()),
 			slog.Uint64("packet_number", uint64(p.num)),
 			slog.Uint64("flags", uint64(pkt[0])),
-			slog.String("scid", ""),
 			slogHexstring("dcid", dstConnID),
 		),
+		slog.Group("raw",
+			slog.Int("length", len(pkt)),
+		),
 		frames,
 	)
 }
 
-func (c *Conn) logPacketSent(ptype packetType, pnum packetNumber, src, dst, payload []byte) {
+func (c *Conn) logPacketSent(ptype packetType, pnum packetNumber, src, dst []byte, pktLen int, payload []byte) {
 	var frames slog.Attr
 	if c.logEnabled(QLogLevelFrame) {
 		frames = c.packetFramesAttr(payload)
@@ -204,6 +206,9 @@ func (c *Conn) logPacketSent(ptype packetType, pnum packetNumber, src, dst, payl
 			scid,
 			slogHexstring("dcid", dst),
 		),
+		slog.Group("raw",
+			slog.Int("length", pktLen),
+		),
 		frames,
 	)
 }