Skip to content

Commit bf642a8

Browse files
mdwhatcottmdwhatcott
committed
test2json: associate streaming log output with the originating test
Up until this commit the test2json utility made the assumption that log output should be associated with the test named in the most recent line starting with "--- PASS: Test..." or "--- FAIL: Test...". A consequence of issue #24929 is that test log output is no longer buffered (it is emitted almost immediately), making the aforementioned assumption incorrect in the case of tests run in parallel. This commit introduces a map which stores the names of all tests to facilitate attributing emitted logs with their originating tests so that readers of test2json such as IDEs and editors can align log output containing important details about specific test failures with the corresponding test name. Fixes #38050
1 parent a3d8c21 commit bf642a8

File tree

3 files changed

+114
-10
lines changed

3 files changed

+114
-10
lines changed

‎src/cmd/internal/test2json/test2json.go

+27-10
Original file line numberDiff line numberDiff line change
@@ -49,15 +49,16 @@ func (b textBytes) MarshalText() ([]byte, error) { return b, nil }
4949
// It implements io.WriteCloser; the caller writes test output in,
5050
// and the converter writes JSON output to w.
5151
type converter struct {
52-
w io.Writer // JSON output stream
53-
pkg string // package to name in events
54-
mode Mode // mode bits
55-
start time.Time // time converter started
56-
testName string // name of current test, for output attribution
57-
report []*event // pending test result reports (nested for subtests)
58-
result string // overall test result if seen
59-
input lineBuffer // input buffer
60-
output lineBuffer // output buffer
52+
w io.Writer // JSON output stream
53+
pkg string // package to name in events
54+
mode Mode // mode bits
55+
start time.Time // time converter started
56+
testName string // name of current test, for output attribution
57+
testNames map[string]struct{} // names of all tests, for log output attribution
58+
report []*event // pending test result reports (nested for subtests)
59+
result string // overall test result if seen
60+
input lineBuffer // input buffer
61+
output lineBuffer // output buffer
6162
}
6263

6364
// inBuffer and outBuffer are the input and output buffer sizes.
@@ -117,6 +118,7 @@ func NewConverter(w io.Writer, pkg string, mode Mode) io.WriteCloser {
117118
line: c.writeOutputEvent,
118119
part: c.writeOutputEvent,
119120
},
121+
testNames: make(map[string]struct{}),
120122
}
121123
return c
122124
}
@@ -151,6 +153,8 @@ var (
151153
[]byte("--- BENCH: "),
152154
}
153155

156+
testNamePrefix = "Test"
157+
154158
fourSpace = []byte(" ")
155159

156160
skipLinePrefix = []byte("? \t")
@@ -212,7 +216,18 @@ func (c *converter) handleInputLine(line []byte) {
212216
}
213217

