data races in plumbing/transport/internal/common

[orirawlings]

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?

[smola]

@orirawlings Thank you for taking the time to debug and report this. I'm committing a fix now.

Running tests with -race is a good idea. We'll think about a proper way of adding it.