testing: data race in testing.go

[bep]

Please answer these questions before submitting your issue. Thanks!

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

tip

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

Linux.

WARNING: DATA RACE

Read at 0x00c4200a6404 by goroutine 29:

  testing.(*common).Fail()

      /home/travis/.gimme/versions/go/src/testing/testing.go:411 +0x9f

  testing.(*common).FailNow()

      /home/travis/.gimme/versions/go/src/testing/testing.go:431 +0x38

  testing.(*common).Fatalf()

      /home/travis/.gimme/versions/go/src/testing/testing.go:496 +0x94

  github.com/fsnotify/fsnotify.TestInotifyStress.func3()

      /home/travis/gopath/src/github.com/fsnotify/fsnotify/inotify_test.go:223 +0x18b

Previous write at 0x00c4200a6404 by goroutine 25:

  testing.tRunner.func1()

      /home/travis/.gimme/versions/go/src/testing/testing.go:605 +0x34a

  testing.tRunner()

      /home/travis/.gimme/versions/go/src/testing/testing.go:612 +0xe5

Goroutine 29 (running) created at:

  github.com/fsnotify/fsnotify.TestInotifyStress()

      /home/travis/gopath/src/github.com/fsnotify/fsnotify/inotify_test.go:227 +0x318

  testing.tRunner()

      /home/travis/.gimme/versions/go/src/testing/testing.go:610 +0xc9

Goroutine 25 (finished) created at:

  testing.(*T).Run()

      /home/travis/.gimme/versions/go/src/testing/testing.go:646 +0x52f

  testing.RunTests.func1()

      /home/travis/.gimme/versions/go/src/testing/testing.go:793 +0xb9

  testing.tRunner()

      /home/travis/.gimme/versions/go/src/testing/testing.go:610 +0xc9

  testing.RunTests()

      /home/travis/.gimme/versions/go/src/testing/testing.go:799 +0x4b5

  testing.(*M).Run()

      /home/travis/.gimme/versions/go/src/testing/testing.go:743 +0x12f

  main.main()

      github.com/fsnotify/fsnotify/_test/_testmain.go:114 +0x1b4

==================

panic: Fail in goroutine after TestInotifyStress has completed

goroutine 37 [running]:

panic(0x58d060, 0xc420017440)

    /home/travis/.gimme/versions/go/src/runtime/panic.go:500 +0x1ae

testing.(*common).Fail(0xc4200a63c0)

    /home/travis/.gimme/versions/go/src/testing/testing.go:412 +0x182

testing.(*common).FailNow(0xc4200a63c0)

    /home/travis/.gimme/versions/go/src/testing/testing.go:431 +0x39

testing.(*common).Fatalf(0xc4200a63c0, 0x5bc565, 0x11, 0xc42003ff60, 0x1, 0x1)

    /home/travis/.gimme/versions/go/src/testing/testing.go:496 +0x95

github.com/fsnotify/fsnotify.TestInotifyStress.func3(0xc42001b020, 0xc42000cb60, 0x1f, 0xc4200a63c0)

    /home/travis/gopath/src/github.com/fsnotify/fsnotify/inotify_test.go:223 +0x18c

created by github.com/fsnotify/fsnotify.TestInotifyStress

    /home/travis/gopath/src/github.com/fsnotify/fsnotify/inotify_test.go:227 +0x319

exit status 2

See https://travis-ci.org/fsnotify/fsnotify/jobs/124355194

There have been several related issues with the fsnotify build on Linux on tip lately.

See fsnotify/fsnotify#150

[dsnet]

This is actually intended behavior.

If you read the panic in https://travis-ci.org/fsnotify/fsnotify/jobs/135335818, you see the message:
panic: Fail in goroutine after TestInotifyStress has completed. What this means is that one of the tests called t.Error or t.Fatal some time after the Test function had returned.

Prior to Go 1.7, the testing package would silently ignore this situation, but in Go1.7 it would now complain loudly when this happened.

If this is not the case, feel free to re-open this issue!

[bep]

@dsnet a data race can never be intented behaviour; data race means "all bets are off" and should be fixed -- or at least not brushed off with a "I don't think this is an issue anymore". There are two issues in the log above. I have no access to reopen this issue, so please do.

[davecheney]

@bep, the issue is in the fsnotify code, you should raise the error there.

[bep]

The data race is in the Go code.

[davecheney]

@bep i'm sorry it is not. The race is because the fsnotify test is calling Fatal in a goroutine it has spawned from the main testing goroutine. This is specifically prohibited, and noted explicitly when running under the race detector.

[dsnet]

It is intended behavior in the sense that calling t.Error or t.Fatal after the Test function has returned was undefined behavior. If you think about it, there is a no sensible action in this situation other than to complain loudly. If we were to ignore the Error (as in 1.6 behavior), that leads to tests that may mistakenly report pass, when it was intended that they fail. If we were to allow Error after the Test function returned, then the tests may pass or fail in non-deterministic ways, especially if the Test in question happened to be the last Test run.

Thus, correct Go tests must ensure that they don't call Error or Fatal after the Test completes.

[cespare]

@bep FYI see #15654 and https://golang.org/cl/23320 for more info.

[dsnet]

Russ' comment on that CL is helpful:

The Lock/Unlock here is only to synchronize buggy tests that are racing the test finishing against another goroutine calling t.Fail. If you take the lock out, then tests run under the race detector will report the race, possibly more reliably. So probably take the Lock out.

[bep]

Thanks for the context, will track this on fsnotify.