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

Jump to bottom

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
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.16

Comments

@bcmills
Copy link
Contributor

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
@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Aug 19, 2020
@bcmills bcmills added this to the Backlog milestone Aug 19, 2020
@bcmills bcmills mentioned this issue Aug 19, 2020
Closed
@rogpeppe
Copy link
Contributor

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

@bcmills
Copy link
Contributor Author

bcmills commented Aug 21, 2020

CC @mlowicki @tklauser

@mlowicki
Copy link
Contributor

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

@vagababov vagababov mentioned this issue Aug 21, 2020
Merged
@vagababov
Copy link

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

@gopherbot
Copy link

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

@bcmills
Copy link
Contributor Author

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 gopherbot mentioned this issue Aug 25, 2020
Closed
@gopherbot
Copy link

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
Contributor Author

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

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
@mlowicki
[release-branch.go1.15] testing: fix Cleanup race with Logf and Errorf
45265c2 
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>
@vagababov vagababov mentioned this issue Aug 31, 2020
Merged
@julz julz mentioned this issue Sep 2, 2020
Merged
@markusthoemmes markusthoemmes mentioned this issue Sep 2, 2020
Closed
@dmitshur dmitshur modified the milestones: Backlog, Go1.16 Sep 2, 2020
@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Sep 2, 2020
@dsymonds dsymonds mentioned this issue Sep 8, 2020
Open
@bcmills bcmills mentioned this issue Oct 9, 2020
Open
@nak3 nak3 mentioned this issue Jan 25, 2021
Merged
@golang golang locked and limited conversation to collaborators Sep 2, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Milestone
Go1.16
Development

No branches or pull requests
6 participants
@rogpeppe @mlowicki @vagababov @dmitshur @bcmills @gopherbot