diff --git a/internal/testlog/testlog.go b/internal/testlog/testlog.go index ad61af9eac..8a3ea85438 100644 --- a/internal/testlog/testlog.go +++ b/internal/testlog/testlog.go @@ -23,7 +23,6 @@ import ( "fmt" "log/slog" "sync" - "testing" "github.com/ethereum/go-ethereum/log" ) @@ -32,12 +31,21 @@ const ( termTimeFormat = "01-02|15:04:05.000" ) +// T wraps methods from testing.T used by the test logger into an interface. +// It is specified so that unit tests can instantiate the logger with an +// implementation of T which can capture the output of logging statements +// from T.Logf, as this cannot be using testing.T. +type T interface { + Logf(format string, args ...any) + Helper() +} + // 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 + t T l log.Logger mu *sync.Mutex h *bufHandler @@ -78,7 +86,7 @@ func (h *bufHandler) WithGroup(_ string) slog.Handler { } // Logger returns a logger which logs to the unit test log of t. -func Logger(t *testing.T, level slog.Level) log.Logger { +func Logger(t T, level slog.Level) log.Logger { handler := bufHandler{ buf: []slog.Record{}, attrs: []slog.Attr{}, @@ -92,17 +100,6 @@ func Logger(t *testing.T, level slog.Level) log.Logger { } } -// LoggerWithHandler returns -func LoggerWithHandler(t *testing.T, handler slog.Handler) log.Logger { - var bh bufHandler - return &logger{ - t: t, - l: log.NewLogger(handler), - mu: new(sync.Mutex), - h: &bh, - } -} - func (l *logger) Handler() slog.Handler { return l.l.Handler() } @@ -170,7 +167,8 @@ func (l *logger) Crit(msg string, ctx ...interface{}) { } func (l *logger) With(ctx ...interface{}) log.Logger { - return &logger{l.t, l.l.With(ctx...), l.mu, l.h} + newLogger := l.l.With(ctx...) + return &logger{l.t, newLogger, l.mu, newLogger.Handler().(*bufHandler)} } func (l *logger) New(ctx ...interface{}) log.Logger { diff --git a/internal/testlog/testlog_test.go b/internal/testlog/testlog_test.go new file mode 100644 index 0000000000..7789a47270 --- /dev/null +++ b/internal/testlog/testlog_test.go @@ -0,0 +1,67 @@ +package testlog + +import ( + "bytes" + "fmt" + "io" + "strings" + "testing" + + "github.com/ethereum/go-ethereum/log" +) + +type mockT struct { + out io.Writer +} + +func (t *mockT) Helper() { + // noop for the purposes of unit tests +} + +func (t *mockT) Logf(format string, args ...any) { + // we could gate this operation in a mutex, but because testlogger + // only calls Logf with its internal mutex held, we just write output here + var lineBuf bytes.Buffer + if _, err := fmt.Fprintf(&lineBuf, format, args...); err != nil { + panic(err) + } + // The timestamp is locale-dependent, so we want to trim that off + // "INFO [01-01|00:00:00.000] a message ..." -> "a message..." + sanitized := strings.Split(lineBuf.String(), "]")[1] + if _, err := t.out.Write([]byte(sanitized)); err != nil { + panic(err) + } +} + +func TestLogging(t *testing.T) { + tests := []struct { + name string + expected string + run func(t *mockT) + }{ + { + "SubLogger", + ` Visible + Hide and seek foobar=123 + Also visible +`, + func(t *mockT) { + l := Logger(t, log.LevelInfo) + subLogger := l.New("foobar", 123) + + l.Info("Visible") + subLogger.Info("Hide and seek") + l.Info("Also visible") + }, + }, + } + + for _, tc := range tests { + outp := bytes.Buffer{} + mock := mockT{&outp} + tc.run(&mock) + if outp.String() != tc.expected { + fmt.Printf("output mismatch.\nwant: '%s'\ngot: '%s'\n", tc.expected, outp.String()) + } + } +} diff --git a/tests/testdata b/tests/testdata index 81862e4848..faf33b4714 160000 --- a/tests/testdata +++ b/tests/testdata @@ -1 +1 @@ -Subproject commit 81862e4848585a438d64f911a19b3825f0f4cd95 +Subproject commit faf33b471465d3c6cdc3d04fbd690895f78d33f2