Skip to content

Commit 58d655a

Browse files
committed
fix(logger/parser): de-interleave parallel logs emitted through t.Log
Routing logs through t.Log (previous commit) indents each line and prepends the testing framework's "file.go:NN: " decoration, so terratest_log_parser's un-indented "Test"-prefix heuristic no longer matched and every parallel line fell through to the previousTestName rollup. Both parallel tests resume up front via === CONT and never pause again, so that rollup attributed all output to the last test resumed. The indented lines still embed their owning test name, so detect that format and extract the name directly, restoring correct de-interleaving. The existing un-indented case still handles the stdout fallback path. Adds unit tests for the new matcher and an end-to-end SpawnParsers test over interleaved t.Log output.
1 parent 8344898 commit 58d655a

2 files changed

Lines changed: 145 additions & 2 deletions

File tree

modules/core/logger/parser/parser.go

Lines changed: 33 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,11 @@ var (
5656
regexStatus = regexp.MustCompile(`=== (RUN|PAUSE|CONT)\s+(.+)`)
5757
regexSummary = regexp.MustCompile(`(^FAIL$)|(^(ok|FAIL)\s+([^ ]+)\s+(?:(\d+\.\d+)s|\(cached\)|(\[\w+ failed]))(?:\s+coverage:\s+(\d+\.\d+)%\sof\sstatements(?:\sin\s.+)?)?$)`)
5858
regexPanic = regexp.MustCompile(`^panic:`)
59+
// regexIndentedTerratestLog matches a terratest log line emitted through t.Log: the testing framework indents it
60+
// and prepends its own "file.go:NN: " decoration, e.g. " apply_test.go:42: TestFoo 2006-01-02T15:04:05Z07:00
61+
// caller.go:7: message". It captures the embedded test name so parallel output can still be de-interleaved. The
62+
// "TestName <RFC3339 timestamp>" signature is what distinguishes a terratest line from an ordinary t.Log line.
63+
regexIndentedTerratestLog = regexp.MustCompile(`^\s+\S+:\d+:\s+(Test\S*)\s+\d{4}-\d{2}-\d{2}T`)
5964
)
6065

6166
// GetIndent takes a line and returns the indent string
@@ -109,6 +114,19 @@ func IsPanicLine(text string) bool {
109114
return regexPanic.MatchString(text)
110115
}
111116

