internal/testlog: fix log output from sub-loggers

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 {

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