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

Route stdout logging through t.Log when a *testing.T is available so go test -json attributes each line to the correct parallel test (#1871). Also teach terratest_log_parser to de-interleave the resulting indented, framework-decorated lines by the test name they embed.

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",
 		},

modules/core/logger/parser/parser.go

@@ -56,6 +56,11 @@ var (
 	regexStatus  = regexp.MustCompile(`=== (RUN|PAUSE|CONT)\s+(.+)`)
 	regexSummary = regexp.MustCompile(`(^FAIL$)|(^(ok|FAIL)\s+([^ ]+)\s+(?:(\d+\.\d+)s|\(cached\)|(\[\w+ failed]))(?:\s+coverage:\s+(\d+\.\d+)%\sof\sstatements(?:\sin\s.+)?)?$)`)
 	regexPanic   = regexp.MustCompile(`^panic:`)
+	// regexIndentedTerratestLog matches a terratest log line emitted through t.Log: the testing framework indents it
+	// and prepends its own "file.go:NN: " decoration, e.g. "    apply_test.go:42: TestFoo 2006-01-02T15:04:05Z07:00
+	// caller.go:7: message". It captures the embedded test name so parallel output can still be de-interleaved. The
+	// "TestName <RFC3339 timestamp>" signature is what distinguishes a terratest line from an ordinary t.Log line.
+	regexIndentedTerratestLog = regexp.MustCompile(`^\s+\S+:\d+:\s+(Test\S*)\s+\d{4}-\d{2}-\d{2}T`)
 )
 
 // GetIndent takes a line and returns the indent string
@@ -109,6 +114,19 @@ func IsPanicLine(text string) bool {
 	return regexPanic.MatchString(text)
 }
 
+// IsIndentedTerratestLogLine checks whether a line is a terratest log line that was emitted through t.Log, i.e. indented
+// by the testing framework and prefixed with its "file.go:NN: " decoration. See regexIndentedTerratestLog.
+func IsIndentedTerratestLogLine(text string) bool {
+	return regexIndentedTerratestLog.MatchString(text)
+}
+
+// GetTestNameFromIndentedTerratestLogLine extracts the test name embedded in a terratest log line emitted through
+// t.Log. See regexIndentedTerratestLog.
+func GetTestNameFromIndentedTerratestLogLine(text string) string {
+	m := regexIndentedTerratestLog.FindStringSubmatch(text)
+	return m[1]
+}
+
 // parseAndStoreTestOutput will take test log entries from terratest and aggregate the output by test. Takes advantage
 // of the fact that terratest logs are prefixed by the test name. This will store the broken out logs into files under
 // the outputDir, named by test name.
