testing: Document that T.Log and friends should not be invoked after the end of the test

[slinkydeveloper]

What version of Go are you using (go version)?

$ go version
go version go1.14.3 linux/amd64

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/slinkydeveloper/.cache/go-build"
GOENV="/home/slinkydeveloper/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/slinkydeveloper/go"
GOPRIVATE=""
GOPROXY="direct"
GOROOT="/usr/lib/golang"
GOSUMDB="off"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/golang/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build310442572=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I learnt, while using testing tools, that you cannot invoke t.Logf and similar after t is done: https://golang.org/src/testing/testing.go?s=25276:25317#L1025

What did you expect to see?

Some doc in all logging methods of T, like https://golang.org/pkg/testing/#T.Log, explaining this behaviour:

Be aware that you cannot invoke this method after t is done, otherwise the race detector will detect a race inside the t code.

What did you see instead?

Nothing documented so far

[toothrot]

/cc @mpvl

[ianlancetaylor]

I don't think the docs for this should say anything about the race detector.

In some sense it seems obvious to me that you should not be able to log information after the test ends. And indeed there is an explicit panic for that case (https://golang.org/src/testing/testing.go#L721). But although it seems obvious I think it would be OK to briefly document that requirement in the various Log methods.

[slinkydeveloper]

@ianlancetaylor what about panicking more than causing triggering this race condition?

[ianlancetaylor]

@slinkydeveloper I'm sorry, I don't understand the question.

[slinkydeveloper]

So I experienced this issue because https://golang.org/src/testing/testing.go?s=25276:25317#L1025 writes at same time than https://golang.org/src/testing/testing.go?s=25276:25317#L716 reads, but the write at L1025 doesn't lock the mu mutex.
My understanding from the comment at L1024 is that the write is not guarded by the mutex on purpose, in order to trigger the race detector for bad usages of T.Log. Is it possible to guard that L1025 with a try lock, so if somebody else already locked the mutex, then it's an user error and the code panics with an explicative message?

[slinkydeveloper]

If that's not possible, then I think we should clearly doc this behaviour, so people understands why they see a race in the testing code

[ianlancetaylor]

There is no try-lock for sync.Mutex. And that seems like more complicated code. It might help if you could show a small example that demonstrates the behavior that you want to change.

I've already agreed that we can add some brief documentation. I just don't think the documentation should mention the race detector, because that is irrelevant.

[slinkydeveloper]

Try to run this test:

import (
	"testing"
	"time"
)

func TestTestRace(t *testing.T) {
	t.Run("aaa", func(t *testing.T) {
		go func() {
			for true {
				t.Logf("aaa")
			}
		}()
		time.Sleep(1 * time.Second)
	})
	t.Run("bbb", func(t *testing.T) {
		t.Logf("bbb")
	})
}

And you'll get this race from the race detector:

WARNING: DATA RACE
Read at 0x00c0002da3a3 by goroutine 11:
  testing.(*common).logDepth()
      /usr/lib/golang/src/testing/testing.go:675 +0x14b
  testing.(*common).log()
      /usr/lib/golang/src/testing/testing.go:662 +0x8f
  testing.(*common).Logf()
      /usr/lib/golang/src/testing/testing.go:701 +0x21
  knative.dev/pkg/test/monitoring.TestTestRace.func1.1()
      /home/slinkydeveloper/go/src/knative.dev/pkg/test/monitoring/monitoring_test.go:12 +0x60

Previous write at 0x00c0002da3a3 by goroutine 9:
  testing.tRunner.func1()
      /usr/lib/golang/src/testing/testing.go:977 +0x467
  testing.tRunner()
      /usr/lib/golang/src/testing/testing.go:995 +0x20d

Goroutine 11 (running) created at:
  knative.dev/pkg/test/monitoring.TestTestRace.func1()
      /home/slinkydeveloper/go/src/knative.dev/pkg/test/monitoring/monitoring_test.go:10 +0x4c
  testing.tRunner()
      /usr/lib/golang/src/testing/testing.go:991 +0x1eb

Goroutine 9 (finished) created at:
  testing.(*T).Run()
      /usr/lib/golang/src/testing/testing.go:1042 +0x660
  testing.runTests.func1()
      /usr/lib/golang/src/testing/testing.go:1284 +0xa6
  testing.tRunner()
      /usr/lib/golang/src/testing/testing.go:991 +0x1eb
  testing.runTests()
      /usr/lib/golang/src/testing/testing.go:1282 +0x527
  testing.(*M).Run()
      /usr/lib/golang/src/testing/testing.go:1199 +0x2ff
  main.main()
      _testmain.go:44 +0x223

And that race just sounds weird to me because i don't get any enforcements/clear error messages that I'm effectively doing something wrong. Maybe is the testing.T code itself that is wrong and should have a lock here? https://golang.org/src/testing/testing.go?s=25276:25317#L1025

[ianlancetaylor]

Note that if I change your test to

package x_test

import (
	"testing"
	"time"
)

func TestTestRace(t *testing.T) {
	t.Run("aaa", func(t *testing.T) {
		go func() {
			for true {
				t.Logf("aaa")
			}
		}()
		time.Sleep(1 * time.Second)
	})
	t.Run("bbb", func(t *testing.T) {
		t.Logf("bbb")
	})
}

func TestWait(t *testing.T) {
	time.Sleep(5 * time.Second)
}

then I get

PASS
panic: Log in goroutine after TestTestRace/aaa has completed

goroutine 8 [running]:
testing.(*common).logDepth(0xc000001680, 0xc0010778f8, 0x3, 0x3)
	/home/iant/go/src/testing/testing.go:738 +0x59f
testing.(*common).log(...)
	/home/iant/go/src/testing/testing.go:720
testing.(*common).Logf(0xc000001680, 0x542a91, 0x3, 0x0, 0x0, 0x0)
	/home/iant/go/src/testing/testing.go:766 +0x7e
command-line-arguments_test.TestTestRace.func1.1(0xc000001680)
	/home/iant/foo_test.go:12 +0x53
created by command-line-arguments_test.TestTestRace.func1
	/home/iant/foo_test.go:10 +0x3f
FAIL	command-line-arguments	6.033s
FAIL

In other words, the reason that you don't see a failure with your test is that the test program exits before the problem is detected.

That said, I'm OK with detecting the problem more reliably if there is some safe way to do so.

[ianlancetaylor]

(To be clear, I see that panic shown above when not using -race.)