log timestamps

example/client/main.go

@@ -21,6 +21,7 @@ func main() {
 	} else {
 		utils.SetLogLevel(utils.LogLevelInfo)
 	}
+	utils.SetLogTimeFormat("")
 
 	hclient := &http.Client{
 		Transport: &h2quic.QuicRoundTripper{},

example/main.go

@@ -128,6 +128,7 @@ func main() {
 	} else {
 		utils.SetLogLevel(utils.LogLevelInfo)
 	}
+	utils.SetLogTimeFormat("")
 
 	certFile := *certPath + "/fullchain.pem"
 	keyFile := *certPath + "/privkey.pem"

frames/log_test.go

@@ -36,12 +36,12 @@ var _ = Describe("Frame logging", func() {
 
 	It("logs sent frames", func() {
 		LogFrame(&RstStreamFrame{}, true)
-		Expect(string(buf.Bytes())).To(Equal("\t-> &frames.RstStreamFrame{StreamID:0x0, ErrorCode:0x0, ByteOffset:0x0}\n"))
+		Expect(buf.Bytes()).To(ContainSubstring("\t-> &frames.RstStreamFrame{StreamID:0x0, ErrorCode:0x0, ByteOffset:0x0}\n"))
 	})
 
 	It("logs received frames", func() {
 		LogFrame(&RstStreamFrame{}, false)
-		Expect(string(buf.Bytes())).To(Equal("\t<- &frames.RstStreamFrame{StreamID:0x0, ErrorCode:0x0, ByteOffset:0x0}\n"))
+		Expect(buf.Bytes()).To(ContainSubstring("\t<- &frames.RstStreamFrame{StreamID:0x0, ErrorCode:0x0, ByteOffset:0x0}\n"))
 	})
 
 	It("logs stream frames", func() {
@@ -51,7 +51,7 @@ var _ = Describe("Frame logging", func() {
 			Data:     bytes.Repeat([]byte{'f'}, 0x100),
 		}
 		LogFrame(frame, false)
-		Expect(string(buf.Bytes())).To(Equal("\t<- &frames.StreamFrame{StreamID: 42, FinBit: false, Offset: 0x1337, Data length: 0x100, Offset + Data length: 0x1437}\n"))
+		Expect(buf.Bytes()).To(ContainSubstring("\t<- &frames.StreamFrame{StreamID: 42, FinBit: false, Offset: 0x1337, Data length: 0x100, Offset + Data length: 0x1437}\n"))
 	})
 
 	It("logs ACK frames", func() {
@@ -61,7 +61,7 @@ var _ = Describe("Frame logging", func() {
 			DelayTime:    1 * time.Millisecond,
 		}
 		LogFrame(frame, false)
-		Expect(string(buf.Bytes())).To(Equal("\t<- &frames.AckFrame{LargestAcked: 0x1337, LowestAcked: 0x42, AckRanges: []frames.AckRange(nil), DelayTime: 1ms}\n"))
+		Expect(buf.Bytes()).To(ContainSubstring("\t<- &frames.AckFrame{LargestAcked: 0x1337, LowestAcked: 0x42, AckRanges: []frames.AckRange(nil), DelayTime: 1ms}\n"))
 	})
 
 	It("logs incoming StopWaiting frames", func() {
@@ -69,7 +69,7 @@ var _ = Describe("Frame logging", func() {
 			LeastUnacked: 0x1337,
 		}
 		LogFrame(frame, false)
-		Expect(string(buf.Bytes())).To(Equal("\t<- &frames.StopWaitingFrame{LeastUnacked: 0x1337}\n"))
+		Expect(buf.Bytes()).To(ContainSubstring("\t<- &frames.StopWaitingFrame{LeastUnacked: 0x1337}\n"))
 	})
 
 	It("logs outgoing StopWaiting frames", func() {
@@ -78,6 +78,6 @@ var _ = Describe("Frame logging", func() {
 			PacketNumberLen: protocol.PacketNumberLen4,
 		}
 		LogFrame(frame, true)
-		Expect(string(buf.Bytes())).To(Equal("\t-> &frames.StopWaitingFrame{LeastUnacked: 0x1337, PacketNumberLen: 0x4}\n"))
+		Expect(buf.Bytes()).To(ContainSubstring("\t-> &frames.StopWaitingFrame{LeastUnacked: 0x1337, PacketNumberLen: 0x4}\n"))
 	})
 })

session.go

@@ -393,9 +393,9 @@ func (s *session) handlePacketImpl(p *receivedPacket) error {
 	packet, err := s.unpacker.Unpack(hdr.Raw, hdr, data)
 	if utils.Debug() {
 		if err != nil {
-			utils.Debugf("<- Reading packet 0x%x (%d bytes) for connection %x @ %s", hdr.PacketNumber, len(data)+len(hdr.Raw), hdr.ConnectionID, time.Now().Format("15:04:05.000"))
+			utils.Debugf("<- Reading packet 0x%x (%d bytes) for connection %x", hdr.PacketNumber, len(data)+len(hdr.Raw), hdr.ConnectionID)
 		} else {
-			utils.Debugf("<- Reading packet 0x%x (%d bytes) for connection %x, %s @ %s", hdr.PacketNumber, len(data)+len(hdr.Raw), hdr.ConnectionID, packet.encryptionLevel, time.Now().Format("15:04:05.000"))
+			utils.Debugf("<- Reading packet 0x%x (%d bytes) for connection %x, %s", hdr.PacketNumber, len(data)+len(hdr.Raw), hdr.ConnectionID, packet.encryptionLevel)
 		}
 	}
 	// if the decryption failed, this might be a packet sent by an attacker
@@ -735,7 +735,7 @@ func (s *session) logPacket(packet *packedPacket) {
 		return
 	}
 	if utils.Debug() {
-		utils.Debugf("-> Sending packet 0x%x (%d bytes), %s, @ %s", packet.number, len(packet.raw), packet.encryptionLevel, time.Now().Format("15:04:05.000"))
+		utils.Debugf("-> Sending packet 0x%x (%d bytes), %s", packet.number, len(packet.raw), packet.encryptionLevel)
 		for _, frame := range packet.frames {
 			frames.LogFrame(frame, true)
 		}

utils/log.go

@@ -6,6 +6,7 @@ import (
 	"os"
 	"strconv"
 	"sync"
+	"time"
 )
 
 // LogLevel of quic-go
@@ -25,8 +26,9 @@ const (
 )
 
 var (
-	logLevel           = LogLevelNothing
+	logLevel             = LogLevelNothing
-	out      io.Writer = os.Stdout
+	out        io.Writer = os.Stdout
+	timeFormat           = "15:04:05.000"
 
 	mutex sync.Mutex
 )
@@ -41,10 +43,17 @@ func SetLogLevel(level LogLevel) {
 	logLevel = level
 }
 
+// SetLogTimeFormat sets the format of the timestamp
+// an empty string disables the logging of timestamps
+func SetLogTimeFormat(format string) {
+	timeFormat = format
+}
+
 // Debugf logs something
 func Debugf(format string, args ...interface{}) {
 	if logLevel == LogLevelDebug {
 		mutex.Lock()
+		logTimestamp()
 		fmt.Fprintf(out, format+"\n", args...)
 		mutex.Unlock()
 	}
@@ -54,6 +63,7 @@ func Debugf(format string, args ...interface{}) {
 func Infof(format string, args ...interface{}) {
 	if logLevel <= LogLevelInfo {
 		mutex.Lock()
+		logTimestamp()
 		fmt.Fprintf(out, format+"\n", args...)
 		mutex.Unlock()
 	}
@@ -63,11 +73,18 @@ func Infof(format string, args ...interface{}) {
 func Errorf(format string, args ...interface{}) {
 	if logLevel <= LogLevelError {
 		mutex.Lock()
+		logTimestamp()
 		fmt.Fprintf(out, format+"\n", args...)
 		mutex.Unlock()
 	}
 }
 
+func logTimestamp() {
+	if len(timeFormat) > 0 {
+		fmt.Fprintf(out, time.Now().Format(timeFormat)+" ")
+	}
+}
+
 // Debug returns true if the log level is LogLevelDebug
 func Debug() bool {
 	return logLevel == LogLevelDebug

utils/log_test.go

@@ -3,6 +3,7 @@ package utils
 import (
 	"bytes"
 	"os"
+	"time"
 
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
@@ -36,7 +37,9 @@ var _ = Describe("Log", func() {
 		Debugf("debug")
 		Infof("info")
 		Errorf("err")
-		Expect(b.Bytes()).To(Equal([]byte("err\n")))
+		Expect(b.Bytes()).To(ContainSubstring("err\n"))
+		Expect(b.Bytes()).ToNot(ContainSubstring("info"))
+		Expect(b.Bytes()).ToNot(ContainSubstring("debug"))
 	})
 
 	It("log level info", func() {
@@ -44,7 +47,9 @@ var _ = Describe("Log", func() {
 		Debugf("debug")
 		Infof("info")
 		Errorf("err")
-		Expect(b.Bytes()).To(Equal([]byte("info\nerr\n")))
+		Expect(b.Bytes()).To(ContainSubstring("err\n"))
+		Expect(b.Bytes()).To(ContainSubstring("info\n"))
+		Expect(b.Bytes()).ToNot(ContainSubstring("debug"))
 	})
 
 	It("log level debug", func() {
@@ -52,7 +57,26 @@ var _ = Describe("Log", func() {
 		Debugf("debug")
 		Infof("info")
 		Errorf("err")
-		Expect(b.Bytes()).To(Equal([]byte("debug\ninfo\nerr\n")))
+		Expect(b.Bytes()).To(ContainSubstring("err\n"))
+		Expect(b.Bytes()).To(ContainSubstring("info\n"))
+		Expect(b.Bytes()).To(ContainSubstring("debug\n"))
+	})
+
+	It("doesn't add a timestamp if the time format is empty", func() {
+		SetLogLevel(LogLevelDebug)
+		SetLogTimeFormat("")
+		Debugf("debug")
+		Expect(b.Bytes()).To(Equal([]byte("debug\n")))
+	})
+
+	It("adds a timestamp", func() {
+		format := "Jan 2, 2006 at 3:04:05pm (MST)"
+		SetLogTimeFormat(format)
+		SetLogLevel(LogLevelInfo)
+		Infof("info")
+		t, err := time.Parse(format, string(b.Bytes()[:b.Len()-6]))
+		Expect(err).ToNot(HaveOccurred())
+		Expect(t).To(BeTemporally("~", time.Now(), 2*time.Second))
 	})
 
 	It("says whether debug is enabled", func() {