117+
// IsIndentedTerratestLogLine checks whether a line is a terratest log line that was emitted through t.Log, i.e. indented
118+
// by the testing framework and prefixed with its "file.go:NN: " decoration. See regexIndentedTerratestLog.
119+
func IsIndentedTerratestLogLine(text string) bool {
120+
return regexIndentedTerratestLog.MatchString(text)
121+
}
122+
123+
// GetTestNameFromIndentedTerratestLogLine extracts the test name embedded in a terratest log line emitted through
124+
// t.Log. See regexIndentedTerratestLog.
125+
func GetTestNameFromIndentedTerratestLogLine(text string) string {
126+
m := regexIndentedTerratestLog.FindStringSubmatch(text)
127+
return m[1]
128+
}
129+
112130
// parseAndStoreTestOutput will take test log entries from terratest and aggregate the output by test. Takes advantage
113131
// of the fact that terratest logs are prefixed by the test name. This will store the broken out logs into files under
114132
// the outputDir, named by test name.
@@ -170,8 +188,8 @@ func parseAndStoreTestOutput(
170188
case strings.HasPrefix(data, "Test"):
171189
// Heuristic: `go test` will only execute test functions named `Test.*`, so we assume any line prefixed
172190
// with `Test` is a test output for a named test. Also assume that test output will be space delimited and
173-
// test names can't contain spaces (because they are function names).
174-
// This must be modified when `logger.DoLog` changes.
191+
// test names can't contain spaces (because they are function names). This handles un-indented terratest
192+
// output, i.e. the stdout fallback path in logger.DoLog (used when no *testing.T is available).
175193
vals := strings.Split(data, " ")
176194
testName := vals[0]
177195
previousTestName = testName
@@ -180,6 +198,19 @@ func parseAndStoreTestOutput(
180198
logger.Errorf("Error writing log for test %s: %s", testName, writeErr)
181199
}
182200

201+
case IsIndentedTerratestLogLine(data):
202+
// When a *testing.T is available, logger.DoLog emits through t.Log, so terratest lines are indented and
203+
// carry the framework's "file.go:NN: " decoration before the terratest prefix. The line still embeds its
204+
// owning test name, so we extract and attribute it directly. This is what preserves de-interleaving of
205+
// parallel tests: the `=== CONT` status lines alone cannot, since both tests resume up front and never
206+
// pause again, so previousTestName would otherwise misattribute every line to the last test resumed.
207+
testName := GetTestNameFromIndentedTerratestLogLine(data)
208+
previousTestName = testName
209+
210+
if writeErr := logWriter.WriteLog(logger, testName, data); writeErr != nil {
211+
logger.Errorf("Error writing log for test %s: %s", testName, writeErr)
212+
}
213+
183214
case isIndented && IsResultLine(data):
184215
// In a nested test result block, so collect the line into all the test results we have seen so far.
185216
for _, marker := range testResultMarkers {
Lines changed: 112 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,112 @@
1+
package parser_test
2+
3+
import (
4+
"os"
5+
"path/filepath"
6+
"strings"
7+
"testing"
8+
9+
"github.com/gruntwork-io/terratest/modules/core/v2/logger/parser"
10+
"github.com/sirupsen/logrus"
11+
"github.com/stretchr/testify/assert"
12+
"github.com/stretchr/testify/require"
13+
)
14+
15+
func TestIsIndentedTerratestLogLine(t *testing.T) {
16+
t.Parallel()
17+
18+
testCases := []struct {
19+
name string
20+
in string
21+
out bool
22+
}{
23+
{
24+
name: "IndentedTerratestLine",
25+
in: " apply_test.go:42: TestFoo 2026-07-18T13:36:46-04:00 logger.go:81: applying",
26+
out: true,
27+
},
28+
{
29+
name: "IndentedSubtestLine",
30+
in: " apply_test.go:42: TestFoo/Sub1 2026-07-18T13:36:46-04:00 logger.go:81: applying",
31+
out: true,
32+
},
33+
{
34+
name: "UnindentedTerratestLine",
35+
in: "TestFoo 2026-07-18T13:36:46-04:00 logger.go:81: applying",
36+
out: false,
37+
},
38+
{
39+
name: "PlainTLogLine",
40+
in: " apply_test.go:42: some plain message",
41+
out: false,
42+
},
43+
{
44+
name: "IndentedResultLine",
45+
in: " --- PASS: TestFoo (0.02s)",
46+
out: false,
47+
},
48+
}
49+
50+
for _, testCase := range testCases {
51+
testCase := testCase
52+
t.Run(testCase.name, func(t *testing.T) {
53+
t.Parallel()
54+
assert.Equal(t, testCase.out, parser.IsIndentedTerratestLogLine(testCase.in))
55+
})
56+
}
57+
}
58+
59+
func TestGetTestNameFromIndentedTerratestLogLine(t *testing.T) {
60+
t.Parallel()
61+
62+
assert.Equal(t, "TestFoo", parser.GetTestNameFromIndentedTerratestLogLine(
63+
" apply_test.go:42: TestFoo 2026-07-18T13:36:46-04:00 logger.go:81: applying"))
64+
assert.Equal(t, "TestFoo/Sub1", parser.GetTestNameFromIndentedTerratestLogLine(
65+
" apply_test.go:42: TestFoo/Sub1 2026-07-18T13:36:46-04:00 logger.go:81: applying"))
66+
}
67+
68+
// TestSpawnParsersDeinterleavesTLogOutput verifies that the parser de-interleaves parallel-test output that terratest
69+
// now emits through t.Log (indented and decorated by the testing framework). Both tests resume up front, so the
70+
// `=== CONT` status lines cannot distinguish them; correct attribution relies on the test name embedded in each line.
71+
func TestSpawnParsersDeinterleavesTLogOutput(t *testing.T) {
72+
t.Parallel()
73+
74+
// Interleaved `go test -v` output (non-JSON) as produced after logging is routed through t.Log.
75+
sample := strings.Join([]string{
76+
"=== RUN TestParA",
77+
"=== PAUSE TestParA",
78+
"=== RUN TestParB",
79+
"=== PAUSE TestParB",
80+
"=== CONT TestParA",
81+
"=== CONT TestParB",
82+
" a_test.go:10: TestParA 2026-07-18T13:36:46-04:00 logger.go:81: MARKA payload 0",
83+
" b_test.go:20: TestParB 2026-07-18T13:36:46-04:00 logger.go:81: MARKB payload 0",
84+
" b_test.go:20: TestParB 2026-07-18T13:36:46-04:00 logger.go:81: MARKB payload 1",
85+
" a_test.go:10: TestParA 2026-07-18T13:36:46-04:00 logger.go:81: MARKA payload 1",
86+
" a_test.go:10: TestParA 2026-07-18T13:36:46-04:00 logger.go:81: MARKA payload 2",
87+
" b_test.go:20: TestParB 2026-07-18T13:36:46-04:00 logger.go:81: MARKB payload 2",
88+
"--- PASS: TestParA (0.02s)",
89+
"--- PASS: TestParB (0.02s)",
90+
"PASS",
91+
"ok \tpkg\t0.10s",
92+
"",
93+
}, "\n")
94+
95+
out := t.TempDir()
96+
parser.SpawnParsers(logrus.New(), strings.NewReader(sample), out)
97+
98+
readLog := func(test string) string {
99+
b, err := os.ReadFile(filepath.Join(out, test+".log"))
100+
require.NoError(t, err, "expected a log file for %s", test)
101+
102+
return string(b)
103+
}
104+
105+
a := readLog("TestParA")
106+
assert.Equal(t, 3, strings.Count(a, "MARKA"), "TestParA.log should contain all of its own lines")
107+
assert.NotContains(t, a, "MARKB", "TestParA.log should not contain TestParB output")
108+
109+
b := readLog("TestParB")
110+
assert.Equal(t, 3, strings.Count(b, "MARKB"), "TestParB.log should contain all of its own lines")
111+
assert.NotContains(t, b, "MARKA", "TestParB.log should not contain TestParA output")
112+
}

0 commit comments

Comments
 (0)