From e91cbd912ad379aebd1a4bec7643cc9c078869a1 Mon Sep 17 00:00:00 2001 From: Daniel Nephin Date: Sat, 17 Apr 2021 14:51:53 -0400 Subject: [PATCH] Mitigate gotest bug with missing end events Previously all missing events were reported. This commit omits events for any missed subtests, so that subtests that passed do not show as failed. The upstream bug was fixed in go1.16, so this mitigation probably does not need to stick around for long. Co-Authored-By: Aaron Lehmann --- testjson/execution.go | 40 +++++++++++++-- testjson/execution_test.go | 51 +++++++++++++++++-- .../go-test-json-missing-test-events.out | 37 ++++++++++++++ 3 files changed, 118 insertions(+), 10 deletions(-) create mode 100644 testjson/testdata/go-test-json-missing-test-events.out diff --git a/testjson/execution.go b/testjson/execution.go index 24790246..6e3dad34 100644 --- a/testjson/execution.go +++ b/testjson/execution.go @@ -73,8 +73,8 @@ type Package struct { Passed []TestCase // mapping of root TestCase ID to all sub test IDs. Used to mitigate - // github.com/golang/go/issues/29755. - // In the future when that bug is fixed this mapping can likely be removed. + // github.com/golang/go/issues/29755, and github.com/golang/go/issues/40771. + // In the future when those bug are fixed this mapping can likely be removed. subTests map[int][]int // output printed by test cases, indexed by TestCase.ID. Package output is @@ -221,6 +221,12 @@ const neverFinished time.Duration = -1 func (p *Package) end() []TestEvent { result := make([]TestEvent, 0, len(p.running)) for k, tc := range p.running { + if tc.Test.IsSubTest() && rootTestPassed(p, tc) { + // mitigate github.com/golang/go/issues/40771 (gotestsum/issues/141) + // by skipping missing subtest end events when the root test passed. + continue + } + tc.Elapsed = neverFinished p.Failed = append(p.Failed, tc) @@ -235,6 +241,32 @@ func (p *Package) end() []TestEvent { return result } +// rootTestPassed looks for the root test associated with subtest and returns +// true if the root test passed. This is used to mitigate +// github.com/golang/go/issues/40771 (gotestsum/issues/141) and may be removed +// in the future since that issue was patched in go1.16. +// +// This function is slightly expensive because it has to scan every test in the +// package, but it should only run in the rare case where a subtest was missing +// an end event. Spending a little more time in that rare case is probably better +// than keeping extra mapping of tests in all cases. +func rootTestPassed(p *Package, subtest TestCase) bool { + root, _ := subtest.Test.Split() + + for _, tc := range p.Passed { + if tc.Test.Name() != root { + continue + } + + for _, subID := range p.subTests[tc.ID] { + if subID == subtest.ID { + return true + } + } + } + return false +} + // TestCase stores the name and elapsed time for a test case. type TestCase struct { // ID is unique ID for each test case. A test run may include multiple instances @@ -343,7 +375,7 @@ func (p *Package) addTestEvent(event TestEvent) { return } - // the event.Action must be one of the three test end events + // the event.Action must be one of the three "test end" events delete(p.running, event.Test) tc.Elapsed = elapsedDuration(event.Elapsed) @@ -373,8 +405,6 @@ func (p *Package) addTestEvent(event TestEvent) { // Remove test output once a test passes, it wont be used. p.removeOutput(tc.ID) - // Remove subtest mapping, it is only used when a test fails. - delete(p.subTests, tc.ID) } } diff --git a/testjson/execution_test.go b/testjson/execution_test.go index f52daff5..9fc316bc 100644 --- a/testjson/execution_test.go +++ b/testjson/execution_test.go @@ -115,11 +115,6 @@ func TestPackage_AddEvent(t *testing.T) { expected Package } - var cmpPackage = cmp.Options{ - cmp.AllowUnexported(Package{}), - cmpopts.EquateEmpty(), - } - run := func(t *testing.T, tc testCase) { te, err := parseEvent([]byte(tc.event)) assert.NilError(t, err) @@ -176,3 +171,49 @@ func TestPackage_AddEvent(t *testing.T) { func pkgOutput(id int, line string) map[int][]string { return map[int][]string{id: {line}} } + +func TestScanOutput_WithMissingEvents(t *testing.T) { + source := golden.Get(t, "go-test-json-missing-test-events.out") + handler := &captureHandler{} + cfg := ScanConfig{ + Stdout: bytes.NewReader(source), + Handler: handler, + } + _, err := ScanTestOutput(cfg) + assert.NilError(t, err) + + var cmpTestEventShallow = cmp.Options{ + cmp.Comparer(func(x, y TestEvent) bool { + return x.Test == y.Test && x.Action == y.Action && x.Elapsed == y.Elapsed + }), + cmpopts.SortSlices(func(x, y TestEvent) bool { + return x.Test < y.Test + }), + } + + // the package end event should come immediately before the artificial events + expected := []TestEvent{ + {Action: ActionPass}, + {Action: ActionFail, Test: "TestMissing", Elapsed: -1}, + {Action: ActionFail, Test: "TestMissing/a", Elapsed: -1}, + {Action: ActionFail, Test: "TestMissingEvent", Elapsed: -1}, + {Action: ActionFail, Test: "TestFailed/a", Elapsed: -1}, + {Action: ActionFail, Test: "TestFailed/a/sub", Elapsed: -1}, + } + assert.Assert(t, len(handler.events) > len(expected)) + start := len(handler.events) - len(expected) + assert.DeepEqual(t, expected, handler.events[start:], cmpTestEventShallow) +} + +type captureHandler struct { + events []TestEvent +} + +func (s *captureHandler) Event(event TestEvent, _ *Execution) error { + s.events = append(s.events, event) + return nil +} + +func (s *captureHandler) Err(text string) error { + return fmt.Errorf(text) +} diff --git a/testjson/testdata/go-test-json-missing-test-events.out b/testjson/testdata/go-test-json-missing-test-events.out new file mode 100644 index 00000000..5f080e3d --- /dev/null +++ b/testjson/testdata/go-test-json-missing-test-events.out @@ -0,0 +1,37 @@ +{"Time":"2021-04-17T14:33:35.167978423Z","Action":"run","Package":"gotest.tools/testing","Test":"TestPassed"} +{"Time":"2021-04-17T14:33:35.167999152Z","Action":"output","Package":"gotest.tools/testing","Test":"TestPassed","Output":"=== RUN TestPassed\n"} +{"Time":"2021-04-17T14:33:35.168007043Z","Action":"output","Package":"gotest.tools/testing","Test":"TestPassed","Output":"--- PASS: TestPassed (0.00s)\n"} +{"Time":"2021-04-17T14:33:35.16801113Z","Action":"pass","Package":"gotest.tools/testing","Test":"TestPassed","Elapsed":0} +{"Time":"2021-04-17T14:33:35.167978423Z","Action":"run","Package":"gotest.tools/testing","Test":"TestMissingEvent"} +{"Time":"2021-04-17T14:33:35.167999152Z","Action":"output","Package":"gotest.tools/testing","Test":"TestMissingEvent","Output":"=== RUN TestMissingEvent\n"} +{"Time":"2021-04-17T14:33:35.168007043Z","Action":"output","Package":"gotest.tools/testing","Test":"TestMissingEvent","Output":"--- PASS: TestMissingEvent (0.00s)\n"} +{"Time":"2021-04-17T14:33:35.168147969Z","Action":"run","Package":"gotest.tools/testing","Test":"TestNestedSuccess"} +{"Time":"2021-04-17T14:33:35.168150995Z","Action":"output","Package":"gotest.tools/testing","Test":"TestNestedSuccess","Output":"=== RUN TestNestedSuccess\n"} +{"Time":"2021-04-17T14:33:35.168155447Z","Action":"run","Package":"gotest.tools/testing","Test":"TestNestedSuccess/a"} +{"Time":"2021-04-17T14:33:35.168158403Z","Action":"output","Package":"gotest.tools/testing","Test":"TestNestedSuccess/a","Output":"=== RUN TestNestedSuccess/a\n"} +{"Time":"2021-04-17T14:33:35.168161668Z","Action":"run","Package":"gotest.tools/testing","Test":"TestNestedSuccess/a/sub"} +{"Time":"2021-04-17T14:33:35.168164766Z","Action":"output","Package":"gotest.tools/testing","Test":"TestNestedSuccess/a/sub","Output":"=== RUN TestNestedSuccess/a/sub\n"} +{"Time":"2021-04-17T14:33:35.168168123Z","Action":"run","Package":"gotest.tools/testing","Test":"TestNestedSuccess/b"} +{"Time":"2021-04-17T14:33:35.168170964Z","Action":"output","Package":"gotest.tools/testing","Test":"TestNestedSuccess/b","Output":"=== RUN TestNestedSuccess/b\n"} +{"Time":"2021-04-17T14:33:35.168174253Z","Action":"run","Package":"gotest.tools/testing","Test":"TestNestedSuccess/b/sub"} +{"Time":"2021-04-17T14:33:35.168177104Z","Action":"output","Package":"gotest.tools/testing","Test":"TestNestedSuccess/b/sub","Output":"=== RUN TestNestedSuccess/b/sub\n"} +{"Time":"2021-04-17T14:33:35.16820637Z","Action":"output","Package":"gotest.tools/testing","Test":"TestNestedSuccess","Output":"--- PASS: TestNestedSuccess (0.00s)\n"} +{"Time":"2021-04-17T14:33:35.168210256Z","Action":"output","Package":"gotest.tools/testing","Test":"TestNestedSuccess/a","Output":" --- PASS: TestNestedSuccess/a (0.00s)\n"} +{"Time":"2021-04-17T14:33:35.168213987Z","Action":"output","Package":"gotest.tools/testing","Test":"TestNestedSuccess/a/sub","Output":" --- PASS: TestNestedSuccess/a/sub (0.00s)\n"} +{"Time":"2021-04-17T14:33:35.168217438Z","Action":"pass","Package":"gotest.tools/testing","Test":"TestNestedSuccess/a/sub","Elapsed":0} +{"Time":"2021-04-17T14:33:35.168222153Z","Action":"pass","Package":"gotest.tools/testing","Test":"TestNestedSuccess/a","Elapsed":0} +{"Time":"2021-04-17T14:33:35.16826478Z","Action":"pass","Package":"gotest.tools/testing","Test":"TestNestedSuccess","Elapsed":0} +{"Time":"2021-04-17T14:33:35.168147969Z","Action":"run","Package":"gotest.tools/testing","Test":"TestFailed"} +{"Time":"2021-04-17T14:33:35.168150995Z","Action":"output","Package":"gotest.tools/testing","Test":"TestFailed","Output":"=== RUN TestFailed\n"} +{"Time":"2021-04-17T14:33:35.168155447Z","Action":"run","Package":"gotest.tools/testing","Test":"TestFailed/a"} +{"Time":"2021-04-17T14:33:35.168158403Z","Action":"output","Package":"gotest.tools/testing","Test":"TestFailed/a","Output":"=== RUN TestFailed/a\n"} +{"Time":"2021-04-17T14:33:35.168161668Z","Action":"run","Package":"gotest.tools/testing","Test":"TestFailed/a/sub"} +{"Time":"2021-04-17T14:33:35.168164766Z","Action":"output","Package":"gotest.tools/testing","Test":"TestFailed/a/sub","Output":"=== RUN TestFailed/a/sub\n"} +{"Time":"2021-04-17T14:33:35.16826478Z","Action":"fail","Package":"gotest.tools/testing","Test":"TestFailed","Elapsed":0} +{"Time":"2021-04-17T14:33:35.168147969Z","Action":"run","Package":"gotest.tools/testing","Test":"TestMissing"} +{"Time":"2021-04-17T14:33:35.168150995Z","Action":"output","Package":"gotest.tools/testing","Test":"TestMissing","Output":"=== RUN TestMissing\n"} +{"Time":"2021-04-17T14:33:35.168155447Z","Action":"run","Package":"gotest.tools/testing","Test":"TestMissing/a"} +{"Time":"2021-04-17T14:33:35.168158403Z","Action":"output","Package":"gotest.tools/testing","Test":"TestMissing/a","Output":"=== RUN TestMissing/a\n"} +{"Time":"2021-04-17T14:33:35.168308334Z","Action":"output","Package":"gotest.tools/testing","Output":"PASS\n"} +{"Time":"2021-04-17T14:33:35.168311492Z","Action":"output","Package":"gotest.tools/testing","Output":"ok \tgotest.tools/testing\t(cached)\n"} +{"Time":"2021-04-17T14:33:35.168316085Z","Action":"pass","Package":"gotest.tools/testing","Elapsed":0} \ No newline at end of file