data races in plumbing/transport/internal/common #463
Description
I was recently trying to debug some races in an application which uses go-git. My first instinct is to run my tests with race detection enabled.
$ go test -race
Unfortunately when I do that, many races are printed which actually originate in the underlying go-git library code. I was curious about reproducing this, but it looks like they are reproducible by just running the existing tests for some of the ./plumbing/transport/... modules.
$ go test -race ./plumbing/transport/file
==================
WARNING: DATA RACE
Write at 0x00c420295740 by goroutine 9:
os.(*file).close()
/usr/local/go/src/os/file_unix.go:143 +0x10a
os.(*File).Close()
/usr/local/go/src/os/file_unix.go:132 +0x55
os/exec.(*Cmd).closeDescriptors()
/usr/local/go/src/os/exec/exec.go:263 +0x67
os/exec.(*Cmd).Wait()
/usr/local/go/src/os/exec/exec.go:448 +0x2b8
gopkg.in/src-d/go-git.v4/plumbing/transport/file.(*command).Close()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/file/client.go:76 +0xaa
gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common.(*session).Close()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common/common.go:305 +0xca
gopkg.in/src-d/go-git.v4/plumbing/transport/test.(*ReceivePackSuite).TestAdvertisedReferencesEmpty.func1()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/test/receive_pack.go:33 +0x42
gopkg.in/src-d/go-git.v4/plumbing/transport/test.(*ReceivePackSuite).TestAdvertisedReferencesEmpty()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/test/receive_pack.go:37 +0x2bf
gopkg.in/src-d/go-git.v4/plumbing/transport/file.(*ReceivePackSuite).TestAdvertisedReferencesEmpty()
<autogenerated>:2 +0x5e
runtime.call32()
/usr/local/go/src/runtime/asm_amd64.s:514 +0x47
reflect.Value.Call()
/usr/local/go/src/reflect/value.go:302 +0xc0
gopkg.in/check%2ev1.(*suiteRunner).forkTest.func1()
/Users/orawlings/go/src/gopkg.in/check.v1/check.go:772 +0xa71
gopkg.in/check%2ev1.(*suiteRunner).forkCall.func1()
/Users/orawlings/go/src/gopkg.in/check.v1/check.go:666 +0x89
Previous read at 0x00c420295740 by goroutine 11:
os.(*File).Read()
/usr/local/go/src/os/file.go:98 +0x70
bufio.(*Scanner).Scan()
/usr/local/go/src/bufio/scan.go:207 +0x539
gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common.(*client).listenErrors.func1()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common/common.go:144 +0xf6
Goroutine 9 (running) created at:
gopkg.in/check%2ev1.(*suiteRunner).forkCall()
/Users/orawlings/go/src/gopkg.in/check.v1/check.go:667 +0x42a
gopkg.in/check%2ev1.(*suiteRunner).forkTest()
/Users/orawlings/go/src/gopkg.in/check.v1/check.go:804 +0x133
gopkg.in/check%2ev1.(*suiteRunner).runTest()
/Users/orawlings/go/src/gopkg.in/check.v1/check.go:809 +0x46
gopkg.in/check%2ev1.(*suiteRunner).run()
/Users/orawlings/go/src/gopkg.in/check.v1/check.go:615 +0x205
gopkg.in/check%2ev1.Run()
/Users/orawlings/go/src/gopkg.in/check.v1/run.go:92 +0x5a
gopkg.in/check%2ev1.RunAll()
/Users/orawlings/go/src/gopkg.in/check.v1/run.go:84 +0x14a
gopkg.in/check%2ev1.TestingT()
/Users/orawlings/go/src/gopkg.in/check.v1/run.go:72 +0x6f9
gopkg.in/src-d/go-git.v4/plumbing/transport/file.Test()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/file/client_test.go:15 +0x38
testing.tRunner()
/usr/local/go/src/testing/testing.go:657 +0x107
Goroutine 11 (finished) created at:
gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common.(*client).listenErrors()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common/common.go:148 +0x8c
gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common.(*client).newSession()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common/common.go:131 +0x242
gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common.(*client).NewReceivePackSession()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common/common.go:87 +0x85
gopkg.in/src-d/go-git.v4/plumbing/transport/test.(*ReceivePackSuite).TestAdvertisedReferencesEmpty()
/Users/orawlings/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/test/receive_pack.go:31 +0xb1
gopkg.in/src-d/go-git.v4/plumbing/transport/file.(*ReceivePackSuite).TestAdvertisedReferencesEmpty()
<autogenerated>:2 +0x5e
runtime.call32()
/usr/local/go/src/runtime/asm_amd64.s:514 +0x47
reflect.Value.Call()
/usr/local/go/src/reflect/value.go:302 +0xc0
gopkg.in/check%2ev1.(*suiteRunner).forkTest.func1()
/Users/orawlings/go/src/gopkg.in/check.v1/check.go:772 +0xa71
gopkg.in/check%2ev1.(*suiteRunner).forkCall.func1()
/Users/orawlings/go/src/gopkg.in/check.v1/check.go:666 +0x89
==================
... more races omitted ...
It appears there is at least one race in particular that we detect many times related to the goroutine spawned in gopkg.in/src-d/go-git.v4/plumbing/transport/internal/common.(*client).listenErrors()
func (c *client) listenErrors(r io.Reader) chan string {
if r == nil {
return nil
}
errLines := make(chan string, errLinesBuffer)
go func() {
s := bufio.NewScanner(r)
for s.Scan() {
line := string(s.Bytes())
errLines <- line
}
}()
return errLines
}
It appears that by scanning the stderr spawned for the git-upload-pack or git-receive-pack processes in a separate goroutine, we create races when the cmd.Wait() is eventually invoked on the original goroutine.
It appears that things are implemented this way to allow us to timeout while waiting for a "repository not found error". I suspect this timeout behavior is important, but I'm not quite sure of an easy way to address this while avoiding a data race. Maybe we want to put some mutexs around the critical code blocks here which interact with the os/exec command?
Also, maybe the continuous integration for this project should also run tests with race detection enabled? Maybe in addition to the existing builds? Thoughts?