From 0218d7001d2a566b35072ee21b9f84f6b2711bbe Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Wed, 8 Jan 2020 16:11:51 +0100 Subject: [PATCH] internal/testlog: print file+line number of log call in test log (#20528) * internal/testlog: print file+line number of log call in test log This changes the unit test logger to print the actual file and line number of the logging call instead of "testlog.go:44". Output of 'go test -v -run TestServerListen ./p2p' before this change: === RUN TestServerListen --- PASS: TestServerListen (0.00s) testlog.go:44: DEBUG[01-08|15:16:31.651] UDP listener up addr=127.0.0.1:62678 testlog.go:44: DEBUG[01-08|15:16:31.651] TCP listener up addr=127.0.0.1:62678 testlog.go:44: TRACE[01-08|15:16:31.652] Accepted connection addr=127.0.0.1:62679 And after: === RUN TestServerListen --- PASS: TestServerListen (0.00s) server.go:868: DEBUG[01-08|15:25:35.679] TCP listener up addr=127.0.0.1:62712 server.go:557: DEBUG[01-08|15:25:35.679] UDP listener up addr=127.0.0.1:62712 server.go:912: TRACE[01-08|15:25:35.680] Accepted connection addr=127.0.0.1:62713 * internal/testlog: document use of t.Helper --- internal/testlog/testlog.go | 110 +++++++++++++++++++++++++++++++++--- 1 file changed, 103 insertions(+), 7 deletions(-) diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index c5a6114d1..684339f16 100644 --- a/internal/testlog/testlog.go +++ b/internal/testlog/testlog.go @@ -18,18 +18,12 @@ package testlog import ( + "sync" "testing" "github.com/ethereum/go-ethereum/log" ) -// Logger returns a logger which logs to the unit test log of t. -func Logger(t *testing.T, level log.Lvl) log.Logger { - l := log.New() - l.SetHandler(Handler(t, level)) - return l -} - // Handler returns a log handler which logs to the unit test log of t. func Handler(t *testing.T, level log.Lvl) log.Handler { return log.LvlFilterHandler(level, &handler{t, log.TerminalFormat(false)}) @@ -44,3 +38,105 @@ func (h *handler) Log(r *log.Record) error { h.t.Logf("%s", h.fmt.Format(r)) return nil } + +// logger implements log.Logger such that all output goes to the unit test log via +// t.Logf(). All methods in between logger.Trace, logger.Debug, etc. are marked as test +// helpers, so the file and line number in unit test output correspond to the call site +// which emitted the log message. +type logger struct { + t *testing.T + l log.Logger + mu *sync.Mutex + h *bufHandler +} + +type bufHandler struct { + buf []*log.Record + fmt log.Format +} + +func (h *bufHandler) Log(r *log.Record) error { + h.buf = append(h.buf, r) + return nil +} + +// Logger returns a logger which logs to the unit test log of t. +func Logger(t *testing.T, level log.Lvl) log.Logger { + l := &logger{ + t: t, + l: log.New(), + mu: new(sync.Mutex), + h: &bufHandler{fmt: log.TerminalFormat(false)}, + } + l.l.SetHandler(log.LvlFilterHandler(level, l.h)) + return l +} + +func (l *logger) Trace(msg string, ctx ...interface{}) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.Trace(msg, ctx...) + l.flush() +} + +func (l *logger) Debug(msg string, ctx ...interface{}) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.Debug(msg, ctx...) + l.flush() +} + +func (l *logger) Info(msg string, ctx ...interface{}) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.Info(msg, ctx...) + l.flush() +} + +func (l *logger) Warn(msg string, ctx ...interface{}) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.Warn(msg, ctx...) + l.flush() +} + +func (l *logger) Error(msg string, ctx ...interface{}) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.Error(msg, ctx...) + l.flush() +} + +func (l *logger) Crit(msg string, ctx ...interface{}) { + l.t.Helper() + l.mu.Lock() + defer l.mu.Unlock() + l.l.Crit(msg, ctx...) + l.flush() +} + +func (l *logger) New(ctx ...interface{}) log.Logger { + return &logger{l.t, l.l.New(ctx...), l.mu, l.h} +} + +func (l *logger) GetHandler() log.Handler { + return l.l.GetHandler() +} + +func (l *logger) SetHandler(h log.Handler) { + l.l.SetHandler(h) +} + +// flush writes all buffered messages and clears the buffer. +func (l *logger) flush() { + l.t.Helper() + for _, r := range l.h.buf { + l.t.Logf("%s", l.h.fmt.Format(r)) + } + l.h.buf = nil +}