reduce calls to Debugf when not debugging to reduce slice allocs

ref #129

ackhandler/sent_packet_handler.go

@@ -198,7 +198,9 @@ func (h *sentPacketHandler) ReceivedAck(ackFrame *frames.AckFrame) error {
 	timeDelta := time.Now().Sub(h.packetHistory[h.LargestObserved].sendTime)
 	// TODO: Don't always update RTT
 	h.rttStats.UpdateRTT(timeDelta, ackFrame.DelayTime, time.Now())
+	if utils.Debug() {
 		utils.Debugf("\tEstimated RTT: %dms", h.rttStats.SmoothedRTT()/time.Millisecond)
+	}
 
 	var ackedPackets congestion.PacketVector
 	var lostPackets congestion.PacketVector

frames/log.go

@@ -0,0 +1,19 @@
+package frames
+
+import "github.com/lucas-clemente/quic-go/utils"
+
+// LogFrame logs a frame, either sent or received
+func LogFrame(frame Frame, sent bool) {
+	if !utils.Debug() {
+		return
+	}
+	dir := "<-"
+	if sent {
+		dir = "->"
+	}
+	if sf, ok := frame.(*StreamFrame); ok {
+		utils.Debugf("\t%s &frames.StreamFrame{StreamID: %d, FinBit: %t, Offset: 0x%x, Data length: 0x%x, Offset + Data length: 0x%x}", dir, sf.StreamID, sf.FinBit, sf.Offset, sf.DataLen(), sf.Offset+sf.DataLen())
+	} else {
+		utils.Debugf("\t%s %#v", dir, frame)
+	}
+}

frames/log_test.go

@@ -0,0 +1,49 @@
+package frames
+
+import (
+	"bytes"
+	"os"
+
+	"github.com/lucas-clemente/quic-go/utils"
+
+	. "github.com/onsi/ginkgo"
+	. "github.com/onsi/gomega"
+)
+
+var _ = Describe("Frame logging", func() {
+	var (
+		buf bytes.Buffer
+	)
+
+	BeforeEach(func() {
+		buf.Reset()
+		utils.SetLogLevel(utils.LogLevelDebug)
+		utils.SetLogWriter(&buf)
+	})
+
+	AfterSuite(func() {
+		utils.SetLogLevel(utils.LogLevelNothing)
+		utils.SetLogWriter(os.Stdout)
+	})
+
+	It("doesn't log when debug is disabled", func() {
+		utils.SetLogLevel(utils.LogLevelInfo)
+		LogFrame(&RstStreamFrame{}, true)
+		Expect(buf.Len()).To(BeZero())
+	})
+
+	It("logs sent frames", func() {
+		LogFrame(&RstStreamFrame{}, true)
+		Expect(string(buf.Bytes())).To(Equal("\t-> &frames.RstStreamFrame{StreamID:0x0, ByteOffset:0x0, ErrorCode:0x0}\n"))
+	})
+
+	It("logs received frames", func() {
+		LogFrame(&RstStreamFrame{}, false)
+		Expect(string(buf.Bytes())).To(Equal("\t<- &frames.RstStreamFrame{StreamID:0x0, ByteOffset:0x0, ErrorCode:0x0}\n"))
+	})
+
+	It("logs stream frames", func() {
+		LogFrame(&StreamFrame{}, false)
+		Expect(string(buf.Bytes())).To(Equal("\t<- &frames.StreamFrame{StreamID: 0, FinBit: false, Offset: 0x0, Data length: 0x0, Offset + Data length: 0x0}\n"))
+	})
+})

session.go

@@ -226,7 +226,9 @@ func (s *Session) handlePacketImpl(remoteAddr interface{}, hdr *publicHeader, da
 		hdr.PacketNumber,
 	)
 	s.lastRcvdPacketNumber = hdr.PacketNumber
+	if utils.Debug() {
 		utils.Debugf("<- Reading packet 0x%x (%d bytes) for connection %x", hdr.PacketNumber, r.Size(), hdr.ConnectionID)
+	}
 
 	// TODO: Only do this after authenticating
 	s.conn.setCurrentRemoteAddr(remoteAddr)
@@ -240,32 +242,25 @@ func (s *Session) handlePacketImpl(remoteAddr interface{}, hdr *publicHeader, da
 
 	for _, ff := range packet.frames {
 		var err error
+		frames.LogFrame(ff, false)
 		switch frame := ff.(type) {
 		case *frames.StreamFrame:
-			utils.Debugf("\t<- &frames.StreamFrame{StreamID: %d, FinBit: %t, Offset: 0x%x, Data length: 0x%x, Offset + Data length: 0x%x}", frame.StreamID, frame.FinBit, frame.Offset, frame.DataLen(), frame.Offset+frame.DataLen())
 			err = s.handleStreamFrame(frame)
 			// TODO: send RstStreamFrame
 		case *frames.AckFrame:
 			err = s.handleAckFrame(frame)
 		case *frames.ConnectionCloseFrame:
-			utils.Debugf("\t<- %#v", frame)
 			s.closeImpl(qerr.Error(frame.ErrorCode, frame.ReasonPhrase), true)
 		case *frames.GoawayFrame:
-			utils.Debugf("\t<- %#v", frame)
 			err = errors.New("unimplemented: handling GOAWAY frames")
 		case *frames.StopWaitingFrame:
-			utils.Debugf("\t<- %#v", frame)
 			err = s.receivedPacketHandler.ReceivedStopWaiting(frame)
 		case *frames.RstStreamFrame:
 			err = s.handleRstStreamFrame(frame)
-			utils.Debugf("\t<- %#v", frame)
 		case *frames.WindowUpdateFrame:
-			utils.Debugf("\t<- %#v", frame)
 			err = s.handleWindowUpdateFrame(frame)
 		case *frames.BlockedFrame:
-			utils.Infof("BLOCKED frame received for connection %x stream %d", s.connectionID, frame.StreamID)
 		case *frames.PingFrame:
-			utils.Debugf("\t<- %#v", frame)
 		default:
 			return errors.New("Session BUG: unexpected frame type")
 		}
@@ -370,7 +365,6 @@ func (s *Session) handleAckFrame(frame *frames.AckFrame) error {
 	if err := s.sentPacketHandler.ReceivedAck(frame); err != nil {
 		return err
 	}
-	utils.Debugf("\t<- %#v", frame)
 	return nil
 }
 
@@ -563,12 +557,10 @@ func (s *Session) logPacket(packet *packedPacket) {
 		// We don't need to allocate the slices for calling the format functions
 		return
 	}
+	if utils.Debug() {
 		utils.Debugf("-> Sending packet 0x%x (%d bytes)", packet.number, len(packet.raw))
 		for _, frame := range packet.frames {
-		if streamFrame, isStreamFrame := frame.(*frames.StreamFrame); isStreamFrame {
-			utils.Debugf("\t-> &frames.StreamFrame{StreamID: %d, FinBit: %t, Offset: 0x%x, Data length: 0x%x, Offset + Data length: 0x%x}", streamFrame.StreamID, streamFrame.FinBit, streamFrame.Offset, streamFrame.DataLen(), streamFrame.Offset+streamFrame.DataLen())
-		} else {
-			utils.Debugf("\t-> %#v", frame)
+			frames.LogFrame(frame, true)
 		}
 	}
 }

utils/log.go

@@ -27,6 +27,11 @@ var logLevel = LogLevelNothing
 
 var mutex sync.Mutex
 
+// SetLogWriter sets the log writer.
+func SetLogWriter(w io.Writer) {
+	out = w
+}
+
 // SetLogLevel sets the log level
 func SetLogLevel(level LogLevel) {
 	logLevel = level