race detected output inconsistently reported

[edaniels]

With the following test and gotestsum -- -race, the race detector output is inconsistently output.

package main

import (
	"fmt"
	"testing"
)

func TestRace(t *testing.T) {
	a := 1
	go func() {
		a = 2
	}()
	fmt.Println(a)
}

Expected (sometimes):

✖  . (112ms)

=== Failed
=== FAIL: . TestRace (0.00s)
1
==================
WARNING: DATA RACE
Write at 0x00c000126178 by goroutine 8:
  foo.TestRace.func1()
      /Users/eric/Downloads/temp/main_test.go:11 +0x2c

Previous read at 0x00c000126178 by goroutine 7:
  foo.TestRace()
      /Users/eric/Downloads/temp/main_test.go:13 +0xac
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.19.6/libexec/src/testing/testing.go:1446 +0x188
  testing.(*T).Run.func1()
      /opt/homebrew/Cellar/go/1.19.6/libexec/src/testing/testing.go:1493 +0x40

Goroutine 8 (running) created at:
  foo.TestRace()
      /Users/eric/Downloads/temp/main_test.go:10 +0xa0
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.19.6/libexec/src/testing/testing.go:1446 +0x188
  testing.(*T).Run.func1()
      /opt/homebrew/Cellar/go/1.19.6/libexec/src/testing/testing.go:1493 +0x40

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /opt/homebrew/Cellar/go/1.19.6/libexec/src/testing/testing.go:1493 +0x55c
  testing.runTests.func1()
      /opt/homebrew/Cellar/go/1.19.6/libexec/src/testing/testing.go:1846 +0x90
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.19.6/libexec/src/testing/testing.go:1446 +0x188
  testing.runTests()
      /opt/homebrew/Cellar/go/1.19.6/libexec/src/testing/testing.go:1844 +0x6c0
  testing.(*M).Run()
      /opt/homebrew/Cellar/go/1.19.6/libexec/src/testing/testing.go:1726 +0x870
  main.main()
      _testmain.go:47 +0x2fc
==================

DONE 1 tests, 1 failure in 0.277s

Actual (sometimes):

✖  . (115ms)

=== Failed
=== FAIL: .  (0.00s)
=== CONT  
    testing.go:1319: race detected during execution of test
FAIL
FAIL	foo	0.115s

DONE 1 tests, 1 failure in 0.281s

[dnephin]

Thank you for the detailed bug report and the minimal reproduction!

I ran this test using go test -race -count=1 -json . and I noticed that sometimes the data race output has Test: "", and other times it has Test: "TestRace". This confirms the problem is an issue with test2json. The data race output is being attributed to the package instead of the test.

It looks like there is an open issue about this problem: https://github.com/golang/go/issues/58634

#298 added a workaround for a similar bug and seems like it almost fixes the problem. That change is included in gotestsum v1.9.0. When I run the test case with v1.9.0 I see that sometimes the data race is attributed to the test, and sometimes it attributed the package, but very rarely it's neither. In those rare cases it must be missing from the go test output entirely.

Upgrading to gotestsum v1.9.0 should mostly work around the problem until it's fixed in the go toolchain.

[edaniels]

That does not appear to help the issue on v1.9.0

[edaniels]

Thank you for checking if it would though!

[mitar]

It is still an issue for me in v1.11.0.

[epot]

Just to confirm: I am using junit as output and not json and see the same issue, is it because the junit output is relying on json internally?

[szykol]

I also bumped into this issue using following command:

go run gotest.tools/gotestsum@latest -- -timeout 10m -race -v -count=1 ./...

any news on this issue?

[kszafran]

I believe I also have a case where gotestsum swallows goroutine dumps. I see multiple race detected during execution of test, but no goroutine dumps. What's worse, I cannot reproduce this locally, only in CI.

The command I'm using is:

gotestsum --debug --format pkgname-and-test-fails -- -v -race -timeout 5m <paths>

(I'm using GOEXPERIMENT=synctest, though it probably doesn't matter here.)

[dnephin]

The bug is likely a race that causes https://pkg.go.dev/cmd/test2json to attribute the failure to the wrong package.

I would capture the full output to a file using --jsonfile and save it as an artifact somewhere. That should show the problem, and also make it possible for you to view the stack traces.