mirror of
https://github.com/tailscale/tailscale.git
synced 2026-06-03 21:01:54 +08:00
cmd/testwrapper: surface race reports and skip retries when detected
A data race in a package matters more than any individual test
result. Two related problems:
1. Where go test's race detector text ("WARNING: DATA RACE" plus
the goroutine stack traces) lands in JSON output is timing-
dependent: it can be attributed to a test that ends up reporting
PASS (e.g. when the racing goroutines outlive the test that
spawned them and TSan prints during a different test's window).
testwrapper's main loop only flushes the logs of failed tests,
so the race report ends up stuck in a passing test's buffer and
is silently dropped. The race builders just see a bare
"FAIL\nFAIL\tpkg\ttime".
2. If the failing test in such a package happens to be marked flaky,
testwrapper retries it. That is the worst possible response to a
race: the flaky test might not even be the racy code, and a
second run without the racy goroutines could "succeed" while
hiding the real bug.
Address both: scan every output line for the race detector's first-
line marker. Track whether the package observed a race at all, on
the pkgFinished testAttempt. When a race was seen, fold every per-
test log buffer into the package-level logs (so the full report
surfaces from the existing pkg-fail flush path), and drop any
flaky-test retry plans for that package so we fail immediately
instead of running another attempt.
Two new tests:
- TestRaceSuppressesFlakyRetry verifies that a flaky test alongside
a racy test does NOT get retried.
- TestRaceAttributedToPassingTest verifies that a race attributed by
test2json to a passing test still surfaces in the output.
Also add a corpus of captured raw test binary outputs under
cmd/testwrapper/testdata/, with one subdirectory per scenario,
documenting the six representative shapes that go test -race can
emit (race in test body, race in goroutines that outlive a test,
race forced into a later test, race in TestMain post-m.Run, and a
parallel-tests split-attribution case via a "=== NAME" redirect
line). See its README.md for details.
Fixes #19603
Change-Id: Ifbfcd67fb3b1882c4907bd9cb2d68a8b5a91dd54
Signed-off-by: Brad Fitzpatrick <bradfitz@tailscale.com>
This commit is contained in:
parent
ee0a03b140
commit
95d874e9b4
6
cmd/testwrapper/testdata/A_baseline/raw.txt
vendored
Normal file
6
cmd/testwrapper/testdata/A_baseline/raw.txt
vendored
Normal file
@ -0,0 +1,6 @@
|
||||
=== RUN TestOne
|
||||
a_test.go:6: hello from one
|
||||
--- PASS: TestOne (0.00s)
|
||||
=== RUN TestTwo
|
||||
--- PASS: TestTwo (0.00s)
|
||||
PASS
|
||||
13
cmd/testwrapper/testdata/A_baseline/src.go
vendored
Normal file
13
cmd/testwrapper/testdata/A_baseline/src.go
vendored
Normal file
@ -0,0 +1,13 @@
|
||||
// Copyright (c) Tailscale Inc & contributors
|
||||
// SPDX-License-Identifier: BSD-3-Clause
|
||||
|
||||
package baseline
|
||||
|
||||
import "testing"
|
||||
|
||||
func TestOne(t *testing.T) {
|
||||
t.Log("hello from one")
|
||||
}
|
||||
|
||||
func TestTwo(t *testing.T) {
|
||||
}
|
||||
30
cmd/testwrapper/testdata/B_inbody/raw.txt
vendored
Normal file
30
cmd/testwrapper/testdata/B_inbody/raw.txt
vendored
Normal file
@ -0,0 +1,30 @@
|
||||
=== RUN TestRace
|
||||
==================
|
||||
WARNING: DATA RACE
|
||||
Read at 0x0000007f12a8 by goroutine 8:
|
||||
racesurvey/B_inbody.TestRace.func1()
|
||||
/tmp/racesurvey/B_inbody/b_test.go:13 +0x74
|
||||
|
||||
Previous write at 0x0000007f12a8 by goroutine 9:
|
||||
racesurvey/B_inbody.TestRace.func2()
|
||||
/tmp/racesurvey/B_inbody/b_test.go:14 +0x8c
|
||||
|
||||
Goroutine 8 (running) created at:
|
||||
racesurvey/B_inbody.TestRace()
|
||||
/tmp/racesurvey/B_inbody/b_test.go:13 +0xbe
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
|
||||
Goroutine 9 (finished) created at:
|
||||
racesurvey/B_inbody.TestRace()
|
||||
/tmp/racesurvey/B_inbody/b_test.go:14 +0x124
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
==================
|
||||
testing.go:1712: race detected during execution of test
|
||||
--- FAIL: TestRace (0.00s)
|
||||
FAIL
|
||||
19
cmd/testwrapper/testdata/B_inbody/src.go
vendored
Normal file
19
cmd/testwrapper/testdata/B_inbody/src.go
vendored
Normal file
@ -0,0 +1,19 @@
|
||||
// Copyright (c) Tailscale Inc & contributors
|
||||
// SPDX-License-Identifier: BSD-3-Clause
|
||||
|
||||
package inbody
|
||||
|
||||
import (
|
||||
"sync"
|
||||
"testing"
|
||||
)
|
||||
|
||||
var counter int
|
||||
|
||||
func TestRace(t *testing.T) {
|
||||
var wg sync.WaitGroup
|
||||
wg.Add(2)
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
wg.Wait()
|
||||
}
|
||||
32
cmd/testwrapper/testdata/C_spawnwait/caught.raw.txt
vendored
Normal file
32
cmd/testwrapper/testdata/C_spawnwait/caught.raw.txt
vendored
Normal file
@ -0,0 +1,32 @@
|
||||
=== RUN TestSpawn
|
||||
==================
|
||||
WARNING: DATA RACE
|
||||
Read at 0x0000007f12a8 by goroutine 9:
|
||||
racesurvey/C_spawnwait.TestSpawn.func2()
|
||||
/tmp/racesurvey/C_spawnwait/c_test.go:14 +0x70
|
||||
|
||||
Previous write at 0x0000007f12a8 by goroutine 8:
|
||||
racesurvey/C_spawnwait.TestSpawn.func1()
|
||||
/tmp/racesurvey/C_spawnwait/c_test.go:13 +0x88
|
||||
|
||||
Goroutine 9 (running) created at:
|
||||
racesurvey/C_spawnwait.TestSpawn()
|
||||
/tmp/racesurvey/C_spawnwait/c_test.go:14 +0x44
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
|
||||
Goroutine 8 (finished) created at:
|
||||
racesurvey/C_spawnwait.TestSpawn()
|
||||
/tmp/racesurvey/C_spawnwait/c_test.go:13 +0x34
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
==================
|
||||
testing.go:1712: race detected during execution of test
|
||||
--- FAIL: TestSpawn (0.00s)
|
||||
=== RUN TestWait
|
||||
--- PASS: TestWait (0.00s)
|
||||
FAIL
|
||||
31
cmd/testwrapper/testdata/C_spawnwait/pass.raw.txt
vendored
Normal file
31
cmd/testwrapper/testdata/C_spawnwait/pass.raw.txt
vendored
Normal file
@ -0,0 +1,31 @@
|
||||
=== RUN TestSpawn
|
||||
--- PASS: TestSpawn (0.00s)
|
||||
=== RUN TestWait
|
||||
==================
|
||||
WARNING: DATA RACE
|
||||
Read at 0x0000007f12a8 by goroutine 8:
|
||||
racesurvey/C_spawnwait.TestSpawn.func1()
|
||||
/tmp/racesurvey/C_spawnwait/c_test.go:13 +0x70
|
||||
|
||||
Previous write at 0x0000007f12a8 by goroutine 9:
|
||||
racesurvey/C_spawnwait.TestSpawn.func2()
|
||||
/tmp/racesurvey/C_spawnwait/c_test.go:14 +0x88
|
||||
|
||||
Goroutine 8 (running) created at:
|
||||
racesurvey/C_spawnwait.TestSpawn()
|
||||
/tmp/racesurvey/C_spawnwait/c_test.go:13 +0x34
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
|
||||
Goroutine 9 (finished) created at:
|
||||
racesurvey/C_spawnwait.TestSpawn()
|
||||
/tmp/racesurvey/C_spawnwait/c_test.go:14 +0x44
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
==================
|
||||
--- PASS: TestWait (0.00s)
|
||||
FAIL
|
||||
22
cmd/testwrapper/testdata/C_spawnwait/src.go
vendored
Normal file
22
cmd/testwrapper/testdata/C_spawnwait/src.go
vendored
Normal file
@ -0,0 +1,22 @@
|
||||
// Copyright (c) Tailscale Inc & contributors
|
||||
// SPDX-License-Identifier: BSD-3-Clause
|
||||
|
||||
package spawnwait
|
||||
|
||||
import (
|
||||
"sync"
|
||||
"testing"
|
||||
)
|
||||
|
||||
var counter int
|
||||
var wg sync.WaitGroup
|
||||
|
||||
func TestSpawn(t *testing.T) {
|
||||
wg.Add(2)
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
}
|
||||
|
||||
func TestWait(t *testing.T) {
|
||||
wg.Wait()
|
||||
}
|
||||
32
cmd/testwrapper/testdata/D_delayed/raw.txt
vendored
Normal file
32
cmd/testwrapper/testdata/D_delayed/raw.txt
vendored
Normal file
@ -0,0 +1,32 @@
|
||||
=== RUN TestA
|
||||
--- PASS: TestA (0.00s)
|
||||
=== RUN TestSleep
|
||||
==================
|
||||
WARNING: DATA RACE
|
||||
Read at 0x0000007f12a8 by goroutine 9:
|
||||
racesurvey/D_postterminal.TestA.func2()
|
||||
/tmp/racesurvey/D_postterminal/d_test.go:16 +0x8a
|
||||
|
||||
Previous write at 0x0000007f12a8 by goroutine 8:
|
||||
racesurvey/D_postterminal.TestA.func1()
|
||||
/tmp/racesurvey/D_postterminal/d_test.go:15 +0xa4
|
||||
|
||||
Goroutine 9 (running) created at:
|
||||
racesurvey/D_postterminal.TestA()
|
||||
/tmp/racesurvey/D_postterminal/d_test.go:16 +0x44
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
|
||||
Goroutine 8 (finished) created at:
|
||||
racesurvey/D_postterminal.TestA()
|
||||
/tmp/racesurvey/D_postterminal/d_test.go:15 +0x34
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
==================
|
||||
testing.go:1712: race detected during execution of test
|
||||
--- FAIL: TestSleep (0.05s)
|
||||
FAIL
|
||||
28
cmd/testwrapper/testdata/D_delayed/src.go
vendored
Normal file
28
cmd/testwrapper/testdata/D_delayed/src.go
vendored
Normal file
@ -0,0 +1,28 @@
|
||||
// Copyright (c) Tailscale Inc & contributors
|
||||
// SPDX-License-Identifier: BSD-3-Clause
|
||||
|
||||
package delayed
|
||||
|
||||
import (
|
||||
"sync"
|
||||
"testing"
|
||||
"time"
|
||||
)
|
||||
|
||||
var counter int
|
||||
var wg sync.WaitGroup
|
||||
var trigger = make(chan struct{})
|
||||
|
||||
func TestA(t *testing.T) {
|
||||
wg.Add(2)
|
||||
go func() { defer wg.Done(); <-trigger; counter++ }()
|
||||
go func() { defer wg.Done(); <-trigger; counter++ }()
|
||||
}
|
||||
|
||||
func TestSleep(t *testing.T) {
|
||||
close(trigger)
|
||||
// Sleep long enough that the goroutines race during this sleep,
|
||||
// but TestSleep itself doesn't write to counter.
|
||||
time.Sleep(50 * time.Millisecond)
|
||||
wg.Wait()
|
||||
}
|
||||
26
cmd/testwrapper/testdata/E_testmain/raw.txt
vendored
Normal file
26
cmd/testwrapper/testdata/E_testmain/raw.txt
vendored
Normal file
@ -0,0 +1,26 @@
|
||||
=== RUN TestPass
|
||||
--- PASS: TestPass (0.00s)
|
||||
PASS
|
||||
==================
|
||||
WARNING: DATA RACE
|
||||
Read at 0x0000007f52a8 by goroutine 9:
|
||||
racesurvey/E_testmain.TestMain.func2()
|
||||
/tmp/racesurvey/E_testmain/e_test.go:18 +0x74
|
||||
|
||||
Previous write at 0x0000007f52a8 by goroutine 8:
|
||||
racesurvey/E_testmain.TestMain.func1()
|
||||
/tmp/racesurvey/E_testmain/e_test.go:17 +0x8c
|
||||
|
||||
Goroutine 9 (running) created at:
|
||||
racesurvey/E_testmain.TestMain()
|
||||
/tmp/racesurvey/E_testmain/e_test.go:18 +0x139
|
||||
main.main()
|
||||
_testmain.go:48 +0x171
|
||||
|
||||
Goroutine 8 (finished) created at:
|
||||
racesurvey/E_testmain.TestMain()
|
||||
/tmp/racesurvey/E_testmain/e_test.go:17 +0xcc
|
||||
main.main()
|
||||
_testmain.go:48 +0x171
|
||||
==================
|
||||
Found 1 data race(s)
|
||||
24
cmd/testwrapper/testdata/E_testmain/src.go
vendored
Normal file
24
cmd/testwrapper/testdata/E_testmain/src.go
vendored
Normal file
@ -0,0 +1,24 @@
|
||||
// Copyright (c) Tailscale Inc & contributors
|
||||
// SPDX-License-Identifier: BSD-3-Clause
|
||||
|
||||
package testmain
|
||||
|
||||
import (
|
||||
"sync"
|
||||
"testing"
|
||||
)
|
||||
|
||||
var counter int
|
||||
|
||||
func TestPass(t *testing.T) {
|
||||
}
|
||||
|
||||
func TestMain(m *testing.M) {
|
||||
code := m.Run()
|
||||
var wg sync.WaitGroup
|
||||
wg.Add(2)
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
wg.Wait()
|
||||
_ = code
|
||||
}
|
||||
57
cmd/testwrapper/testdata/F_parallel/split.raw.txt
vendored
Normal file
57
cmd/testwrapper/testdata/F_parallel/split.raw.txt
vendored
Normal file
@ -0,0 +1,57 @@
|
||||
=== RUN TestParA
|
||||
=== PAUSE TestParA
|
||||
=== RUN TestParB
|
||||
=== PAUSE TestParB
|
||||
=== CONT TestParA
|
||||
=== CONT TestParB
|
||||
--- PASS: TestParA (0.00s)
|
||||
==================
|
||||
WARNING: DATA RACE
|
||||
Read at 0x0000007f02b0 by goroutine 8:
|
||||
racesurvey/F_parallel.TestParB()
|
||||
/tmp/racesurvey/F_parallel/f_test.go:17 +0x3b
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
|
||||
Previous write at 0x0000007f02b0 by goroutine 7:
|
||||
racesurvey/F_parallel.TestParA()
|
||||
/tmp/racesurvey/F_parallel/f_test.go:10 +0x53
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.(*T).Run.gowrap1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0x38
|
||||
|
||||
Goroutine 8 (running) created at:
|
||||
testing.(*T).Run()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0xb12
|
||||
testing.runTests.func1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2585 +0x84
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.runTests()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2583 +0x9e9
|
||||
testing.(*M).Run()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2443 +0xf4b
|
||||
main.main()
|
||||
_testmain.go:48 +0x164
|
||||
|
||||
Goroutine 7 (running) created at:
|
||||
testing.(*T).Run()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2101 +0xb12
|
||||
testing.runTests.func1()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2585 +0x84
|
||||
testing.tRunner()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2036 +0x21c
|
||||
testing.runTests()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2583 +0x9e9
|
||||
testing.(*M).Run()
|
||||
/home/ubuntu/sdk/go1.26.3/src/testing/testing.go:2443 +0xf4b
|
||||
main.main()
|
||||
_testmain.go:48 +0x164
|
||||
==================
|
||||
=== NAME TestParB
|
||||
testing.go:1712: race detected during execution of test
|
||||
--- FAIL: TestParB (0.00s)
|
||||
FAIL
|
||||
22
cmd/testwrapper/testdata/F_parallel/src.go
vendored
Normal file
22
cmd/testwrapper/testdata/F_parallel/src.go
vendored
Normal file
@ -0,0 +1,22 @@
|
||||
// Copyright (c) Tailscale Inc & contributors
|
||||
// SPDX-License-Identifier: BSD-3-Clause
|
||||
|
||||
package parallel
|
||||
|
||||
import "testing"
|
||||
|
||||
var counter int
|
||||
|
||||
func TestParA(t *testing.T) {
|
||||
t.Parallel()
|
||||
for i := 0; i < 100; i++ {
|
||||
counter++
|
||||
}
|
||||
}
|
||||
|
||||
func TestParB(t *testing.T) {
|
||||
t.Parallel()
|
||||
for i := 0; i < 100; i++ {
|
||||
counter++
|
||||
}
|
||||
}
|
||||
133
cmd/testwrapper/testdata/README.md
vendored
Normal file
133
cmd/testwrapper/testdata/README.md
vendored
Normal file
@ -0,0 +1,133 @@
|
||||
# Race-output test corpus
|
||||
|
||||
This directory is a corpus of captured Go test binary outputs that
|
||||
exercise the various ways the `-race` detector's `WARNING: DATA RACE`
|
||||
text can land relative to `=== RUN` / `--- PASS:` / `--- FAIL:` /
|
||||
`=== NAME` lines, and how `cmd/internal/test2json` attributes that
|
||||
output to tests.
|
||||
|
||||
Each scenario subdirectory contains:
|
||||
|
||||
- `src.go` — the Go source code that was compiled and run to produce
|
||||
the captured output. Reproduce via
|
||||
`go test -race -c -o /tmp/scenario.test ./<dir>/`.
|
||||
- `raw.txt` (or scenario-specific name) — the raw stdout+stderr of
|
||||
the resulting test binary when run as `./scenario.test -test.v`.
|
||||
This is the byte stream that `go test -json` feeds to
|
||||
`go tool test2json` in production.
|
||||
|
||||
`go test -json` adds two things on top of what `test2json` sees,
|
||||
which are NOT in these captures: a `FAIL\t<pkg>\t<time>` output line
|
||||
and a corresponding `fail` action event when the binary exits with a
|
||||
non-zero status (e.g. the race detector's exit code 66). Consumers
|
||||
that simulate the `go test -json` view from these files need to
|
||||
append those.
|
||||
|
||||
To turn a `raw.txt` into the JSON `testwrapper` would consume:
|
||||
|
||||
```
|
||||
go tool test2json -p <pkgname> < raw.txt
|
||||
```
|
||||
|
||||
## Scenarios
|
||||
|
||||
### A_baseline — no race
|
||||
|
||||
Two trivial passing tests, no `-race` involvement at all. Useful as a
|
||||
sanity-check for parsers; demonstrates the standard mapping from
|
||||
`=== RUN`/`--- PASS:`/bare `PASS` lines to JSON events.
|
||||
|
||||
### B_inbody — race during a test's own body
|
||||
|
||||
A single test spawns racing goroutines and `wg.Wait()`s for them.
|
||||
The race fires while the test is still running, so
|
||||
`testing.checkRaces` sees `race.Errors()` increment between the
|
||||
test's start and end and the test is marked `--- FAIL:` with a
|
||||
`testing.go:1712: race detected during execution of test` line.
|
||||
|
||||
This is the well-behaved case: the race output and the failure marker
|
||||
are both attributed to a single, clearly-failed test.
|
||||
|
||||
### C_spawnwait — race in goroutines that outlive a test
|
||||
|
||||
`TestSpawn` spawns racing goroutines and returns immediately;
|
||||
`TestWait` blocks until they finish. Where the race report lands is
|
||||
timing-dependent. Two captured variants:
|
||||
|
||||
- `pass.raw.txt` — both `TestSpawn` and `TestWait` end up marked
|
||||
`--- PASS:`, with the entire `WARNING: DATA RACE` report
|
||||
attributed to `TestWait` (the test whose `=== RUN` line was the
|
||||
most recent thing emitted when TSan printed). Neither test's
|
||||
`checkRaces` saw `race.Errors()` increment within its window. The
|
||||
binary still exits non-zero, producing only a bare trailing
|
||||
`FAIL`. **This is the case where testwrapper currently drops the
|
||||
race report on the floor.**
|
||||
|
||||
- `caught.raw.txt` — `TestSpawn`'s `checkRaces` happened to fire
|
||||
after the goroutines raced, so it emits the standard
|
||||
`testing.go:1712:` + `--- FAIL: TestSpawn` markers. Race report is
|
||||
attributed to `TestSpawn`, and the failure is attributed to
|
||||
`TestSpawn` too. Well-behaved.
|
||||
|
||||
### D_delayed — race delayed into the next test's body
|
||||
|
||||
Like `C_spawnwait` but the spawned goroutines block on a channel that
|
||||
the second test closes, then sleeps. This forces the race counter
|
||||
delta to land between the second test's `resetRaces` and
|
||||
`checkRaces`, so the framework reliably attributes a failure to the
|
||||
sleeping test. Compare with `B_inbody`: same end shape, but the
|
||||
failure is attributed to a test that doesn't *contain* the racing
|
||||
code.
|
||||
|
||||
### E_testmain — race in `TestMain` after `m.Run()`
|
||||
|
||||
The race-producing goroutines are spawned by `TestMain` after
|
||||
`m.Run()` returns. By that point the framework has already printed
|
||||
its top-level `PASS` summary, so `test2json`'s `c.testName` is reset
|
||||
to `""` and the entire race report shows up at **package level** —
|
||||
all of its `output` events have an empty `Test` field. The bare
|
||||
`PASS` line earlier in the output also causes `test2json` to set
|
||||
`c.result = "pass"`, which means `go tool test2json` in isolation
|
||||
ends up emitting `{"Action":"pass","Package":"..."}` for the
|
||||
package; only `go test`'s own exit-code post-processing turns it
|
||||
into the visible package-level failure.
|
||||
|
||||
### F_parallel — racing parallel tests
|
||||
|
||||
Two `t.Parallel()` tests both increment the same global. The
|
||||
captured `split.raw.txt` shows the report **split across two tests**
|
||||
via a `=== NAME TestParB` redirect line emitted by the framework:
|
||||
|
||||
```
|
||||
--- PASS: TestParA (0.00s)
|
||||
==================
|
||||
WARNING: DATA RACE
|
||||
... full race report ...
|
||||
==================
|
||||
=== NAME TestParB
|
||||
testing.go:1712: race detected during execution of test
|
||||
--- FAIL: TestParB (0.00s)
|
||||
```
|
||||
|
||||
`test2json` attributes the `WARNING: DATA RACE` block plus the full
|
||||
stack trace to `TestParA` (which passes), then sees the
|
||||
`=== NAME TestParB` directive and switches attribution, so the
|
||||
trailing `race detected` line and `--- FAIL` end up under
|
||||
`TestParB` (which fails). A consumer that only flushes failed tests'
|
||||
logs sees the `race detected` line but loses the stack trace.
|
||||
|
||||
## How these were captured
|
||||
|
||||
```
|
||||
# For each scenario directory <name>/ (e.g. C_spawnwait):
|
||||
go test -race -c -o /tmp/<name>.test ./testdata/<name>/
|
||||
/tmp/<name>.test -test.v >./testdata/<name>/raw.txt 2>&1
|
||||
```
|
||||
|
||||
For scenarios where the race detector's attribution is
|
||||
timing-dependent (C, F), the binary was run repeatedly and the
|
||||
interesting variants saved with distinct names.
|
||||
|
||||
The captured outputs contain absolute file paths from the machine
|
||||
they were recorded on (e.g. `/tmp/racesurvey/...`). Tests that
|
||||
match against these files should not depend on those paths.
|
||||
@ -30,6 +30,14 @@
|
||||
|
||||
const (
|
||||
maxAttempts = 3
|
||||
|
||||
// raceDetectorMarkerLine is the first line of every Go race
|
||||
// detector report, emitted at column 0. We look for it as a
|
||||
// whole line (not as a substring) so that we don't false-fire
|
||||
// on tests that legitimately print the same text indented in
|
||||
// their own logs — for example, this package's own race tests,
|
||||
// which exec a child testwrapper and dump its captured output.
|
||||
raceDetectorMarkerLine = "WARNING: DATA RACE\n"
|
||||
)
|
||||
|
||||
type testAttempt struct {
|
||||
@ -41,6 +49,10 @@ type testAttempt struct {
|
||||
start, end time.Time
|
||||
isMarkedFlaky bool // set if the test is marked as flaky
|
||||
issueURL string // set if the test is marked as flaky
|
||||
// raceDetected is true on a per-test event if that test's output
|
||||
// contained a race report, and true on a pkgFinished event if any
|
||||
// test in the package -- or the package's own output -- did.
|
||||
raceDetected bool
|
||||
|
||||
pkgFinished bool
|
||||
}
|
||||
@ -153,14 +165,46 @@ func runTests(ctx context.Context, attempt int, pt *packageTests, goTestArgs, te
|
||||
outcome = "fail"
|
||||
}
|
||||
pkgTests[""].logs.WriteString(goOutput.Output)
|
||||
// If a data race was detected anywhere in this
|
||||
// package's output -- whether at the package level or
|
||||
// attributed to a specific test -- consolidate all
|
||||
// per-test logs into the package-level logs so the
|
||||
// full race report is visible regardless of which
|
||||
// test test2json happened to attribute it to. The
|
||||
// pkgFinished testAttempt also carries raceDetected
|
||||
// so the main loop can suppress flaky-test retries.
|
||||
raceDetected := pkgTests[""].raceDetected
|
||||
if !raceDetected {
|
||||
for _, t := range pkgTests {
|
||||
if t.raceDetected {
|
||||
raceDetected = true
|
||||
break
|
||||
}
|
||||
}
|
||||
}
|
||||
if raceDetected {
|
||||
var ts []*testAttempt
|
||||
for _, t := range pkgTests {
|
||||
if t.testName != "" && t.logs.Len() > 0 {
|
||||
ts = append(ts, t)
|
||||
}
|
||||
}
|
||||
slices.SortFunc(ts, func(a, b *testAttempt) int {
|
||||
return a.start.Compare(b.start)
|
||||
})
|
||||
for _, t := range ts {
|
||||
pkgTests[""].logs.Write(t.logs.Bytes())
|
||||
}
|
||||
}
|
||||
ch <- &testAttempt{
|
||||
pkg: goOutput.Package,
|
||||
outcome: outcome,
|
||||
start: pkgTests[""].start,
|
||||
end: goOutput.Time,
|
||||
logs: pkgTests[""].logs,
|
||||
pkgFinished: true,
|
||||
cached: pkgCached[goOutput.Package],
|
||||
pkg: goOutput.Package,
|
||||
outcome: outcome,
|
||||
start: pkgTests[""].start,
|
||||
end: goOutput.Time,
|
||||
logs: pkgTests[""].logs,
|
||||
pkgFinished: true,
|
||||
cached: pkgCached[goOutput.Package],
|
||||
raceDetected: raceDetected,
|
||||
}
|
||||
case "output":
|
||||
// Capture all output from the package except for the final
|
||||
@ -168,6 +212,9 @@ func runTests(ctx context.Context, attempt int, pt *packageTests, goTestArgs, te
|
||||
// printPkgOutcome will output a similar line
|
||||
if !strings.HasPrefix(goOutput.Output, fmt.Sprintf("FAIL\t%s\t", goOutput.Package)) {
|
||||
pkgTests[""].logs.WriteString(goOutput.Output)
|
||||
if goOutput.Output == raceDetectorMarkerLine {
|
||||
pkgTests[""].raceDetected = true
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@ -178,6 +225,9 @@ func runTests(ctx context.Context, attempt int, pt *packageTests, goTestArgs, te
|
||||
testName = test
|
||||
if goOutput.Action == "output" {
|
||||
resultMap[pkg][testName].logs.WriteString(goOutput.Output)
|
||||
if goOutput.Output == raceDetectorMarkerLine {
|
||||
resultMap[pkg][testName].raceDetected = true
|
||||
}
|
||||
}
|
||||
continue
|
||||
}
|
||||
@ -200,6 +250,9 @@ func runTests(ctx context.Context, attempt int, pt *packageTests, goTestArgs, te
|
||||
pkgTests[testName].issueURL = strings.TrimPrefix(suffix, ": ")
|
||||
} else {
|
||||
pkgTests[testName].logs.WriteString(goOutput.Output)
|
||||
if goOutput.Output == raceDetectorMarkerLine {
|
||||
pkgTests[testName].raceDetected = true
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
@ -305,6 +358,16 @@ type nextRun struct {
|
||||
tr.pkg = packages[0]
|
||||
}
|
||||
if tr.pkgFinished {
|
||||
if tr.raceDetected {
|
||||
// A data race is never something we want to
|
||||
// paper over by retrying flaky tests in the
|
||||
// package: the race indicates a real bug
|
||||
// that may not even be in the failing test,
|
||||
// and a retry could hide it. Discard any
|
||||
// retry plans for this pkg and fail fast.
|
||||
delete(toRetry, tr.pkg)
|
||||
failed = true
|
||||
}
|
||||
if tr.outcome == "fail" && len(toRetry[tr.pkg]) == 0 {
|
||||
// If a package fails and we don't have any tests to
|
||||
// retry, then we should fail. This typically happens
|
||||
|
||||
@ -145,6 +145,118 @@ func TestAlwaysError(t *testing.T) {
|
||||
}
|
||||
}
|
||||
|
||||
// TestRaceSuppressesFlakyRetry verifies that detecting a data race
|
||||
// in a package's output stops testwrapper from retrying any flaky
|
||||
// test in that package. Races are too serious to paper over: the
|
||||
// flaky test might not even be the one whose code is racy, and a
|
||||
// retry without the racy goroutine could silently hide the bug.
|
||||
func TestRaceSuppressesFlakyRetry(t *testing.T) {
|
||||
if runtime.GOOS != "linux" || runtime.GOARCH != "amd64" {
|
||||
t.Skip("test requires the race detector, which needs linux/amd64")
|
||||
}
|
||||
t.Parallel()
|
||||
|
||||
testfile := filepath.Join(t.TempDir(), "raceretry_test.go")
|
||||
code := []byte(`package raceretry_test
|
||||
|
||||
import (
|
||||
"sync"
|
||||
"testing"
|
||||
"tailscale.com/cmd/testwrapper/flakytest"
|
||||
)
|
||||
|
||||
var counter int
|
||||
|
||||
func TestRace(t *testing.T) {
|
||||
var wg sync.WaitGroup
|
||||
wg.Add(2)
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
wg.Wait()
|
||||
}
|
||||
|
||||
func TestFlaky(t *testing.T) {
|
||||
flakytest.Mark(t, "https://github.com/tailscale/tailscale/issues/0")
|
||||
t.Fatal("flaky test failing; would normally be retried")
|
||||
}
|
||||
`)
|
||||
if err := os.WriteFile(testfile, code, 0o644); err != nil {
|
||||
t.Fatalf("writing package: %s", err)
|
||||
}
|
||||
|
||||
out, err := cmdTestwrapper(t, testfile, "-race").CombinedOutput()
|
||||
if code, ok := errExitCode(err); !ok || code != 1 {
|
||||
t.Fatalf("testwrapper %s -race: expected exit code 1, got %v; output was:\n%s", testfile, err, out)
|
||||
}
|
||||
if want := "WARNING: DATA RACE"; !bytes.Contains(out, []byte(want)) {
|
||||
t.Fatalf("expected race report in output, got:\n%s", out)
|
||||
}
|
||||
if want := "Not retrying flaky tests"; !bytes.Contains(out, []byte(want)) {
|
||||
t.Fatalf("expected no-retry message in output, got:\n%s", out)
|
||||
}
|
||||
if got := bytes.Count(out, []byte("Attempt #")); got != 0 {
|
||||
t.Fatalf("expected no retry attempts to be made, but %d were:\n%s", got, out)
|
||||
}
|
||||
if got := bytes.Count(out, []byte("=== RUN TestFlaky")); got != 1 {
|
||||
t.Fatalf("expected TestFlaky to be run exactly once, ran %d times:\n%s", got, out)
|
||||
}
|
||||
|
||||
if testing.Verbose() {
|
||||
t.Logf("success - output:\n%s", out)
|
||||
}
|
||||
}
|
||||
|
||||
// TestRaceAttributedToPassingTest covers the case where go test
|
||||
// attributes a data race report to a test that itself reports PASS
|
||||
// (e.g. when the racing goroutines outlive the test that spawned
|
||||
// them and TSan prints during a different test's window). Without
|
||||
// the race-detection fix, the WARNING: DATA RACE block would be
|
||||
// stuck in a passing test's log buffer and dropped on the floor.
|
||||
// See https://github.com/tailscale/tailscale/issues/19603.
|
||||
func TestRaceAttributedToPassingTest(t *testing.T) {
|
||||
if runtime.GOOS != "linux" || runtime.GOARCH != "amd64" {
|
||||
t.Skip("test requires the race detector, which needs linux/amd64")
|
||||
}
|
||||
t.Parallel()
|
||||
|
||||
testfile := filepath.Join(t.TempDir(), "race_test.go")
|
||||
code := []byte(`package race_test
|
||||
|
||||
import (
|
||||
"sync"
|
||||
"testing"
|
||||
)
|
||||
|
||||
var counter int
|
||||
var wg sync.WaitGroup
|
||||
|
||||
func TestSpawn(t *testing.T) {
|
||||
wg.Add(2)
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
go func() { defer wg.Done(); counter++ }()
|
||||
}
|
||||
|
||||
func TestWait(t *testing.T) {
|
||||
wg.Wait()
|
||||
}
|
||||
`)
|
||||
if err := os.WriteFile(testfile, code, 0o644); err != nil {
|
||||
t.Fatalf("writing package: %s", err)
|
||||
}
|
||||
|
||||
out, err := cmdTestwrapper(t, testfile, "-race").CombinedOutput()
|
||||
if code, ok := errExitCode(err); !ok || code != 1 {
|
||||
t.Fatalf("testwrapper %s -race: expected exit code 1, got %v; output was:\n%s", testfile, err, out)
|
||||
}
|
||||
if want := "WARNING: DATA RACE"; !bytes.Contains(out, []byte(want)) {
|
||||
t.Fatalf("expected race report in output, got:\n%s", out)
|
||||
}
|
||||
|
||||
if testing.Verbose() {
|
||||
t.Logf("success - output:\n%s", out)
|
||||
}
|
||||
}
|
||||
|
||||
func TestBuildError(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
|
||||
Loading…
Reference in New Issue
Block a user