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

Author: fjl

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
+}