quic: add -vv flag for more verbose tests

Add a -vv flag to make tests log each packet sent/received.
Disable logging of packets generally not relevant to the test,
namely the handshake and the series of pings and acks used
to trigger loss detection in loss tests.

For golang/go#58547

Change-Id: I69c7f6743436648c2c2f202e38c3f6fb2c73c802
Reviewed-on: https://go-review.googlesource.com/c/net/+/515339
Run-TryBot: Damien Neil <[email protected]>
TryBot-Result: Gopher Robot <[email protected]>
Reviewed-by: Jonathan Amsterdam <[email protected]>

Author: neild

internal/quic/conn_loss_test.go

@@ -30,9 +30,19 @@ func (tc *testConn) triggerLossOrPTO(ptype packetType, pto bool) {
 		if !tc.conn.loss.ptoTimerArmed {
 			tc.t.Fatalf("PTO timer not armed, expected it to be")
 		}
+		if *testVV {
+			tc.t.Logf("advancing to PTO timer")
+		}
 		tc.advanceTo(tc.conn.loss.timer)
 		return
 	}
+	if *testVV {
+		*testVV = false
+		defer func() {
+			tc.t.Logf("cause conn to declare last packet lost")
+			*testVV = true
+		}()
+	}
 	defer func(ignoreFrames map[byte]bool) {
 		tc.ignoreFrames = ignoreFrames
 	}(tc.ignoreFrames)

internal/quic/conn_test.go

@@ -11,6 +11,7 @@ import (
 	"context"
 	"crypto/tls"
 	"errors"
+	"flag"
 	"fmt"
 	"math"
 	"net/netip"
@@ -20,6 +21,8 @@ import (
 	"time"
 )
 
+var testVV = flag.Bool("vv", false, "even more verbose test output")
+
 func TestConnTestConn(t *testing.T) {
 	tc := newTestConn(t, serverSide)
 	if got, want := tc.timeUntilEvent(), defaultMaxIdleTimeout; got != want {
@@ -308,10 +311,34 @@ func (tc *testConn) cleanup() {
 	tc.conn.exit()
 }
 
+func (tc *testConn) logDatagram(text string, d *testDatagram) {
+	tc.t.Helper()
+	if !*testVV {
+		return
+	}
+	pad := ""
+	if d.paddedSize > 0 {
+		pad = fmt.Sprintf(" (padded to %v)", d.paddedSize)
+	}
+	tc.t.Logf("%v datagram%v", text, pad)
+	for _, p := range d.packets {
+		switch p.ptype {
+		case packetType1RTT:
+			tc.t.Logf("  %v pnum=%v", p.ptype, p.num)
+		default:
+			tc.t.Logf("  %v pnum=%v ver=%v dst={%x} src={%x}", p.ptype, p.num, p.version, p.dstConnID, p.srcConnID)
+		}
+		for _, f := range p.frames {
+			tc.t.Logf("    %v", f)
+		}
+	}
+}
+
 // write sends the Conn a datagram.
 func (tc *testConn) write(d *testDatagram) {
 	tc.t.Helper()
 	var buf []byte
+	tc.logDatagram("<- conn under test receives", d)
 	for _, p := range d.packets {
 		space := spaceForPacketType(p.ptype)
 		if p.num >= tc.peerNextPacketNum[space] {
@@ -374,7 +401,9 @@ func (tc *testConn) readDatagram() *testDatagram {
 	}
 	buf := tc.sentDatagrams[0]
 	tc.sentDatagrams = tc.sentDatagrams[1:]
-	return tc.parseTestDatagram(buf)
+	d := tc.parseTestDatagram(buf)
+	tc.logDatagram("-> conn under test sends", d)
+	return d
 }
 
 // readPacket reads the next packet sent by the Conn.

internal/quic/tls_test.go

@@ -18,6 +18,13 @@ import (
 // handshake executes the handshake.
 func (tc *testConn) handshake() {
 	tc.t.Helper()
+	if *testVV {
+		*testVV = false
+		defer func() {
+			*testVV = true
+			tc.t.Logf("performed connection handshake")
+		}()
+	}
 	defer func(saved map[byte]bool) {
 		tc.ignoreFrames = saved
 	}(tc.ignoreFrames)