Make recordingconn emit more useful things for DTLS.

It's somewhat annoying to have to parse out the packetAdaptor mini-language.
Actually seeing those is only useful when debugging the adaptor itself, rather
than DTLS. Switch the order of the two middleware bits and add an escape hatch
to log the funny opcodes.

Change-Id: I249c45928a76b747d69f3ab972ea4d31e0680a62
Reviewed-on: https://boringssl-review.googlesource.com/6416
Reviewed-by: Adam Langley <agl@google.com>

3 files changed, 86 insertions, 47 deletions

diff --git a/ssl/test/runner/packet_adapter.go b/ssl/test/runner/packet_adapter.go
index b4326596..2351eb0f 100644
--- a/ssl/test/runner/packet_adapter.go
+++ b/ssl/test/runner/packet_adapter.go
@@ -28,13 +28,22 @@ const opcodeTimeoutAck = byte('t')
 
 type packetAdaptor struct {
 	net.Conn
+	debug *recordingConn
 }
 
 // newPacketAdaptor wraps a reliable streaming net.Conn into a reliable
 // packet-based net.Conn. The stream contains packets and control commands,
 // distinguished by a one byte opcode.
 func newPacketAdaptor(conn net.Conn) *packetAdaptor {
-	return &packetAdaptor{conn}
+	return &packetAdaptor{conn, nil}
+}
+
+func (p *packetAdaptor) log(message string, data []byte) {
+	if p.debug == nil {
+		return
+	}
+
+	p.debug.LogSpecial(message, data)
 }
 
 func (p *packetAdaptor) readOpcode() (byte, error) {
@@ -87,6 +96,8 @@ func (p *packetAdaptor) Write(b []byte) (int, error) {
 // for acknowledgement of the timeout, buffering any packets received since
 // then. The packets are then returned.
 func (p *packetAdaptor) SendReadTimeout(d time.Duration) ([][]byte, error) {
+	p.log("Simulating read timeout: " + d.String(), nil)
+
 	payload := make([]byte, 1+8)
 	payload[0] = opcodeTimeout
 	binary.BigEndian.PutUint64(payload[1:], uint64(d.Nanoseconds()))
@@ -102,6 +113,7 @@ func (p *packetAdaptor) SendReadTimeout(d time.Duration) ([][]byte, error) {
 		}
 		switch opcode {
 		case opcodeTimeoutAck:
+			p.log("Received timeout ACK", nil)
 			// Done! Return the packets buffered and continue.
 			return packets, nil
 		case opcodePacket:
@@ -110,6 +122,7 @@ func (p *packetAdaptor) SendReadTimeout(d time.Duration) ([][]byte, error) {
 			if err != nil {
 				return nil, err
 			}
+			p.log("Simulating dropped packet", packet)
 			packets = append(packets, packet)
 		default:
 			return nil, fmt.Errorf("unexpected opcode '%d'", opcode)
diff --git a/ssl/test/runner/recordingconn.go b/ssl/test/runner/recordingconn.go
index 65377147..39deb194 100644
--- a/ssl/test/runner/recordingconn.go
+++ b/ssl/test/runner/recordingconn.go
@@ -12,33 +12,49 @@ import (
 	"sync"
 )
 
+type flowType int
+
+const (
+	readFlow flowType = iota
+	writeFlow
+	specialFlow
+)
+
+type flow struct {
+	flowType flowType
+	message  string
+	data     []byte
+}
+
 // recordingConn is a net.Conn that records the traffic that passes through it.
 // WriteTo can be used to produce output that can be later be loaded with
 // ParseTestData.
 type recordingConn struct {
 	net.Conn
 	sync.Mutex
-	flows   [][]byte
-	reading bool
+	flows       []flow
+	isDatagram  bool
+	local, peer string
 }
 
-func (r *recordingConn) Read(b []byte) (n int, err error) {
-	if n, err = r.Conn.Read(b); n == 0 {
-		return
-	}
-	b = b[:n]
-
+func (r *recordingConn) appendFlow(flowType flowType, message string, data []byte) {
 	r.Lock()
 	defer r.Unlock()
 
-	if l := len(r.flows); l == 0 || !r.reading {
-		buf := make([]byte, len(b))
-		copy(buf, b)
-		r.flows = append(r.flows, buf)
+	if l := len(r.flows); flowType == specialFlow || r.isDatagram || l == 0 || r.flows[l-1].flowType != flowType {
+		buf := make([]byte, len(data))
+		copy(buf, data)
+		r.flows = append(r.flows, flow{flowType, message, buf})
 	} else {
-		r.flows[l-1] = append(r.flows[l-1], b[:n]...)
+		r.flows[l-1].data = append(r.flows[l-1].data, data...)
 	}
-	r.reading = true
+}
+
+func (r *recordingConn) Read(b []byte) (n int, err error) {
+	if n, err = r.Conn.Read(b); n == 0 {
+		return
+	}
+	r.appendFlow(readFlow, "", b[:n])
 	return
 }
 
@@ -46,37 +62,33 @@ func (r *recordingConn) Write(b []byte) (n int, err error) {
 	if n, err = r.Conn.Write(b); n == 0 {
 		return
 	}
-	b = b[:n]
-
-	r.Lock()
-	defer r.Unlock()
-
-	if l := len(r.flows); l == 0 || r.reading {
-		buf := make([]byte, len(b))
-		copy(buf, b)
-		r.flows = append(r.flows, buf)
-	} else {
-		r.flows[l-1] = append(r.flows[l-1], b[:n]...)
-	}
-	r.reading = false
+	r.appendFlow(writeFlow, "", b[:n])
 	return
 }
 
+// LogSpecial appends an entry to the record of type 'special'.
+func (r *recordingConn) LogSpecial(message string, data []byte) {
+	r.appendFlow(specialFlow, message, data)
+}
+
 // WriteTo writes hex dumps to w that contains the recorded traffic.
 func (r *recordingConn) WriteTo(w io.Writer) {
-	// TLS always starts with a client to server flow.
-	clientToServer := true
-
+	fmt.Fprintf(w, ">>> runner is %s, shim is %s\n", r.local, r.peer)
 	for i, flow := range r.flows {
-		source, dest := "client", "server"
-		if !clientToServer {
-			source, dest = dest, source
+		switch flow.flowType {
+		case readFlow:
+			fmt.Fprintf(w, ">>> Flow %d (%s to %s)\n", i+1, r.peer, r.local)
+		case writeFlow:
+			fmt.Fprintf(w, ">>> Flow %d (%s to %s)\n", i+1, r.local, r.peer)
+		case specialFlow:
+			fmt.Fprintf(w, ">>> Flow %d %q\n", i+1, flow.message)
+		}
+
+		if flow.data != nil {
+			dumper := hex.Dumper(w)
+			dumper.Write(flow.data)
+			dumper.Close()
 		}
-		fmt.Fprintf(w, ">>> Flow %d (%s to %s)\n", i+1, source, dest)
-		dumper := hex.Dumper(w)
-		dumper.Write(flow)
-		dumper.Close()
-		clientToServer = !clientToServer
 	}
 }
 
diff --git a/ssl/test/runner/runner.go b/ssl/test/runner/runner.go
index 17fdff94..4f0f8a3c 100644
--- a/ssl/test/runner/runner.go
+++ b/ssl/test/runner/runner.go
@@ -244,24 +244,38 @@ type testCase struct {
 var testCases []testCase
 
 func doExchange(test *testCase, config *Config, conn net.Conn, isResume bool) error {
-	var connDebug *recordingConn
 	var connDamage *damageAdaptor
+
+	if test.protocol == dtls {
+		config.Bugs.PacketAdaptor = newPacketAdaptor(conn)
+		conn = config.Bugs.PacketAdaptor
+	}
+
 	if *flagDebug {
-		connDebug = &recordingConn{Conn: conn}
+		local, peer := "client", "server"
+		if test.testType == clientTest {
+			local, peer = peer, local
+		}
+		connDebug := &recordingConn{
+			Conn:       conn,
+			isDatagram: test.protocol == dtls,
+			local:      local,
+			peer:       peer,
+		}
 		conn = connDebug
 		defer func() {
 			connDebug.WriteTo(os.Stdout)
 		}()
-	}
 
-	if test.protocol == dtls {
-		config.Bugs.PacketAdaptor = newPacketAdaptor(conn)
-		conn = config.Bugs.PacketAdaptor
-		if test.replayWrites {
-			conn = newReplayAdaptor(conn)
+		if config.Bugs.PacketAdaptor != nil {
+			config.Bugs.PacketAdaptor.debug = connDebug
 		}
 	}
 
+	if test.replayWrites {
+		conn = newReplayAdaptor(conn)
+	}
+
 	if test.damageFirstWrite {
 		connDamage = newDamageAdaptor(conn)
 		conn = connDamage