quic: debug logging of packets

Log every packet sent and received to stdout when
GODEBUG=quiclogpackets=1.

For golang/go#58547

Change-Id: I904336017ea646ad6459557b44702bfe4c732ba9
Reviewed-on: https://go-review.googlesource.com/c/net/+/513439
Reviewed-by: Jonathan Amsterdam <jba@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Damien Neil <dneil@google.com>

internal/quic/conn.go

@@ -116,6 +116,10 @@ func newConn(now time.Time, side connSide, initialConnID []byte, peerAddr netip.
 	return c, nil
 }
 
+func (c *Conn) String() string {
+	return fmt.Sprintf("quic.Conn(%v,->%v)", c.side, c.peerAddr)
+}
+
 // confirmHandshake is called when the handshake is confirmed.
 // https://www.rfc-editor.org/rfc/rfc9001#section-4.1.2
 func (c *Conn) confirmHandshake(now time.Time) {

internal/quic/conn_recv.go

@@ -60,6 +60,9 @@ func (c *Conn) handleLongHeader(now time.Time, ptype packetType, space numberSpa
 		return n
 	}
 
+	if logPackets {
+		logInboundLongPacket(c, p)
+	}
 	c.connIDState.handlePacket(c.side, p.ptype, p.srcConnID)
 	ackEliciting := c.handleFrames(now, ptype, space, p.payload)
 	c.acks[space].receive(now, space, p.num, ackEliciting)
@@ -96,6 +99,9 @@ func (c *Conn) handle1RTT(now time.Time, buf []byte) int {
 		return len(buf)
 	}
 
+	if logPackets {
+		logInboundShortPacket(c, p)
+	}
 	ackEliciting := c.handleFrames(now, packetType1RTT, appDataSpace, p.payload)
 	c.acks[appDataSpace].receive(now, appDataSpace, p.num, ackEliciting)
 	return len(buf)

internal/quic/conn_send.go

@@ -59,6 +59,9 @@ func (c *Conn) maybeSend(now time.Time) (next time.Time) {
 			}
 			c.w.startProtectedLongHeaderPacket(pnumMaxAcked, p)
 			c.appendFrames(now, initialSpace, pnum, limit)
+			if logPackets {
+				logSentPacket(c, packetTypeInitial, pnum, p.srcConnID, p.dstConnID, c.w.payload())
+			}
 			sentInitial = c.w.finishProtectedLongHeaderPacket(pnumMaxAcked, k, p)
 			if sentInitial != nil {
 				// Client initial packets need to be sent in a datagram padded to
@@ -83,6 +86,9 @@ func (c *Conn) maybeSend(now time.Time) (next time.Time) {
 			}
 			c.w.startProtectedLongHeaderPacket(pnumMaxAcked, p)
 			c.appendFrames(now, handshakeSpace, pnum, limit)
+			if logPackets {
+				logSentPacket(c, packetTypeHandshake, pnum, p.srcConnID, p.dstConnID, c.w.payload())
+			}
 			if sent := c.w.finishProtectedLongHeaderPacket(pnumMaxAcked, k, p); sent != nil {
 				c.loss.packetSent(now, handshakeSpace, sent)
 				if c.side == clientSide {
@@ -108,6 +114,9 @@ func (c *Conn) maybeSend(now time.Time) (next time.Time) {
 				c.w.appendPaddingTo(minimumClientInitialDatagramSize)
 				pad = false
 			}
+			if logPackets {
+				logSentPacket(c, packetType1RTT, pnum, nil, dstConnID, c.w.payload())
+			}
 			if sent := c.w.finish1RTTPacket(pnum, pnumMaxAcked, dstConnID, k); sent != nil {
 				c.loss.packetSent(now, appDataSpace, sent)
 			}

internal/quic/log.go

@@ -0,0 +1,69 @@
+// Copyright 2023 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+//go:build go1.21
+
+package quic
+
+import (
+	"fmt"
+	"os"
+	"strings"
+)
+
+var logPackets bool
+
+// Parse GODEBUG settings.
+//
+// GODEBUG=quiclogpackets=1 -- log every packet sent and received.
+func init() {
+	s := os.Getenv("GODEBUG")
+	for len(s) > 0 {
+		var opt string
+		opt, s, _ = strings.Cut(s, ",")
+		switch opt {
+		case "quiclogpackets=1":
+			logPackets = true
+		}
+	}
+}
+
+func logInboundLongPacket(c *Conn, p longPacket) {
+	if !logPackets {
+		return
+	}
+	prefix := c.String()
+	fmt.Printf("%v recv %v %v\n", prefix, p.ptype, p.num)
+	logFrames(prefix+"   <- ", p.payload)
+}
+
+func logInboundShortPacket(c *Conn, p shortPacket) {
+	if !logPackets {
+		return
+	}
+	prefix := c.String()
+	fmt.Printf("%v recv 1-RTT %v\n", prefix, p.num)
+	logFrames(prefix+"   <- ", p.payload)
+}
+
+func logSentPacket(c *Conn, ptype packetType, pnum packetNumber, src, dst, payload []byte) {
+	if !logPackets || len(payload) == 0 {
+		return
+	}
+	prefix := c.String()
+	fmt.Printf("%v send %v %v\n", prefix, ptype, pnum)
+	logFrames(prefix+"   -> ", payload)
+}
+
+func logFrames(prefix string, payload []byte) {
+	for len(payload) > 0 {
+		f, n := parseDebugFrame(payload)
+		if n < 0 {
+			fmt.Printf("%vBAD DATA\n", prefix)
+			break
+		}
+		payload = payload[n:]
+		fmt.Printf("%v%v\n", prefix, f)
+	}
+}