From 7e256e0ebe3564e14b9db0d0b7d903877127e344 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Mon, 15 May 2017 15:00:17 +0800 Subject: [PATCH] log timestamps --- example/client/main.go | 1 + example/main.go | 1 + frames/log_test.go | 12 ++++++------ session.go | 6 +++--- utils/log.go | 21 +++++++++++++++++++-- utils/log_test.go | 30 +++++++++++++++++++++++++++--- 6 files changed, 57 insertions(+), 14 deletions(-) diff --git a/example/client/main.go b/example/client/main.go index 549db89c..21bc5cef 100644 --- a/example/client/main.go +++ b/example/client/main.go @@ -21,6 +21,7 @@ func main() { } else { utils.SetLogLevel(utils.LogLevelInfo) } + utils.SetLogTimeFormat("") hclient := &http.Client{ Transport: &h2quic.QuicRoundTripper{}, diff --git a/example/main.go b/example/main.go index 96be4f7c..63f63bb5 100644 --- a/example/main.go +++ b/example/main.go @@ -128,6 +128,7 @@ func main() { } else { utils.SetLogLevel(utils.LogLevelInfo) } + utils.SetLogTimeFormat("") certFile := *certPath + "/fullchain.pem" keyFile := *certPath + "/privkey.pem" diff --git a/frames/log_test.go b/frames/log_test.go index d4f419c4..5151f837 100644 --- a/frames/log_test.go +++ b/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")) }) }) diff --git a/session.go b/session.go index 70622620..3b7f6b9b 100644 --- a/session.go +++ b/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) } diff --git a/utils/log.go b/utils/log.go index af2b6bd3..952052c0 100644 --- a/utils/log.go +++ b/utils/log.go @@ -6,6 +6,7 @@ import ( "os" "strconv" "sync" + "time" ) // LogLevel of quic-go @@ -25,8 +26,9 @@ const ( ) var ( - logLevel = LogLevelNothing - out io.Writer = os.Stdout + logLevel = LogLevelNothing + 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 diff --git a/utils/log_test.go b/utils/log_test.go index 5d299997..1bb2c297 100644 --- a/utils/log_test.go +++ b/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() {