Go: testing: Cleanup races with Logf and Errorf

[bcmills]

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]

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

[bcmills]

CC @mlowicki @tklauser

[mlowicki]

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

[vagababov]

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

[gopherbot]

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

[bcmills]

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

[gopherbot]

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]

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

[gopherbot]

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