diff --git a/internal/quic/conn.go b/internal/quic/conn.go index 8130c549b9..ff03bd7f87 100644 --- a/internal/quic/conn.go +++ b/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) { diff --git a/internal/quic/conn_recv.go b/internal/quic/conn_recv.go index 7eb03e7279..3baa79a0cc 100644 --- a/internal/quic/conn_recv.go +++ b/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) diff --git a/internal/quic/conn_send.go b/internal/quic/conn_send.go index 71d24e6f0f..62c9b62ec7 100644 --- a/internal/quic/conn_send.go +++ b/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) } diff --git a/internal/quic/log.go b/internal/quic/log.go new file mode 100644 index 0000000000..d7248343b0 --- /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) + } +}