race detected output inconsistently reported #310

edaniels · 2023-03-09T01:42:20Z

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

The text was updated successfully, but these errors were encountered:

dnephin · 2023-03-13T21:26:48Z

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: golang/go#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 · 2023-03-15T23:27:40Z

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

edaniels · 2023-03-15T23:27:54Z

Thank you for checking if it would though!

The original flaky test shows in CI pipeline[1], but gotestsum run into a golang issue[2]. The error message is not clear from summary, like ``` {"Time":"2023-03-02T09:19:38.754394861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1433 +0x7e4\n"} {"Time":"2023-03-02T09:19:38.754414561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/runtime/panic.go:476 +0x32\n"} {"Time":"2023-03-02T09:19:38.754430561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1493 +0x47\n"} {"Time":"2023-03-02T09:19:38.754482561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:883 +0xc4\n"} {"Time":"2023-03-02T09:19:38.754497661Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:876 +0xa4\n"} {"Time":"2023-03-02T09:19:38.754512161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:927 +0x6a\n"} {"Time":"2023-03-02T09:19:38.754567661Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap/zaptest.testingWriter.Write()\n"} {"Time":"2023-03-02T09:19:38.754571261Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x12c\n"} {"Time":"2023-03-02T09:19:38.754582861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap/zaptest.(*testingWriter).Write()\n"} {"Time":"2023-03-02T09:19:38.754597761Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap/zapcore.(*ioCore).Write()\n"} {"Time":"2023-03-02T09:19:38.754600961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x199\n"} {"Time":"2023-03-02T09:19:38.754612761Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap/zapcore.(*CheckedEntry).Write()\n"} {"Time":"2023-03-02T09:19:38.754618561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2ce\n"} {"Time":"2023-03-02T09:19:38.754630161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.uber.org/zap.(*Logger).Info()\n"} {"Time":"2023-03-02T09:19:38.754633261Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:220 +0x6a\n"} {"Time":"2023-03-02T09:19:38.754644861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.(*treeIndex).Compact()\n"} {"Time":"2023-03-02T09:19:38.754648461Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/index.go:194 +0x144\n"} {"Time":"2023-03-02T09:19:38.754664961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.(*store).scheduleCompaction()\n"} {"Time":"2023-03-02T09:19:38.754670161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/kvstore_compaction.go:29 +0xbb\n"} {"Time":"2023-03-02T09:19:38.754681861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.(*store).compact.func1()\n"} {"Time":"2023-03-02T09:19:38.754690561Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/kvstore.go:235 +0x9e\n"} {"Time":"2023-03-02T09:19:38.754720061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.job.Do()\n"} {"Time":"2023-03-02T09:19:38.754724161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:41 +0x70\n"} {"Time":"2023-03-02T09:19:38.754736161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.(*job).Do()\n"} {"Time":"2023-03-02T09:19:38.754750961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.(*fifo).executeJob()\n"} {"Time":"2023-03-02T09:19:38.754754161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:206 +0x101\n"} {"Time":"2023-03-02T09:19:38.754765861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.(*fifo).run()\n"} {"Time":"2023-03-02T09:19:38.754769061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:187 +0x1a5\n"} {"Time":"2023-03-02T09:19:38.754780461Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler.func1()\n"} {"Time":"2023-03-02T09:19:38.754783661Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:101 +0x39\n"} {"Time":"2023-03-02T09:19:38.754824061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1493 +0x75d\n"} FAIL: (code:1): % (cd server && 'env' 'ETCD_VERIFY=all' 'go' 'test' '-v' '-json' '-short' '-timeout=3m' '--race=true' '--cpu=4' './...' '-p=2') {"Time":"2023-03-02T09:19:38.754838961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1846 +0x99\n"} {"Time":"2023-03-02T09:19:38.754854961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1446 +0x216\n"} {"Time":"2023-03-02T09:19:38.754893461Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1844 +0x7ec\n"} {"Time":"2023-03-02T09:19:38.754908961Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1726 +0xa84\n"} {"Time":"2023-03-02T09:19:38.754957861Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler()\n"} {"Time":"2023-03-02T09:19:38.754961061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/pkg/schedule/schedule.go:101 +0x3b6\n"} {"Time":"2023-03-02T09:19:38.754976161Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.NewStore()\n"} {"Time":"2023-03-02T09:19:38.754979361Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/kvstore.go:111 +0x331\n"} {"Time":"2023-03-02T09:19:38.754991061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" go.etcd.io/etcd/server/v3/storage/mvcc.TestHashByRevValue()\n"} {"Time":"2023-03-02T09:19:38.754994261Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /home/runner/work/etcd/etcd/server/storage/mvcc/hash_test.go:36 +0xa4\n"} {"Time":"2023-03-02T09:19:38.755010061Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1446 +0x216\n"} {"Time":"2023-03-02T09:19:38.755024461Z","Action":"output","Package":"go.etcd.io/etcd/server/v3/storage/mvcc","Test":"TestHashByRevValue","Output":" /opt/hostedtoolcache/go/1.19.6/x64/src/testing/testing.go:1493 +0x47\n"} === Failed === FAIL: storage/mvcc (0.00s) === CONT testing.go:1319: race detected during execution of test FAIL FAIL go.etcd.io/etcd/server/v3/storage/mvcc 9.852s ``` After using the following command to reproduce it, we can get the error like: ```bash go test -v -p=2 --cpu=4 -count=1000 -failfast --race=true -short -timeout=30m ./ --- PASS: TestHashByRevValueLastRevision (0.12s) ================== WARNING: DATA RACE Read at 0x00c002024043 by goroutine 65745: testing.(*common).logDepth() /usr/lib/go-1.19/src/testing/testing.go:883 +0xc4 testing.(*common).log() /usr/lib/go-1.19/src/testing/testing.go:876 +0xa4 testing.(*common).Logf() /usr/lib/go-1.19/src/testing/testing.go:927 +0x6a testing.(*T).Logf() <autogenerated>:1 +0x75 go.uber.org/zap/zaptest.testingWriter.Write() /home/fuwei/go/pkg/mod/go.uber.org/zap@v1.24.0/zaptest/logger.go:130 +0x12c go.uber.org/zap/zaptest.(*testingWriter).Write() <autogenerated>:1 +0x7e go.uber.org/zap/zapcore.(*ioCore).Write() /home/fuwei/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/core.go:99 +0x199 go.uber.org/zap/zapcore.(*CheckedEntry).Write() /home/fuwei/go/pkg/mod/go.uber.org/zap@v1.24.0/zapcore/entry.go:255 +0x2ce go.uber.org/zap.(*Logger).Info() /home/fuwei/go/pkg/mod/go.uber.org/zap@v1.24.0/logger.go:220 +0x6a go.etcd.io/etcd/server/v3/storage/mvcc.(*treeIndex).Compact() /home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/index.go:194 +0x144 go.etcd.io/etcd/server/v3/storage/mvcc.(*store).scheduleCompaction() /home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/kvstore_compaction.go:29 +0xbb go.etcd.io/etcd/server/v3/storage/mvcc.(*store).compact.func1() /home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/kvstore.go:235 +0x9e go.etcd.io/etcd/pkg/v3/schedule.job.Do() /home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:41 +0x70 go.etcd.io/etcd/pkg/v3/schedule.(*job).Do() <autogenerated>:1 +0x29 go.etcd.io/etcd/pkg/v3/schedule.(*fifo).executeJob() /home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:206 +0x101 go.etcd.io/etcd/pkg/v3/schedule.(*fifo).run() /home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:187 +0x1a5 go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler.func1() /home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:101 +0x39 Previous write at 0x00c002024043 by goroutine 65743: testing.tRunner.func1() /usr/lib/go-1.19/src/testing/testing.go:1433 +0x7e4 runtime.deferreturn() /usr/lib/go-1.19/src/runtime/panic.go:476 +0x32 testing.(*T).Run.func1() /usr/lib/go-1.19/src/testing/testing.go:1493 +0x47 Goroutine 65745 (running) created at: go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler() /home/fuwei/go/src/go.etcd.io/etcd/pkg/schedule/schedule.go:101 +0x3b6 go.etcd.io/etcd/server/v3/storage/mvcc.NewStore() /home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/kvstore.go:111 +0x331 go.etcd.io/etcd/server/v3/storage/mvcc.TestHashByRevValueLastRevision() /home/fuwei/go/src/go.etcd.io/etcd/server/storage/mvcc/hash_test.go:76 +0xa4 testing.tRunner() /usr/lib/go-1.19/src/testing/testing.go:1446 +0x216 testing.(*T).Run.func1() /usr/lib/go-1.19/src/testing/testing.go:1493 +0x47 Goroutine 65743 (running) created at: testing.(*T).Run() /usr/lib/go-1.19/src/testing/testing.go:1493 +0x75d testing.runTests.func1() /usr/lib/go-1.19/src/testing/testing.go:1846 +0x99 testing.tRunner() /usr/lib/go-1.19/src/testing/testing.go:1446 +0x216 testing.runTests() /usr/lib/go-1.19/src/testing/testing.go:1844 +0x7ec testing.(*M).Run() /usr/lib/go-1.19/src/testing/testing.go:1726 +0xa84 main.main() _testmain.go:265 +0x2e9 ================== ``` The schedule for compact is handled asynchronously and it might use `t.Logf` after go-test marks the case is done. And there is a comment from go-test: ```go // https://github.com/golang/go/blob/c69ff3a7d0c8bd2878662034c1cbce8613fa6f13/src/testing/testing.go#LL1580C3-L1582C16 // Do not lock t.done to allow race detector to detect race in case // the user does not appropriately synchronize a goroutine. t.done = true ``` We need to ensure that all the goroutines should be closed before case finish. REF: [1]: https://github.com/etcd-io/etcd/actions/runs/4312405975/jobs/7522924734 [2]: gotestyourself/gotestsum#310 Signed-off-by: Wei Fu <fuweid89@gmail.com>

