From ebda9b3736a685d667c856bce4f2e0d109bdede6 Mon Sep 17 00:00:00 2001 From: David Benjamin Date: Mon, 2 Nov 2015 15:33:18 -0500 Subject: [PATCH] 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 --- ssl/test/runner/packet_adapter.go | 15 +++++- ssl/test/runner/recordingconn.go | 90 +++++++++++++++++-------------- ssl/test/runner/runner.go | 34 ++++++++---- 3 files changed, 89 insertions(+), 50 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) appendFlow(flowType flowType, message string, data []byte) { + r.Lock() + defer r.Unlock() + + 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].data = append(r.flows[l-1].data, data...) + } } func (r *recordingConn) Read(b []byte) (n int, err error) { if n, err = r.Conn.Read(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 = true + 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,22 +244,36 @@ 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 *flagDebug { - connDebug = &recordingConn{Conn: conn} - 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 *flagDebug { + 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 config.Bugs.PacketAdaptor != nil { + config.Bugs.PacketAdaptor.debug = connDebug + } + } + + if test.replayWrites { + conn = newReplayAdaptor(conn) } if test.damageFirstWrite {