Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

testing: Cleanup races with Logf and Errorf #40908

Closed
bcmills opened this issue Aug 19, 2020 · 9 comments
Closed

testing: Cleanup races with Logf and Errorf #40908

bcmills opened this issue Aug 19, 2020 · 9 comments
Labels
Milestone

Comments

@bcmills
Copy link
Member

@bcmills bcmills commented Aug 19, 2020

The program in https://play.golang.org/p/rV-CkJivlXs fails under go test -race:

func TestBackgroundCleanup(t *testing.T) {
	helperDone := make(chan struct{})
	go func() {
		t.Logf("Something happened before cleanup.")
		close(helperDone)
	}()

	t.Cleanup(func() {
		<-helperDone
	})
}
$ go version
go version devel +d3a411b6 Wed Aug 19 03:56:26 2020 +0000 linux/amd64

$ go test -race
==================
WARNING: DATA RACE
Read at 0x00c000001858 by goroutine 8:
  testing.(*common).frameSkip()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:488 +0x26e
  testing.(*common).decorate()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:533 +0x64
  testing.(*common).logDepth()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:760 +0x5ab
  testing.(*common).log()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:729 +0x8f
  testing.(*common).Logf()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:775 +0x21
  example%2ecom.TestBackgroundCleanup.func1()
      /tmp/tmp.BqaVZz8DDs/example.com/main_test.go:8 +0x64

Previous write at 0x00c000001858 by goroutine 7:
  testing.(*common).Cleanup.func1()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:867 +0xba
  testing.(*common).runCleanup()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:945 +0xca
  testing.tRunner.func2()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1117 +0x74
  testing.tRunner()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1127 +0x22a

Goroutine 8 (running) created at:
  example%2ecom.TestBackgroundCleanup()
      /tmp/tmp.BqaVZz8DDs/example.com/main_test.go:7 +0x78
  testing.tRunner()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1123 +0x202

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1174 +0x796
  testing.runTests.func1()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1445 +0xa6
  testing.tRunner()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1443 +0x5aa
  testing.(*M).Run()
      /usr/local/google/home/bcmills/sdk/gotip/src/testing/testing.go:1353 +0x4eb
  main.main()
      _testmain.go:43 +0x236
==================
--- FAIL: TestBackgroundCleanup (0.00s)
    main_test.go:8: Something happened before cleanup.
    testing.go:1038: race detected during execution of test
FAIL
exit status 1
FAIL	example.com	0.019s

I think this race should be fixed, because this usage seems reasonable to me: for example, calling t.Logf directly from the Cleanup callback does not race, and it seems very odd to allow t.Logf before and after cleanup begins but not during.

CC @rogpeppe @ianlancetaylor @bradfitz

@rogpeppe
Copy link
Contributor

@rogpeppe rogpeppe commented Aug 21, 2020

Looks like https://go-review.googlesource.com/c/go/+/232237 introduced this issue FWIW.

@bcmills
Copy link
Member Author

@bcmills bcmills commented Aug 21, 2020

@mlowicki
Copy link
Contributor

@mlowicki mlowicki commented Aug 21, 2020

@bcmills Indeed, thanks for pointing this out. I'll work on a fix.

@vagababov
Copy link

@vagababov vagababov commented Aug 21, 2020

We also ran into this here: knative/serving#9153 when I switched from defer to t.Cleanup.

@gopherbot
Copy link

@gopherbot gopherbot commented Aug 23, 2020

Change https://golang.org/cl/250078 mentions this issue: testing: fix Cleanup race with Logf and Errorf

@gopherbot gopherbot closed this in 00a053b Aug 25, 2020
@bcmills
Copy link
Member Author

@bcmills bcmills commented Aug 25, 2020

@gopherbot, please backport to 1.15. This is a fairly subtle race condition, and the fix is small and contained.

@gopherbot
Copy link

@gopherbot gopherbot commented Aug 25, 2020

Backport issue(s) opened: #41034 (for 1.15).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

@bcmills
Copy link
Member Author

@bcmills bcmills commented Aug 25, 2020

Go 1.14.7 does not seem to be affected, so no backport to 1.14 is needed.

@gopherbot
Copy link

@gopherbot gopherbot commented Aug 25, 2020

Change https://golang.org/cl/250617 mentions this issue: [release-branch.go1.15] testing: fix Cleanup race with Logf and Errorf

gopherbot pushed a commit that referenced this issue Aug 27, 2020
Updates #40908
Fixes #41034

Change-Id: I25561a3f18e730a50e6fbf85aa7bd85bf1b73b6e
Reviewed-on: https://go-review.googlesource.com/c/go/+/250078
Reviewed-by: Tobias Klauser <tobias.klauser@gmail.com>
Run-TryBot: Bryan C. Mills <bcmills@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
(cherry picked from commit 00a053b)
Reviewed-on: https://go-review.googlesource.com/c/go/+/250617
Reviewed-by: Emmanuel Odeke <emm.odeke@gmail.com>
Reviewed-by: Michał Łowicki <mlowicki@gmail.com>
@dmitshur dmitshur modified the milestones: Backlog, Go1.16 Sep 2, 2020
@dmitshur dmitshur added NeedsFix and removed NeedsInvestigation labels Sep 2, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
6 participants
You can’t perform that action at this time.