testing: test output interleaves with race-detector warnings

[mfridman]

What version of Go are you using (go version)?

go version devel +353795c839 Sat Dec 8 00:27:08 2018 +0000 darwin/amd64

Does this issue reproduce with the latest release?

N/A. Built from source.

What operating system and processor architecture are you using (go env)?

go env Output

GOARCH="amd64"
GOOS="darwin"

What did you do?

Running go test -count=1 -json -race produces output that's difficult for downstream tools to parse.

https://play.golang.org/p/hpTaOLoTNcL

The reports --- FAIL line may appear anywhere between the goal posts:

================== <- goal post
WARNING: DATA RACE
...
==================

What did you expect to see?

I'd expect a uniform method of outputting tests detected by -race as true. Whether the non-race output is before or after is irrelevant, but it should be consistent.

--- FAIL: TestRace1 (0.00s)                                                  <- HERE
    some_test.go:10: 64
    testing.go:806: race detected during execution of test
==================
WARNING: DATA RACE

// would only expected output related to the DATA RACE

==================
--- FAIL: TestRace1 (0.00s)                                                  <- OR HERE
    some_test.go:10: 64
    testing.go:806: race detected during execution of test

What did you see instead?

The --- FAIL line can appear in random places throughout the output:

Example 1:

==================
WARNING: DATA RACE
Write at 0x00c000014160 by goroutine 12:
  debug/tparse-24.TestRace1.func1()
      /Users/michael.fridman/go/src/debug/tparse-24/some_test.go:8 +0x38

Previous write at 0x00c000014160 by goroutine 6:
  debug/tparse-24.TestRace1()
      /Users/michael.fridman/go/src/debug/tparse-24/some_test.go:9 +0x96
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162

Goroutine 12 (running) created at:
  debug/tparse-24.TestRace1()
      /Users/michael.fridman/go/src/debug/tparse-24/some_test.go:8 +0x88
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162
--- FAIL: TestRace1 (0.00s)                                                  <- HERE
    some_test.go:10: 64
    testing.go:771: race detected during execution of test

Goroutine 6 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:878 +0x650
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1119 +0xa8
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1117 +0x4ee
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1034 +0x2ee
  main.main()
      _testmain.go:48 +0x221
==================

Example 2 (full):

=== RUN   TestRace1
=== PAUSE TestRace1
=== RUN   TestRace2
=== PAUSE TestRace2
=== RUN   TestA
=== PAUSE TestA
=== RUN   TestB
=== PAUSE TestB
=== CONT  TestRace1
=== CONT  TestB
=== CONT  TestRace2
--- PASS: TestB (0.00s)
=== CONT  TestA
--- PASS: TestA (0.00s)
==================
WARNING: DATA RACE
Write at 0x00c0000c2010 by goroutine 11:
  debug/tparse-24.TestRace2.func1()
      /Users/michael.fridman/go/src/debug/tparse-24/some_test.go:15 +0x38

Previous write at 0x00c0000c2010 by goroutine 7:
  debug/tparse-24.TestRace2()
      /Users/michael.fridman/go/src/debug/tparse-24/some_test.go:16 +0xaa
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162

Goroutine 11 (running) created at:
  debug/tparse-24.TestRace2()
      /Users/michael.fridman/go/src/debug/tparse-24/some_test.go:15 +0x9c
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:878 +0x650
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1119 +0xa8
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1117 +0x4ee
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1034 +0x2ee
  main.main()
      _testmain.go:48 +0x221
==================
--- FAIL: TestRace2 (0.00s)
    some_test.go:17: 64
    some_test.go:19: 64
    some_test.go:22: 64
    some_test.go:25: 64
    some_test.go:28: 64
    some_test.go:31: 64
    some_test.go:34: 64
    some_test.go:37: 64
    some_test.go:40: 64
    some_test.go:43: 64
    some_test.go:46: 64
    some_test.go:49: 12
    some_test.go:52: 12
    testing.go:771: race detected during execution of test
==================
WARNING: DATA RACE
Write at 0x00c000014160 by goroutine 12:
  debug/tparse-24.TestRace1.func1()
      /Users/michael.fridman/go/src/debug/tparse-24/some_test.go:8 +0x38

Previous write at 0x00c000014160 by goroutine 6:
  debug/tparse-24.TestRace1()
      /Users/michael.fridman/go/src/debug/tparse-24/some_test.go:9 +0x96
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162

Goroutine 12 (running) created at:
  debug/tparse-24.TestRace1()
      /Users/michael.fridman/go/src/debug/tparse-24/some_test.go:8 +0x88
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162
--- FAIL: TestRace1 (0.00s)                                                  <- HERE
    some_test.go:10: 64
    testing.go:771: race detected during execution of test

Goroutine 6 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:878 +0x650
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1119 +0xa8
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:827 +0x162
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1117 +0x4ee
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1034 +0x2ee
  main.main()
      _testmain.go:48 +0x221
==================
FAIL
exit status 1
FAIL	debug/tparse-24	0.018s

[mfridman]

It appears data race output is printed as soon as it's detected.

Whatever test the go tool is running at that time will "own" the data race output, which means it'll get lumped in seemingly random places.

[bcmills]

This is not a cmd/go issue. The problem is that the test binary itself writes output to stderr, and the race detector also writes to stderr, and there is no active synchronization between the two.

See also #24929.

[bcmills]

CC @mpvl @josharian