214218
if !ok {
215-
// Not a special test output line.
219+
// Not a special test output line, but it may be the beginning
220+
// of decorated test log output.
221+
line := string(origLine)
222+
dedent := strings.TrimLeftFunc(line, unicode.IsSpace)
223+
end := strings.Index(dedent, ":")
224+
if end >= len(testNamePrefix) {
225+
name := dedent[:end]
226+
_, found := c.testNames[name]
227+
if found {
228+
c.testName = name
229+
}
230+
}
216231
c.output.write(origLine)
217232
return
218233
}
@@ -252,6 +267,7 @@ func (c *converter) handleInputLine(line []byte) {
252267
c.flushReport(indent)
253268
e.Test = name
254269
c.testName = name
270+
c.testNames[name] = struct{}{}
255271
c.report = append(c.report, e)
256272
c.output.write(origLine)
257273
return
@@ -260,6 +276,7 @@ func (c *converter) handleInputLine(line []byte) {
260276
// Finish any pending PASS/FAIL reports.
261277
c.flushReport(0)
262278
c.testName = name
279+
c.testNames[name] = struct{}{}
263280

264281
if action == "pause" {
265282
// For a pause, we want to write the pause notification before

‎src/cmd/internal/test2json/testdata/issue38050.json

+56
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,56 @@
1+
{"Action":"run","Test":"Test1"}
2+
{"Action":"output","Test":"Test1","Output":"=== RUN Test1\n"}
3+
{"Action":"output","Test":"Test1","Output":"=== PAUSE Test1\n"}
4+
{"Action":"pause","Test":"Test1"}
5+
{"Action":"run","Test":"Test2"}
6+
{"Action":"output","Test":"Test2","Output":"=== RUN Test2\n"}
7+
{"Action":"output","Test":"Test2","Output":"=== PAUSE Test2\n"}
8+
{"Action":"pause","Test":"Test2"}
9+
{"Action":"cont","Test":"Test1"}
10+
{"Action":"output","Test":"Test1","Output":"=== CONT Test1\n"}
11+
{"Action":"cont","Test":"Test2"}
12+
{"Action":"output","Test":"Test2","Output":"=== CONT Test2\n"}
13+
{"Action":"run","Test":"Test1/this_passes"}
14+
{"Action":"output","Test":"Test1/this_passes","Output":"=== RUN Test1/this_passes\n"}
15+
{"Action":"output","Test":"Test1/this_passes","Output":"=== PAUSE Test1/this_passes\n"}
16+
{"Action":"pause","Test":"Test1/this_passes"}
17+
{"Action":"run","Test":"Test1/this_will_fail"}
18+
{"Action":"output","Test":"Test1/this_will_fail","Output":"=== RUN Test1/this_will_fail\n"}
19+
{"Action":"run","Test":"Test2/this_passes"}
20+
{"Action":"output","Test":"Test2/this_passes","Output":"=== RUN Test2/this_passes\n"}
21+
{"Action":"output","Test":"Test1/this_will_fail","Output":"=== PAUSE Test1/this_will_fail\n"}
22+
{"Action":"pause","Test":"Test1/this_will_fail"}
23+
{"Action":"cont","Test":"Test1/this_passes"}
24+
{"Action":"output","Test":"Test1/this_passes","Output":"=== CONT Test1/this_passes\n"}
25+
{"Action":"output","Test":"Test2/this_passes","Output":"=== PAUSE Test2/this_passes\n"}
26+
{"Action":"pause","Test":"Test2/this_passes"}
27+
{"Action":"cont","Test":"Test1/this_will_fail"}
28+
{"Action":"output","Test":"Test1/this_will_fail","Output":"=== CONT Test1/this_will_fail\n"}
29+
{"Action":"run","Test":"Test2/this_will_fail"}
30+
{"Action":"output","Test":"Test2/this_will_fail","Output":"=== RUN Test2/this_will_fail\n"}
31+
{"Action":"output","Test":"Test2/this_will_fail","Output":"=== PAUSE Test2/this_will_fail\n"}
32+
{"Action":"pause","Test":"Test2/this_will_fail"}
33+
{"Action":"cont","Test":"Test2/this_passes"}
34+
{"Action":"output","Test":"Test2/this_passes","Output":"=== CONT Test2/this_passes\n"}
35+
{"Action":"output","Test":"Test1/this_will_fail","Output":" Test1/this_will_fail: parallel_test.go:40:\n"}
36+
{"Action":"output","Test":"Test1/this_will_fail","Output":" got: [THIS WILL FAIL]\n"}
37+
{"Action":"output","Test":"Test1/this_will_fail","Output":" want: [because this is wrong]\n"}
38+
{"Action":"cont","Test":"Test2/this_will_fail"}
39+
{"Action":"output","Test":"Test2/this_will_fail","Output":"=== CONT Test2/this_will_fail\n"}
40+
{"Action":"output","Test":"Test1","Output":"--- FAIL: Test1 (0.00s)\n"}
41+
{"Action":"output","Test":"Test1/this_passes","Output":" --- PASS: Test1/this_passes (0.00s)\n"}
42+
{"Action":"pass","Test":"Test1/this_passes"}
43+
{"Action":"output","Test":"Test1/this_will_fail","Output":" --- FAIL: Test1/this_will_fail (0.00s)\n"}
44+
{"Action":"output","Test":"Test2/this_will_fail","Output":" Test2/this_will_fail: parallel_test.go:40:\n"}
45+
{"Action":"output","Test":"Test2/this_will_fail","Output":" got: [THIS WILL FAIL]\n"}
46+
{"Action":"output","Test":"Test2/this_will_fail","Output":" want: [because this is wrong]\n"}
47+
{"Action":"fail","Test":"Test1/this_will_fail"}
48+
{"Action":"fail","Test":"Test1"}
49+
{"Action":"output","Test":"Test2","Output":"--- FAIL: Test2 (0.00s)\n"}
50+
{"Action":"output","Test":"Test2/this_passes","Output":" --- PASS: Test2/this_passes (0.00s)\n"}
51+
{"Action":"pass","Test":"Test2/this_passes"}
52+
{"Action":"output","Test":"Test2/this_will_fail","Output":" --- FAIL: Test2/this_will_fail (0.00s)\n"}
53+
{"Action":"fail","Test":"Test2/this_will_fail"}
54+
{"Action":"fail","Test":"Test2"}
55+
{"Action":"output","Output":"FAIL\n"}
56+
{"Action":"fail"}

‎src/cmd/internal/test2json/testdata/issue38050.test

+31
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,31 @@
1+
=== RUN Test1
2+
=== PAUSE Test1
3+
=== RUN Test2
4+
=== PAUSE Test2
5+
=== CONT Test1
6+
=== CONT Test2
7+
=== RUN Test1/this_passes
8+
=== PAUSE Test1/this_passes
9+
=== RUN Test1/this_will_fail
10+
=== RUN Test2/this_passes
11+
=== PAUSE Test1/this_will_fail
12+
=== CONT Test1/this_passes
13+
=== PAUSE Test2/this_passes
14+
=== CONT Test1/this_will_fail
15+
=== RUN Test2/this_will_fail
16+
=== PAUSE Test2/this_will_fail
17+
=== CONT Test2/this_passes
18+
Test1/this_will_fail: parallel_test.go:40:
19+
got: [THIS WILL FAIL]
20+
want: [because this is wrong]
21+
=== CONT Test2/this_will_fail
22+
--- FAIL: Test1 (0.00s)
23+
--- PASS: Test1/this_passes (0.00s)
24+
--- FAIL: Test1/this_will_fail (0.00s)
25+
Test2/this_will_fail: parallel_test.go:40:
26+
got: [THIS WILL FAIL]
27+
want: [because this is wrong]
28+
--- FAIL: Test2 (0.00s)
29+
--- PASS: Test2/this_passes (0.00s)
30+
--- FAIL: Test2/this_will_fail (0.00s)
31+
FAIL

0 commit comments

Comments
 (0)