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>
diff --git a/internal/quic/conn.go b/internal/quic/conn.go
index 8130c54..ff03bd7 100644
--- a/internal/quic/conn.go
+++ b/internal/quic/conn.go
@@ -116,6 +116,10 @@
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) {
diff --git a/internal/quic/conn_recv.go b/internal/quic/conn_recv.go
index 7eb03e7..3baa79a 100644
--- a/internal/quic/conn_recv.go
+++ b/internal/quic/conn_recv.go
@@ -60,6 +60,9 @@
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 @@
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)
diff --git a/internal/quic/conn_send.go b/internal/quic/conn_send.go
index 71d24e6..62c9b62 100644
--- a/internal/quic/conn_send.go
+++ b/internal/quic/conn_send.go
@@ -59,6 +59,9 @@
}
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 @@
}
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 @@
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)
}
diff --git a/internal/quic/log.go b/internal/quic/log.go
new file mode 100644
index 0000000..d724834
--- /dev/null
+++ b/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)
+ }
+}
