internal/testlog: fix log output from sub-loggers (#31539)

When we instantiate a sub-logger via
`go-ethereum/internal/testlog/logger.With`, we copy the reference to the
`bufHandler` from the parent logger. However, internally,
`go-ethereum/internal/testlog/logger.With` calls `log/slog/Logger.With`
which creates a new handler instance (via
`internal/bufHandler.WithAttrs`).

This PR modifies sub-logger instantiation to use the newly-instantiated
handler, instead of copying the reference from the parent instance. The
type cast from `slog.Handler` to `*bufHandler` in
`internal/testlog/Logger.With` is safe here because a
`internal/testlog/Logger` can only be instantiated with a `*bufHandler`
as the underlying handler type.

Note, that I've also removed a pre-existing method that broke the above
assumption. However, this method is not used in our codebase.

I'm not sure if the assumption holds for forks of geth (e.g. optimism
has modified the testlogger somewhat allowing test loggers to accept
arbitrary handler types), but it seems okay to break API compatibility
given that this is in the `internal` package.

closes #31533

Author: jwasinger

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