testing: detect t.FailNow() called from wrong goroutine

[ash2k]

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

1.10.1

Does this issue reproduce with the latest release?

Yes

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

N/A

What did you do?

t.FailNow() has this godoc:

// FailNow marks the function as having failed and stops its execution
// by calling runtime.Goexit (which then runs all deferred calls in the
// current goroutine).
// Execution will continue at the next test or benchmark.
// FailNow must be called from the goroutine running the
// test or benchmark function, not from other goroutines
// created during the test. Calling FailNow does not stop
// those other goroutines.

It is a common mistake to call t.FailNow() from a goroutine spawned in a test, not the goroutine that is executing the test.

What did you expect to see?

Perhaps it is possible to detect this and let the user know? Maybe a panic/failing test with an explanation what is not right.

What did you see instead?

Nothing, it "works".

[dsnet]

Duplicate of #15758, which is closed. I support this feature, but it seems infeasible without runtime trickery.

[dsnet]

If it's any consolation, I've learned that concurrent use of t.FailNow does at least cause the race detector to trigger a warning.

func Test(t *testing.T) {
	go func() { t.FailNow() }()
}

Running with race detector reports:

==================
WARNING: DATA RACE
Write at 0x00c4200e2131 by goroutine 7:
  testing.(*common).Fail()
      /usr/local/go/src/testing/testing.go:511 +0xb2
  testing.(*common).FailNow()
      /usr/local/go/src/testing/testing.go:531 +0x38
  command-line-arguments.Test.func1()
      /tmp/sandbox727028363/main_test.go:8 +0x3a

Previous read at 0x00c4200e2131 by goroutine 6:
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:779 +0x17f

Goroutine 7 (running) created at:
  command-line-arguments.Test()
      /tmp/sandbox727028363/main_test.go:8 +0x4c
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:777 +0x16d

Goroutine 6 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:824 +0x564
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1063 +0xa4
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:777 +0x16d
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1061 +0x4e1
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:978 +0x2cd
  main.main()
      _testmain.go:42 +0x22a
==================
==================
WARNING: DATA RACE
Write at 0x00c4200e2141 by goroutine 7:
  testing.(*common).FailNow()
      /usr/local/go/src/testing/testing.go:552 +0x4a
  command-line-arguments.Test.func1()
      /tmp/sandbox727028363/main_test.go:8 +0x3a

Previous write at 0x00c4200e2141 by goroutine 6:
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:782 +0x199

Goroutine 7 (running) created at:
  command-line-arguments.Test()
      /tmp/sandbox727028363/main_test.go:8 +0x4c
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:777 +0x16d

Goroutine 6 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:824 +0x564
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1063 +0xa4
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:777 +0x16d
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1061 +0x4e1
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:978 +0x2cd
  main.main()
      _testmain.go:42 +0x22a
==================
--- FAIL: Test (0.00s)

[ash2k]

Cannot FailNow() inspect the stacktrace to detect who created the goroutine?

[balshetzer]

@dsnet Can you please reopen this issue? I think the cited duplicate was closed for incorrect reasons and we should discuss the ways in which a solution can be implemented.

[cespare]

@balshetzer well it is true that this issue is a duplicate, so if we were going to reopen one, it would be the first one. At this point, #24680 is the best place to make the case for improving the Fatal/FailNow behavior (as you and I both have).

[balshetzer]

@cespare My thought was that the original issue has been locked due to age and this one had just been closed so I thought it would be easier to reopen this one. I'm concerned that discussion on #24680 will get sidetracked because it is trying to discuss options for Go 2 and I want changes in Go 1.

I think I am going to put together a pull request and see if I can get it accepted.

[ianlancetaylor]

I can reopen #15758 if there is a way to implement it that does not involve any sort of goroutine ID.

[balshetzer]

@ianlancetaylor What I would do is analyze the stack using the runtime package whenever testing.T.FailNow is called. If a specific function isn't in the stack then I would print a warning.

This would also be a good way to catch when the wrong testing.T is called. I see it a lot when people use testing.T.Run they accidentally use the testing.T passed to the Test* function instead of the one passed to the testing.T.Run callback. e.g.

func TestSomething(t1 testing.T) {
  t.Run(func(t2 testing.T) {
    t1.Fatalf("oops")
  })
}

If we encode inside the testing.T which function it should look for then it can even detect this case.

[ianlancetaylor]

OK, reopened #15758.

[cespare]

@ianlancetaylor why is it not okay for the testing package to use the goroutine ID to implement this as long as it's a private detail?

[ianlancetaylor]

The testing package is not the runtime package. Let's not change the testing package to rely on what should be internal runtime details.

[cespare]

@ianlancetaylor we gave testing a hook to know about the environment variables and files that the os package touches in order to support test caching. That seems quite intrusive compared with knowing the goroutine ID.

We can expose the current goroutine via an internal package so that we don't directly do the unsafe nastiness inside the testing package.

Why is it better to rely on parsing the stacks? (Which, incidentally, contain the goroutine ID anyway...)

[ianlancetaylor]

The os package is also not the runtime package. And the internal/testlog package was unavoidable for test caching, which is not the case here.