From f9726a9e4a0fba67ce78802b47601ba194d15b3f Mon Sep 17 00:00:00 2001 From: Damien Neil Date: Mon, 11 Dec 2023 13:54:56 -0800 Subject: [PATCH] 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 Reviewed-by: Jonathan Amsterdam --- internal/quic/conn_send.go | 6 +++--- internal/quic/packet_writer.go | 5 +++++ internal/quic/qlog.go | 15 ++++++++++----- 3 files changed, 18 insertions(+), 8 deletions(-) diff --git a/internal/quic/conn_send.go b/internal/quic/conn_send.go index c2d8d146b9..ccb467591b 100644 --- a/internal/quic/conn_send.go +++ b/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) diff --git a/internal/quic/packet_writer.go b/internal/quic/packet_writer.go index 0c2b2ee41e..b4e54ce4b0 100644 --- a/internal/quic/packet_writer.go +++ b/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:] diff --git a/internal/quic/qlog.go b/internal/quic/qlog.go index fea8b38eef..82ad92ac8c 100644 --- a/internal/quic/qlog.go +++ b/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, ) }