From 6ec6fdaad24a2f331bd45851f19a8d96c7a9841c Mon Sep 17 00:00:00 2001 From: jochen Date: Sun, 25 Oct 2026 15:52:20 +0100 Subject: [PATCH] mesh-build-go: a race the race detector reports is a failure's cause, in a test or after PASS (issue 1901) mesh-controller's try was worded 'PASS' again because the race detector reported after the tests passed and the program exited 66. The cause is now the race: its access, the frame that made it and where its goroutine was created, instead of PASS or testing's generic 'race detected during execution of test'. Tests from captured go test -race -json (1901/AC4). --- .../mesh-build-go/cmd/mesh-build-go/levels.go | 81 ++++++++++++++++++- .../cmd/mesh-build-go/package_cause_test.go | 2 + .../mesh-build-go/testdata/captured/README | 4 + .../captured/go-test-json-pkg-race.jsonl | 53 ++++++++++++ .../captured/go-test-json-pkg-racemain.jsonl | 27 +++++++ 5 files changed, 163 insertions(+), 4 deletions(-) create mode 100644 modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-pkg-race.jsonl create mode 100644 modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-pkg-racemain.jsonl diff --git a/modules/mesh-build-go/cmd/mesh-build-go/levels.go b/modules/mesh-build-go/cmd/mesh-build-go/levels.go index 71af4d52..27d38434 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/levels.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/levels.go @@ -232,7 +232,9 @@ func (r *reader) event(ev event) { if ev.Action == "fail" { r.failedIn[ev.Package] = true cause := r.causes[key] - if cause == "" { + if race := raceCause(r.testOut[key]); race != "" && (cause == "" || strings.HasPrefix(cause, "race detected")) { + cause = race // the race itself, not testing's "race detected during execution of test" + } else if cause == "" { cause = causeOf(r.testOut[key]) } r.res.Failed = append(r.res.Failed, Failure{Package: ev.Package, Test: ev.Test, Output: clip(r.testOut[key], cause), Cause: cause}) @@ -278,10 +280,14 @@ func summaryLine(l string) bool { return l == "PASS" || l == "FAIL" || strings.HasPrefix(l, "ok ") || strings.HasPrefix(l, "ok\t") || strings.HasPrefix(l, "FAIL\t") || strings.HasPrefix(l, "FAIL ") } -// causeOf is the cause in a failure's output that is not a test's assertion (issue 1901): the first "panic:" line, a -// timeout's with the tests it names as running; else the first "fatal error:" (the runtime's) or "signal:" line (a test -// program killed); "" when there is none. It reads every line, so a long goroutine dump after the panic cannot hide it. +// causeOf is the cause in a failure's output that is not a test's assertion (issue 1901): a race the race detector +// reported (raceCause); else the first "panic:" line, a timeout's with the tests it names as running; else the first +// "fatal error:" (the runtime's) or "signal:" line (a test program killed); "" when there is none. It reads every line, +// so a long goroutine dump after the panic cannot hide it. func causeOf(lines []string) string { + if race := raceCause(lines); race != "" { + return race + } for _, prefix := range []string{"panic: ", "fatal error: ", "signal: "} { for i, l := range lines { l = strings.TrimSpace(l) @@ -309,6 +315,73 @@ func causeOf(lines []string) string { return "" } +// raceCause is the first race the race detector reported in a failure's output, in one line (issue 1901: a race after +// the tests' "PASS" was worded "PASS"): its access and the frame that made it, and where the goroutine that made it was +// created, as "WARNING: DATA RACE: Write at 0x... by goroutine 10 in pkg.F.func1() (f_test.go:13); goroutine created at +// pkg.F() (f_test.go:13)". "" when the output holds no race. +func raceCause(lines []string) string { + at := -1 + for i, l := range lines { + if strings.TrimSpace(l) == "WARNING: DATA RACE" { + at = i + break + } + } + if at < 0 { + return "" + } + // frame is the function and the file's base name and line that follow a heading line at i. + frame := func(i int) string { + var fn, file string + for _, l := range lines[i+1:] { + if l = strings.TrimSpace(l); l == "" { + break + } + if fn == "" { + fn = l + continue + } + file = l + if j := strings.LastIndexByte(file, '/'); j >= 0 { + file = file[j+1:] + } + if j := strings.Index(file, " +0x"); j >= 0 { + file = file[:j] + } + break + } + if file != "" { + return fn + " (" + file + ")" + } + return fn + } + words := "WARNING: DATA RACE" + for i := at + 1; i < len(lines); i++ { + l := strings.TrimSpace(lines[i]) + if l == "" || strings.HasPrefix(l, "===") { + continue + } + words += ": " + strings.TrimSuffix(l, ":") + if f := frame(i); f != "" { + words += " in " + f + } + break + } + for i := at + 1; i < len(lines); i++ { + l := strings.TrimSpace(lines[i]) + if strings.HasPrefix(l, "==================") { + break + } + if strings.HasPrefix(l, "Goroutine ") && strings.HasSuffix(l, " created at:") { + if f := frame(i); f != "" { + words += "; its goroutine created at " + f + } + break + } + } + return cutLine(words) +} + // buildCause is the first error line of a failed build: the first line that is not go's "# " heading. func buildCause(lines []string) string { for _, l := range lines { diff --git a/modules/mesh-build-go/cmd/mesh-build-go/package_cause_test.go b/modules/mesh-build-go/cmd/mesh-build-go/package_cause_test.go index 0bdcb5a2..8ba71687 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/package_cause_test.go +++ b/modules/mesh-build-go/cmd/mesh-build-go/package_cause_test.go @@ -23,6 +23,8 @@ func TestAFailureThatIsNotAnAssertionCarriesItsRealCause(t *testing.T) { // 1901 {"killed", "TestKilled", []string{"signal: killed"}}, {"passthenfail", "", []string{"panic: the bus closed after the tests: nats: connection closed"}}, {"mainexit", "", []string{"passed", "exited"}}, + {"race", "TestRacesOnTheSeat", []string{"DATA RACE", "Write at", "example.com/race.TestRacesOnTheSeat.func1()", "p_test.go:13", "created at example.com/race.TestRacesOnTheSeat()"}}, + {"racemain", "", []string{"DATA RACE", "Write at", "example.com/racemain.TestMain.func1()", "p_test.go:15", "created at example.com/racemain.TestMain()"}}, } for _, c := range cases { t.Run(c.fixture, func(t *testing.T) { diff --git a/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/README b/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/README index b5ef36c1..1981bb8a 100644 --- a/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/README +++ b/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/README @@ -32,3 +32,7 @@ parallel tests and sixty blocked goroutines past the timeout, so the goroutine d 4 KB), buildfail (a type error in a test file), exiting (os.Exit(3) in TestExits), killed (TestKilled sends itself SIGKILL), passthenfail (TestMain panics in a goroutine after m.Run passed) and mainexit (TestMain exits 2 after m.Run passed: go test prints "PASS" and then "FAIL "). +go-test-json-pkg-race.jsonl and go-test-json-pkg-racemain.jsonl are the same, with `go test -race -json -count=1 ./...` +(CGO_ENABLED=1, go1.27.3, 2026-10-25, issue 1901): race (TestRacesOnTheSeat writes a package variable from itself and a +goroutine) and racemain (TestMain does so after m.Run passed: go test prints "PASS", then the race report and "Found 1 +data race(s)", then "FAIL "). diff --git a/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-pkg-race.jsonl b/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-pkg-race.jsonl new file mode 100644 index 00000000..93e9ac17 --- /dev/null +++ b/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-pkg-race.jsonl @@ -0,0 +1,53 @@ +{"Time":"2026-10-25T15:50:42.908557309+01:00","Action":"start","Package":"example.com/race"} +{"Time":"2026-10-25T15:50:42.924298679+01:00","Action":"run","Package":"example.com/race","Test":"TestBefore"} +{"Time":"2026-10-25T15:50:42.92438195+01:00","Action":"output","Package":"example.com/race","Test":"TestBefore","Output":"=== RUN TestBefore\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:42.924648842+01:00","Action":"output","Package":"example.com/race","Test":"TestBefore","Output":"--- PASS: TestBefore (0.00s)\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:42.924685133+01:00","Action":"pass","Package":"example.com/race","Test":"TestBefore","Elapsed":0} +{"Time":"2026-10-25T15:50:42.924728573+01:00","Action":"run","Package":"example.com/race","Test":"TestRacesOnTheSeat"} +{"Time":"2026-10-25T15:50:42.924733573+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"=== RUN TestRacesOnTheSeat\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:42.92637298+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"==================\n"} +{"Time":"2026-10-25T15:50:42.92641567+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"WARNING: DATA RACE\n"} +{"Time":"2026-10-25T15:50:42.926444061+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"Write at 0x000000833468 by goroutine 10:\n"} +{"Time":"2026-10-25T15:50:42.926462621+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" example.com/race.TestRacesOnTheSeat.func1()\n"} +{"Time":"2026-10-25T15:50:42.926467121+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /tmp/fix-1901b/race/p_test.go:13 +0x24\n"} +{"Time":"2026-10-25T15:50:42.926483061+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"\n"} +{"Time":"2026-10-25T15:50:42.926509741+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"Previous write at 0x000000833468 by goroutine 9:\n"} +{"Time":"2026-10-25T15:50:42.926530142+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" example.com/race.TestRacesOnTheSeat()\n"} +{"Time":"2026-10-25T15:50:42.926534952+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /tmp/fix-1901b/race/p_test.go:14 +0x30\n"} +{"Time":"2026-10-25T15:50:42.926550462+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.tRunner()\n"} +{"Time":"2026-10-25T15:50:42.926554612+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /usr/lib/go/src/testing/testing.go:2195 +0x21c\n"} +{"Time":"2026-10-25T15:50:42.926571142+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.(*T).Run.gowrap1()\n"} +{"Time":"2026-10-25T15:50:42.926575812+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /usr/lib/go/src/testing/testing.go:2260 +0x38\n"} +{"Time":"2026-10-25T15:50:42.926592202+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"\n"} +{"Time":"2026-10-25T15:50:42.926607792+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"Goroutine 10 (running) created at:\n"} +{"Time":"2026-10-25T15:50:42.926624292+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" example.com/race.TestRacesOnTheSeat()\n"} +{"Time":"2026-10-25T15:50:42.926628923+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /tmp/fix-1901b/race/p_test.go:13 +0x24\n"} +{"Time":"2026-10-25T15:50:42.926643853+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.tRunner()\n"} +{"Time":"2026-10-25T15:50:42.926648103+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /usr/lib/go/src/testing/testing.go:2195 +0x21c\n"} +{"Time":"2026-10-25T15:50:42.926674843+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.(*T).Run.gowrap1()\n"} +{"Time":"2026-10-25T15:50:42.926680673+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /usr/lib/go/src/testing/testing.go:2260 +0x38\n"} +{"Time":"2026-10-25T15:50:42.926695433+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"\n"} +{"Time":"2026-10-25T15:50:42.926711063+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"Goroutine 9 (running) created at:\n"} +{"Time":"2026-10-25T15:50:42.926726614+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.(*T).Run()\n"} +{"Time":"2026-10-25T15:50:42.926730814+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /usr/lib/go/src/testing/testing.go:2260 +0xb12\n"} +{"Time":"2026-10-25T15:50:42.926746484+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.runTests.func1()\n"} +{"Time":"2026-10-25T15:50:42.926750764+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /usr/lib/go/src/testing/testing.go:2744 +0x84\n"} +{"Time":"2026-10-25T15:50:42.926765354+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.tRunner()\n"} +{"Time":"2026-10-25T15:50:42.926769844+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /usr/lib/go/src/testing/testing.go:2195 +0x21c\n"} +{"Time":"2026-10-25T15:50:42.926791794+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.runTests()\n"} +{"Time":"2026-10-25T15:50:42.926796704+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /usr/lib/go/src/testing/testing.go:2742 +0x9e9\n"} +{"Time":"2026-10-25T15:50:42.926811544+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.(*M).Run()\n"} +{"Time":"2026-10-25T15:50:42.926816694+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" /usr/lib/go/src/testing/testing.go:2602 +0xf44\n"} +{"Time":"2026-10-25T15:50:42.926831695+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" main.main()\n"} +{"Time":"2026-10-25T15:50:42.926835935+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" _testmain.go:50 +0x164\n"} +{"Time":"2026-10-25T15:50:42.926850905+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"==================\n"} +{"Time":"2026-10-25T15:50:42.935320241+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":" testing.go:1867: race detected during execution of test\n","OutputType":"error"} +{"Time":"2026-10-25T15:50:42.935520113+01:00","Action":"output","Package":"example.com/race","Test":"TestRacesOnTheSeat","Output":"--- FAIL: TestRacesOnTheSeat (0.01s)\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:42.935592973+01:00","Action":"fail","Package":"example.com/race","Test":"TestRacesOnTheSeat","Elapsed":0.01} +{"Time":"2026-10-25T15:50:42.935722225+01:00","Action":"run","Package":"example.com/race","Test":"TestAfter"} +{"Time":"2026-10-25T15:50:42.935728845+01:00","Action":"output","Package":"example.com/race","Test":"TestAfter","Output":"=== RUN TestAfter\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:42.935995928+01:00","Action":"output","Package":"example.com/race","Test":"TestAfter","Output":"--- PASS: TestAfter (0.00s)\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:42.936006328+01:00","Action":"pass","Package":"example.com/race","Test":"TestAfter","Elapsed":0} +{"Time":"2026-10-25T15:50:42.936009978+01:00","Action":"output","Package":"example.com/race","Output":"FAIL\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:42.937730745+01:00","Action":"output","Package":"example.com/race","Output":"FAIL\texample.com/race\t0.028s\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:42.937802066+01:00","Action":"fail","Package":"example.com/race","Elapsed":0.029} diff --git a/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-pkg-racemain.jsonl b/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-pkg-racemain.jsonl new file mode 100644 index 00000000..8a2a5c07 --- /dev/null +++ b/modules/mesh-build-go/cmd/mesh-build-go/testdata/captured/go-test-json-pkg-racemain.jsonl @@ -0,0 +1,27 @@ +{"Time":"2026-10-25T15:50:43.551701745+01:00","Action":"start","Package":"example.com/racemain"} +{"Time":"2026-10-25T15:50:43.570709708+01:00","Action":"run","Package":"example.com/racemain","Test":"TestFine"} +{"Time":"2026-10-25T15:50:43.570806059+01:00","Action":"output","Package":"example.com/racemain","Test":"TestFine","Output":"=== RUN TestFine\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:43.57085525+01:00","Action":"output","Package":"example.com/racemain","Test":"TestFine","Output":"--- PASS: TestFine (0.00s)\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:43.57086149+01:00","Action":"pass","Package":"example.com/racemain","Test":"TestFine","Elapsed":0} +{"Time":"2026-10-25T15:50:43.57086974+01:00","Action":"output","Package":"example.com/racemain","Output":"PASS\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:43.572155623+01:00","Action":"output","Package":"example.com/racemain","Output":"==================\n"} +{"Time":"2026-10-25T15:50:43.572168083+01:00","Action":"output","Package":"example.com/racemain","Output":"WARNING: DATA RACE\n"} +{"Time":"2026-10-25T15:50:43.572171933+01:00","Action":"output","Package":"example.com/racemain","Output":"Write at 0x000000836428 by goroutine 9:\n"} +{"Time":"2026-10-25T15:50:43.572176703+01:00","Action":"output","Package":"example.com/racemain","Output":" example.com/racemain.TestMain.func1()\n"} +{"Time":"2026-10-25T15:50:43.572180053+01:00","Action":"output","Package":"example.com/racemain","Output":" /tmp/fix-1901b/racemain/p_test.go:15 +0x24\n"} +{"Time":"2026-10-25T15:50:43.572184923+01:00","Action":"output","Package":"example.com/racemain","Output":"\n"} +{"Time":"2026-10-25T15:50:43.572189613+01:00","Action":"output","Package":"example.com/racemain","Output":"Previous write at 0x000000836428 by main goroutine:\n"} +{"Time":"2026-10-25T15:50:43.572192993+01:00","Action":"output","Package":"example.com/racemain","Output":" example.com/racemain.TestMain()\n"} +{"Time":"2026-10-25T15:50:43.572198573+01:00","Action":"output","Package":"example.com/racemain","Output":" /tmp/fix-1901b/racemain/p_test.go:16 +0x44\n"} +{"Time":"2026-10-25T15:50:43.572202433+01:00","Action":"output","Package":"example.com/racemain","Output":" main.main()\n"} +{"Time":"2026-10-25T15:50:43.572205623+01:00","Action":"output","Package":"example.com/racemain","Output":" _testmain.go:48 +0x171\n"} +{"Time":"2026-10-25T15:50:43.572208443+01:00","Action":"output","Package":"example.com/racemain","Output":"\n"} +{"Time":"2026-10-25T15:50:43.572211573+01:00","Action":"output","Package":"example.com/racemain","Output":"Goroutine 9 (running) created at:\n"} +{"Time":"2026-10-25T15:50:43.572214803+01:00","Action":"output","Package":"example.com/racemain","Output":" example.com/racemain.TestMain()\n"} +{"Time":"2026-10-25T15:50:43.572218043+01:00","Action":"output","Package":"example.com/racemain","Output":" /tmp/fix-1901b/racemain/p_test.go:15 +0x37\n"} +{"Time":"2026-10-25T15:50:43.572225414+01:00","Action":"output","Package":"example.com/racemain","Output":" main.main()\n"} +{"Time":"2026-10-25T15:50:43.572228654+01:00","Action":"output","Package":"example.com/racemain","Output":" _testmain.go:48 +0x171\n"} +{"Time":"2026-10-25T15:50:43.572231664+01:00","Action":"output","Package":"example.com/racemain","Output":"==================\n"} +{"Time":"2026-10-25T15:50:44.581262249+01:00","Action":"output","Package":"example.com/racemain","Output":"Found 1 data race(s)\n"} +{"Time":"2026-10-25T15:50:44.584693204+01:00","Action":"output","Package":"example.com/racemain","Output":"FAIL\texample.com/racemain\t1.031s\n","OutputType":"frame"} +{"Time":"2026-10-25T15:50:44.584737425+01:00","Action":"fail","Package":"example.com/racemain","Elapsed":1.033}