proposal: testing: Share logger between test code and application code

[palsivertsen]

Proposal Details

When working with failing tests it is useful to inspect logs from both the test code and the application code. The testing.T type (among other types) exports a method, Log(...any), that one can use to log during tests. The log output is formatted in such a way that it is easy to see which test it belongs to.

The application typically uses the log or log/slog package to do its logging with outputs to os.Stderr. These logs are separate from the test logs, making it hard to correlate to specific tests.

This program highlights the issue:

package main

import (
	"log"
	"testing"
)

func Log(msg string) {
	log.Println(msg)
}

func TestLog(t *testing.T) {
	t.Log("test start")
	Log("hello world")
	t.Log("test end")
	t.Fail()
}

Test output (varies by environment):

2024/10/08 13:19:47 hello world
--- FAIL: TestLog (0.00s)
    example1_test.go:13: test start
    example1_test.go:15: test end
FAIL
FAIL	command-line-arguments	0.001s
FAIL

Note how "hello world" is the first thing that is printed and it's outside the context of the test. The output can vary by environment, go playground typically outputs in desired order.

A solution to this problem is to share a common logger between test and application code. I implemented a wrapper around a .Log(...any) interface to highlight the desired effect. A more robust implementation should probably implement the slog.Handler interface.

Play

Code

package main

import (
	"log/slog"
	"os"
	"testing"
)

func TestILogStuff_LogThis(t *testing.T) {
	tests := map[string]struct {
		newLogger func(tb testing.TB) *slog.Logger
	}{
		"text handler": {
			newLogger: func(tb testing.TB) *slog.Logger { return slog.New(slog.NewTextHandler(os.Stderr, nil)) },
		},
		"text handler with testing.TB writer": {
			newLogger: func(tb testing.TB) *slog.Logger { return slog.New(slog.NewTextHandler(testingTBWriter{tb: tb}, nil)) },
		},
	}
	for name, tt := range tests {
		t.Run(name, func(t *testing.T) {
			logger := tt.newLogger(t).
				With("test name", t.Name())

			unit := Example{
				Logger: logger.With("source", "the unit being tested"),
			}

			t.Log("test start")
			unit.Log("hello world!")
			t.Log("test end")

			t.Fail()
		})
	}
}

type Example struct {
	Logger *slog.Logger
}

func (l *Example) Log(msg string) {
	l.Logger.Info(msg)
}

// testingTBWriter is a naive io.Writer implementation that writes to tb.Log.
// This implementation is intended to demonstrate log output in tests.
// A potential issue with this approach is that lines might not align with the
// bytes given to the Write function.
// A better approach would be to use a type that implements the slog.Handler
// interface and wraps a TestLogger.
type testingTBWriter struct {
	tb TestLogger
}

func (w testingTBWriter) Write(b []byte) (int, error) {
	w.tb.Log(string(b))
	return len(b), nil
}

type TestLogger interface {
	Log(...any)
}

Output (varies by environment):

time=2024-10-08T13:26:24.945+02:00 level=INFO msg="hello world!" "test name"=TestILogStuff_LogThis/text_handler source="the unit being tested"
--- FAIL: TestILogStuff_LogThis (0.00s)
    --- FAIL: TestILogStuff_LogThis/text_handler (0.00s)
        example_test.go:29: test start
        example_test.go:31: test end
    --- FAIL: TestILogStuff_LogThis/text_handler_with_testing.TB_writer (0.00s)
        example_test.go:29: test start
        example_test.go:57: time=2024-10-08T13:26:24.945+02:00 level=INFO msg="hello world!" "test name"=TestILogStuff_LogThis/text_handler_with_testing.TB_writer source="the unit being tested"
            
        example_test.go:31: test end
FAIL
FAIL	command-line-arguments	0.001s
FAIL

[gabyhelp]

Related Issues and Documentation

• proposal: testing: Add LogWriter() method to testing.T for usage with log.Logger #39519
• proposal: testing: add log.Logger adapter to testing.T #22513 (closed)
• proposal: testing: make Log output configurable #28544 (closed)
• proposal: testing: Collect test failure logs on the testing.common struct and expose collected logs via a new method on testing.TB #61860
• proposal: testing: implement io.Writer with T and B #28778 (closed)
• testing: stream t.Log output as it happens #24929 (closed)
• proposal: log: wrap testlog.SetLogger() Visible to the public in package log. #40720 (closed)
• proposal: affected/package: testing #58586 (closed)
• proposal: testing: Add T.Output() etc #59928
• Proposal: Go 2: Create logger interface in the standard log package, with additional levels. Optionally add it to context package, too #28412 (closed)

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[mateusz834]

A solution to this problem is to share a common logger between test and application code.

I always use the -v flag, see:

$ go test . -v
=== RUN   TestLog
    main_test.go:13: test start
2024/10/08 14:02:12 hello world
    main_test.go:15: test end
--- FAIL: TestLog (0.00s)

EDIT: actually this is: #24929

[seankhliao]

Duplicate of #59928