Skip to content

Commit 8feaa93

Browse files
linzhplinzhp
authored
Capturing elapsed time of interrupted test cases due to timeout (#4253)
**What type of PR is this?** Feature **What does this PR do? Why is it needed?** When a test case is interrupted at timeout, we don't have the pass/fail/skip event to report elapsed time. However, we can parse them from the error message at the end to figure it out. The error message looks like: ``` panic: test timed out after 8s running tests: TestReport (8s) TestReport/test_3 (2s) ``` Also, instead of reporting those test cases as "No pass/skip/fail event found for test", we can now report them as "Interrupted".
1 parent 212b76d commit 8feaa93

File tree

3 files changed

+82
-0
lines changed

3 files changed

+82
-0
lines changed

‎go/tools/bzltestutil/testdata/timeout.json

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,26 @@
1+
{"Time":"2025-02-07T17:15:47.557152-08:00","Action":"start","Package":"pkg/testing"}
2+
{"Time":"2025-02-07T17:15:48.107123-08:00","Action":"run","Package":"pkg/testing","Test":"TestReport"}
3+
{"Time":"2025-02-07T17:15:48.107189-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport","Output":"=== RUN TestReport\n"}
4+
{"Time":"2025-02-07T17:15:48.107222-08:00","Action":"run","Package":"pkg/testing","Test":"TestReport/test_0"}
5+
{"Time":"2025-02-07T17:15:48.107227-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_0","Output":"=== RUN TestReport/test_0\n"}
6+
{"Time":"2025-02-07T17:15:50.108298-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_0","Output":"--- PASS: TestReport/test_0 (2.00s)\n"}
7+
{"Time":"2025-02-07T17:15:50.108365-08:00","Action":"pass","Package":"pkg/testing","Test":"TestReport/test_0","Elapsed":2}
8+
{"Time":"2025-02-07T17:15:50.108385-08:00","Action":"run","Package":"pkg/testing","Test":"TestReport/test_1"}
9+
{"Time":"2025-02-07T17:15:50.108392-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_1","Output":"=== RUN TestReport/test_1\n"}
10+
{"Time":"2025-02-07T17:15:52.1095-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_1","Output":"--- PASS: TestReport/test_1 (2.00s)\n"}
11+
{"Time":"2025-02-07T17:15:52.109693-08:00","Action":"pass","Package":"pkg/testing","Test":"TestReport/test_1","Elapsed":2}
12+
{"Time":"2025-02-07T17:15:52.109806-08:00","Action":"run","Package":"pkg/testing","Test":"TestReport/test_2"}
13+
{"Time":"2025-02-07T17:15:52.109841-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_2","Output":"=== RUN TestReport/test_2\n"}
14+
{"Time":"2025-02-07T17:15:54.110684-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_2","Output":"--- PASS: TestReport/test_2 (2.00s)\n"}
15+
{"Time":"2025-02-07T17:15:54.110864-08:00","Action":"pass","Package":"pkg/testing","Test":"TestReport/test_2","Elapsed":2}
16+
{"Time":"2025-02-07T17:15:54.1109-08:00","Action":"run","Package":"pkg/testing","Test":"TestReport/test_3"}
17+
{"Time":"2025-02-07T17:15:54.110923-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_3","Output":"=== RUN TestReport/test_3\n"}
18+
{"Time":"2025-02-07T17:15:56.110984-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_3","Output":"panic: test timed out after 8s\n"}
19+
{"Time":"2025-02-07T17:15:56.11102-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_3","Output":"\trunning tests:\n"}
20+
{"Time":"2025-02-07T17:15:56.111039-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_3","Output":"\t\tTestReport (8s)\n"}
21+
{"Time":"2025-02-07T17:15:56.111046-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_3","Output":"\t\tTestReport/test_3 (2s)\n"}
22+
{"Time":"2025-02-07T17:15:56.111051-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_3","Output":"\n"}
23+
{"Time":"2025-02-07T17:15:56.111056-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_3","Output":"goroutine 33 [running]:\n"}
24+
{"Time":"2025-02-07T17:15:56.111067-08:00","Action":"output","Package":"pkg/testing","Test":"TestReport/test_3","Output":"testing.(*M).startAlarm.func1()\n"}
25+
{"Time":"2025-02-07T17:15:56.11168-08:00","Action":"output","Package":"pkg/testing","Output":"FAIL\tpkg/testing\t8.554s\n"}
26+
{"Time":"2025-02-07T17:15:56.111693-08:00","Action":"fail","Package":"pkg/testing","Elapsed":8.555}

‎go/tools/bzltestutil/testdata/timeout.xml

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,13 @@
1+
<testsuites>
2+
<testsuite errors="2" failures="0" skipped="0" tests="5" time="8.555" name="pkg/testing">
3+
<testcase classname="testing" name="TestReport" time="8.000">
4+
<error message="Interrupted" type="">=== RUN TestReport&#xA;&#x9;&#x9;TestReport (8s)&#xA;</error>
5+
</testcase>
6+
<testcase classname="testing" name="TestReport/test_0" time="2.000"></testcase>
7+
<testcase classname="testing" name="TestReport/test_1" time="2.000"></testcase>
8+
<testcase classname="testing" name="TestReport/test_2" time="2.000"></testcase>
9+
<testcase classname="testing" name="TestReport/test_3" time="2.000">
10+
<error message="Interrupted" type="">=== RUN TestReport/test_3&#xA;&#x9;&#x9;TestReport/test_3 (2s)&#xA;goroutine 33 [running]:&#xA;testing.(*M).startAlarm.func1()&#xA;</error>
11+
</testcase>
12+
</testsuite>
13+
</testsuites>

‎go/tools/bzltestutil/xml.go

Lines changed: 43 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -73,6 +73,10 @@ type testCase struct {
7373
duration *float64
7474
}
7575

76+
const (
77+
timeoutPanicPrefix = "panic: test timed out after "
78+
)
79+
7680
// json2xml converts test2json's output into an xml output readable by Bazel.
7781
// http://windyroad.com.au/dl/Open%20Source/JUnit.xsd
7882
func json2xml(r io.Reader, pkgName string) ([]byte, error) {
@@ -89,6 +93,7 @@ func json2xml(r io.Reader, pkgName string) ([]byte, error) {
8993
}
9094

9195
dec := json.NewDecoder(r)
96+
var inTimeoutSection, inRunningTestSection bool
9297
for {
9398
var e jsonEvent
9499
if err := dec.Decode(&e); err == io.EOF {
@@ -102,6 +107,38 @@ func json2xml(r io.Reader, pkgName string) ([]byte, error) {
102107
c.state = s
103108
}
104109
case "output":
110+
trimmedOutput := strings.TrimSpace(e.Output)
111+
if strings.HasPrefix(trimmedOutput, timeoutPanicPrefix) {
112+
inTimeoutSection = true
113+
// the final "fail" action with "Elapsed" may not appear. If not, using the timeout setting as
114+
// pkgDuration; if it appears, it will override pkgDuration.
115+
if duration, err := time.ParseDuration(strings.TrimSpace(trimmedOutput[len(timeoutPanicPrefix):])); err == nil {
116+
seconds := duration.Seconds()
117+
pkgDuration = &seconds
118+
}
119+
continue
120+
}
121+
if inTimeoutSection && strings.HasPrefix(trimmedOutput, "running tests:") {
122+
inRunningTestSection = true
123+
continue
124+
}
125+
if inRunningTestSection {
126+
// looking for something like "TestReport/test_3 (2s)"
127+
parts := strings.Fields(e.Output)
128+
if len(parts) != 2 || !strings.HasPrefix(parts[1], "(") || !strings.HasSuffix(parts[1], ")") {
129+
inTimeoutSection = false
130+
inRunningTestSection = false
131+
} else if duration, err := time.ParseDuration(parts[1][1:len(parts[1])-1]); err != nil {
132+
inTimeoutSection = false
133+
inRunningTestSection = false
134+
} else if c := testCaseByName(parts[0]); c != nil {
135+
c.state = "interrupt"
136+
seconds := duration.Seconds()
137+
c.duration = &seconds
138+
c.output.WriteString(e.Output)
139+
}
140+
continue
141+
}
105142
if c := testCaseByName(e.Test); c != nil {
106143
c.output.WriteString(e.Output)
107144
}
@@ -166,6 +203,12 @@ func toXML(pkgName string, pkgDuration *float64, testcases map[string]*testCase)
166203
Message: "Failed",
167204
Contents: c.output.String(),
168205
}
206+
case "interrupt":
207+
suite.Errors++
208+
newCase.Error = &xmlMessage{
209+
Message: "Interrupted",
210+
Contents: c.output.String(),
211+
}
169212
case "pass":
170213
break
171214
default:

0 commit comments

Comments
 (0)