@@ -170,8 +188,8 @@ func parseAndStoreTestOutput(
 			case strings.HasPrefix(data, "Test"):
 				// Heuristic: `go test` will only execute test functions named `Test.*`, so we assume any line prefixed
 				// with `Test` is a test output for a named test. Also assume that test output will be space delimited and
-				// test names can't contain spaces (because they are function names).
-				// This must be modified when `logger.DoLog` changes.
+				// test names can't contain spaces (because they are function names). This handles un-indented terratest
+				// output, i.e. the stdout fallback path in logger.DoLog (used when no *testing.T is available).
 				vals := strings.Split(data, " ")
 				testName := vals[0]
 				previousTestName = testName
@@ -180,6 +198,19 @@ func parseAndStoreTestOutput(
 					logger.Errorf("Error writing log for test %s: %s", testName, writeErr)
 				}
 
+			case IsIndentedTerratestLogLine(data):
+				// When a *testing.T is available, logger.DoLog emits through t.Log, so terratest lines are indented and
+				// carry the framework's "file.go:NN: " decoration before the terratest prefix. The line still embeds its
+				// owning test name, so we extract and attribute it directly. This is what preserves de-interleaving of
+				// parallel tests: the `=== CONT` status lines alone cannot, since both tests resume up front and never
+				// pause again, so previousTestName would otherwise misattribute every line to the last test resumed.
+				testName := GetTestNameFromIndentedTerratestLogLine(data)
+				previousTestName = testName
+
+				if writeErr := logWriter.WriteLog(logger, testName, data); writeErr != nil {
+					logger.Errorf("Error writing log for test %s: %s", testName, writeErr)
+				}
+
 			case isIndented && IsResultLine(data):
 				// In a nested test result block, so collect the line into all the test results we have seen so far.
 				for _, marker := range testResultMarkers {

modules/core/logger/parser/terratest_log_line_test.go

@@ -0,0 +1,112 @@
+package parser_test
+
+import (
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+
+	"github.com/gruntwork-io/terratest/modules/core/v2/logger/parser"
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+func TestIsIndentedTerratestLogLine(t *testing.T) {
+	t.Parallel()
+
+	testCases := []struct {
+		name string
+		in   string
+		out  bool
+	}{
+		{
+			name: "IndentedTerratestLine",
+			in:   "    apply_test.go:42: TestFoo 2026-07-18T13:36:46-04:00 logger.go:81: applying",
+			out:  true,
+		},
+		{
+			name: "IndentedSubtestLine",
+			in:   "        apply_test.go:42: TestFoo/Sub1 2026-07-18T13:36:46-04:00 logger.go:81: applying",
+			out:  true,
+		},
+		{
+			name: "UnindentedTerratestLine",
+			in:   "TestFoo 2026-07-18T13:36:46-04:00 logger.go:81: applying",
+			out:  false,
+		},
+		{
+			name: "PlainTLogLine",
+			in:   "    apply_test.go:42: some plain message",
+			out:  false,
+		},
+		{
+			name: "IndentedResultLine",
+			in:   "    --- PASS: TestFoo (0.02s)",
+			out:  false,
+		},
+	}
+
+	for _, testCase := range testCases {
+		testCase := testCase
+		t.Run(testCase.name, func(t *testing.T) {
+			t.Parallel()
+			assert.Equal(t, testCase.out, parser.IsIndentedTerratestLogLine(testCase.in))
+		})
+	}
+}
+
+func TestGetTestNameFromIndentedTerratestLogLine(t *testing.T) {
+	t.Parallel()
+
+	assert.Equal(t, "TestFoo", parser.GetTestNameFromIndentedTerratestLogLine(
+		"    apply_test.go:42: TestFoo 2026-07-18T13:36:46-04:00 logger.go:81: applying"))
+	assert.Equal(t, "TestFoo/Sub1", parser.GetTestNameFromIndentedTerratestLogLine(
+		"        apply_test.go:42: TestFoo/Sub1 2026-07-18T13:36:46-04:00 logger.go:81: applying"))
+}
+
+// TestSpawnParsersDeinterleavesTLogOutput verifies that the parser de-interleaves parallel-test output that terratest
+// now emits through t.Log (indented and decorated by the testing framework). Both tests resume up front, so the
+// `=== CONT` status lines cannot distinguish them; correct attribution relies on the test name embedded in each line.
+func TestSpawnParsersDeinterleavesTLogOutput(t *testing.T) {
+	t.Parallel()
+
+	// Interleaved `go test -v` output (non-JSON) as produced after logging is routed through t.Log.
+	sample := strings.Join([]string{
+		"=== RUN   TestParA",
+		"=== PAUSE TestParA",
+		"=== RUN   TestParB",
+		"=== PAUSE TestParB",
+		"=== CONT  TestParA",
+		"=== CONT  TestParB",
+		"    a_test.go:10: TestParA 2026-07-18T13:36:46-04:00 logger.go:81: MARKA payload 0",
+		"    b_test.go:20: TestParB 2026-07-18T13:36:46-04:00 logger.go:81: MARKB payload 0",
+		"    b_test.go:20: TestParB 2026-07-18T13:36:46-04:00 logger.go:81: MARKB payload 1",
+		"    a_test.go:10: TestParA 2026-07-18T13:36:46-04:00 logger.go:81: MARKA payload 1",
+		"    a_test.go:10: TestParA 2026-07-18T13:36:46-04:00 logger.go:81: MARKA payload 2",
+		"    b_test.go:20: TestParB 2026-07-18T13:36:46-04:00 logger.go:81: MARKB payload 2",
+		"--- PASS: TestParA (0.02s)",
+		"--- PASS: TestParB (0.02s)",
+		"PASS",
+		"ok  \tpkg\t0.10s",
+		"",
+	}, "\n")
+
+	out := t.TempDir()
+	parser.SpawnParsers(logrus.New(), strings.NewReader(sample), out)
+
+	readLog := func(test string) string {
+		b, err := os.ReadFile(filepath.Join(out, test+".log"))
+		require.NoError(t, err, "expected a log file for %s", test)
+
+		return string(b)
+	}
+
+	a := readLog("TestParA")
+	assert.Equal(t, 3, strings.Count(a, "MARKA"), "TestParA.log should contain all of its own lines")
+	assert.NotContains(t, a, "MARKB", "TestParA.log should not contain TestParB output")
+
+	b := readLog("TestParB")
+	assert.Equal(t, 3, strings.Count(b, "MARKB"), "TestParB.log should contain all of its own lines")
+	assert.NotContains(t, b, "MARKA", "TestParB.log should not contain TestParA output")
+}