mitar · 2023-10-31T18:34:30Z

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

epot · 2023-12-07T13:09:21Z

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?

edaniels mentioned this issue Mar 9, 2023

test2json incorrectly attributes output to a subtest, resulting in missing test failure output #66

Closed

dnephin added the test2json-bug A bug in test2json which impacts gotestsum label Mar 13, 2023

fuweid mentioned this issue Mar 16, 2023

deflake: mvcc storage ut etcd-io/etcd#15489

Merged

czeslavo mentioned this issue Mar 16, 2023

fix(ci): don't use gotestsum in integration tests Kong/kubernetes-ingress-controller#3748

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

race detected output inconsistently reported #310

race detected output inconsistently reported #310

edaniels commented Mar 9, 2023

dnephin commented Mar 13, 2023 •

edited

edaniels commented Mar 15, 2023

edaniels commented Mar 15, 2023

mitar commented Oct 31, 2023

epot commented Dec 7, 2023

race detected output inconsistently reported #310

race detected output inconsistently reported #310

Comments

edaniels commented Mar 9, 2023

dnephin commented Mar 13, 2023 • edited

edaniels commented Mar 15, 2023

edaniels commented Mar 15, 2023

mitar commented Oct 31, 2023

epot commented Dec 7, 2023

dnephin commented Mar 13, 2023 •

edited