fix(logger): attribute parallel logs to the correct test under go test -json

The default Terratest logger wrote formatted lines straight to os.Stdout. For
parallel tests, go test -json cannot tell which test a raw stdout write belongs
to, so it tags each line with whichever test was active, mixing up the output of
parallel tests (issue #1871).

When a *testing.T is available, DoLog now routes the line through t.Log so the
framework attributes it to the correct test, including under t.Parallel(). t.Log
still streams immediately under -v on Go 1.14+, and an explicit non-stdout writer
is still honored. If the test has already completed, it falls back to a direct
stdout write instead of panicking.

Author: james00012

modules/core/logger/logger.go

@@ -44,6 +44,10 @@ var (
 	//    because there is no log output with t.Logf (e.g., CircleCI kills tests after 10 minutes of no log output). With
 	//    this log method, you get log output continuously.
 	//
+	// When a *testing.T is available, the log is emitted through t.Log rather than written to stdout directly, so that
+	// `go test -json` attributes each line to the correct test even when tests run in parallel (see DoLog and issue
+	// #1871). t.Log still streams immediately under `-v` on Go 1.14+, so the benefits above are preserved.
+	//
 	Terratest = New(terratestLogger{})
 	// TestingT can be used to use Go's testing.T to log. If this is used, but no testing.T is provided, it will fallback
 	// to Default.
@@ -109,6 +113,10 @@ func (testingT) Logf(t testing.TestingT, format string, args ...any) {
 type terratestLogger struct{}
 
 func (terratestLogger) Logf(t testing.TestingT, format string, args ...any) {
+	if h, ok := t.(helper); ok {
+		h.Helper()
+	}
+
 	DoLog(t, callDepthWrapped, os.Stdout, fmt.Sprintf(format, args...))
 }
 
@@ -132,13 +140,52 @@ var MutexStdout sync.Mutex
 // DoLog logs the given arguments to the given writer, along with a timestamp and information about what test and file is
 // doing the logging.
 func DoLog(t testing.TestingT, callDepth int, writer io.Writer, args ...any) {
+	if h, ok := t.(helper); ok {
+		h.Helper()
+	}
+
 	date := time.Now()
 	prefix := fmt.Sprintf("%s %s %s:", t.Name(), date.Format(time.RFC3339), CallerPrefix(callDepth+1))
 	allArgs := append([]any{prefix}, args...)
 
+	// When we would otherwise write to stdout and a *testing.T is available, route the line through t.Log instead.
+	// This lets `go test -json` attribute each line to the correct test, which it cannot do for raw stdout writes made
+	// by tests running in parallel: such writes bypass the framework's per-test output coordination, so the JSON runner
+	// tags them with whichever test happened to be active, mixing up the output of parallel tests (issue #1871). An
+	// explicit non-stdout writer (e.g. a bytes.Buffer) is always honored as-is.
+	if writer == os.Stdout {
+		if sink, ok := t.(logSink); ok && logViaTestingT(sink, allArgs...) {
+			return
+		}
+	}
+
 	fmt.Fprintln(writer, allArgs...)
 }
 
+// logSink is satisfied by *testing.T (and *testing.B / *testing.F). See DoLog for why terratest routes stdout logging
+// through it: doing so is what allows `go test -json` to attribute output to the right test under t.Parallel().
+type logSink interface {
+	Log(args ...any)
+	Helper()
+}
+
+// logViaTestingT routes the given args through the testing.T's Log method, which formats them like fmt.Sprintln (the
+// same as fmt.Fprintln) and streams them under the testing framework so they are attributed to the right test. It
+// recovers if the test has already completed, since t.Log panics in that case, and reports false so the caller can fall
+// back to writing directly to stdout rather than crash or drop the line.
+func logViaTestingT(sink logSink, args ...any) (logged bool) {
+	defer func() {
+		if recover() != nil {
+			logged = false
+		}
+	}()
+
+	sink.Helper()
+	sink.Log(args...)
+
+	return true
+}
+
 // CallerPrefix returns the file and line number information about the methods that called this method, based on the current
 // goroutine's stack. The argument callDepth is the number of stack frames to ascend, with 0 identifying the method
 // that called CallerPrefix, 1 identifying the method that called that method, and so on.

modules/core/logger/logger_test.go

@@ -59,7 +59,52 @@ func TestCustomLogger(t *testing.T) {
 	assert.Equal(t, "subtest log", c.logs[2])
 }
 
-// TestLockedLog makes sure that Log and Logf which use stdout are thread-safe.
+// fakeTestingT implements testing.TestingT but is deliberately NOT a *testing.T and has no Log method, so logging
+// through it exercises DoLog's stdout fallback path. A real *testing.T is instead routed through t.Log (see DoLog).
+type fakeTestingT struct{ name string }
+
+func (fakeTestingT) Fail()                 {}
+func (fakeTestingT) FailNow()              {}
+func (fakeTestingT) Fatal(...any)          {}
+func (fakeTestingT) Fatalf(string, ...any) {}
+func (fakeTestingT) Error(...any)          {}
+func (fakeTestingT) Errorf(string, ...any) {}
+func (f fakeTestingT) Name() string        { return f.name }
+func (fakeTestingT) Helper()               {}
+
+// spyTestingT satisfies both testing.TestingT and the logSink that DoLog routes stdout logging through, recording each
+// Log call so tests can assert on what was routed.
+type spyTestingT struct {
+	fakeTestingT
+	logged []string
+}
+
+func (s *spyTestingT) Log(args ...any) { s.logged = append(s.logged, fmt.Sprintln(args...)) }
+
+// TestDoLogRoutesThroughTestingT verifies that DoLog routes to t.Log when writing to stdout for a *testing.T (so that
+// `go test -json` attributes output to the correct test), while always honoring an explicit non-stdout writer.
+//
+//nolint:paralleltest // asserts on os.Stdout routing
+func TestDoLogRoutesThroughTestingT(t *testing.T) {
+	// writer == os.Stdout with a testing.T-like sink: routed through Log, nothing written to the real stdout.
+	spy := &spyTestingT{fakeTestingT: fakeTestingT{name: "TestApply1"}}
+	logger.DoLog(spy, 1, os.Stdout, "routed-message")
+	require.Len(t, spy.logged, 1)
+	assert.Contains(t, spy.logged[0], "TestApply1")
+	assert.Contains(t, spy.logged[0], "routed-message")
+
+	// An explicit non-stdout writer is always honored and never routed to the sink.
+	var buf bytes.Buffer
+
+	spy2 := &spyTestingT{fakeTestingT: fakeTestingT{name: "TestApply2"}}
+
+	logger.DoLog(spy2, 1, &buf, "buffered-message")
+	assert.Empty(t, spy2.logged)
+	assert.Contains(t, buf.String(), "buffered-message")
+}
+
+// TestLockedLog makes sure that Log which uses the stdout fallback path is thread-safe. It uses fakeTestingT (not a
+// *testing.T) so DoLog writes to stdout under MutexStdout rather than routing through t.Log.
 //
 //nolint:paralleltest // test modifies os.Stdout
 func TestLockedLog(t *testing.T) {
@@ -69,19 +114,21 @@ func TestLockedLog(t *testing.T) {
 		os.Stdout = stdout
 	})
 
+	ft := fakeTestingT{name: t.Name()}
+
 	data := []struct {
 		fn   func(string)
 		name string
 	}{
 		{
 			fn: func(s string) {
-				logger.Log(t, s)
+				logger.Log(ft, s)
 			},
 			name: "Log",
 		},
 		{
 			fn: func(s string) {
-				logger.Default.Logf(t, "%s", s)
+				logger.Default.Logf(ft, "%s", s)
 			},
 			name: "Logf",
 		},