os/exec: example test using Command.Stdout causes data race

[stapelberg]

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

go version go1.7.3 linux/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/usr/local/google/home/stapelberg/gocode"
GORACE=""
GOROOT="/usr/lib/google-golang"
GOTOOLDIR="/usr/lib/google-golang/pkg/tool/linux_amd64"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build817336530=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"

What did you do?

The following example test triggers a data race:

package example_test

import (
    "os"
    "os/exec"
)

func ExampleFoo() {
    fmt.Println("foo")

    cmd := exec.Command("/bin/sh", "-c", "sleep 999d")
    cmd.Stdout = os.Stdout
    go cmd.Run()

    // OUTPUT:
    // foo
}

In case it matters, I’m running go test -race -v examplerace/..., the above example is stored in gocode/src/examplerace/example_test.go

What did you expect to see?

I expected the test to pass.

What did you see instead?

The test triggers a data race:

$ go test -race -v examplerace/...
=== RUN   ExampleFoo
--- PASS: ExampleFoo (0.00s)
PASS
==================
WARNING: DATA RACE
Read at 0x00c42009c0c0 by goroutine 8:
  os.startProcess()
      /usr/lib/google-golang/src/os/exec_posix.go:45 +0x65a
  os.StartProcess()
      /usr/lib/google-golang/src/os/doc.go:28 +0x7a
  os/exec.(*Cmd).Start()
      /usr/lib/google-golang/src/os/exec/exec.go:358 +0x6a0
  os/exec.(*Cmd).Run()
      /usr/lib/google-golang/src/os/exec/exec.go:276 +0x3c

Previous write at 0x00c42009c0c0 by main goroutine:
  os.(*file).close()
      /usr/lib/google-golang/src/os/file_unix.go:149 +0x124
  os.(*File).Close()
      /usr/lib/google-golang/src/os/file_unix.go:138 +0x55
  testing.runExample.func2()
      /usr/lib/google-golang/src/testing/example.go:85 +0xdf
  testing.runExample()
      /usr/lib/google-golang/src/testing/example.go:115 +0x1fc
  testing.RunExamples()
      /usr/lib/google-golang/src/testing/example.go:38 +0x1b1
  testing.(*M).Run()
      /usr/lib/google-golang/src/testing/testing.go:746 +0x189
  main.main()
      examplerace/_test/_testmain.go:54 +0x1b8

Goroutine 8 (running) created at:
  examplerace_test.ExampleFoo()
      /usr/local/google/home/stapelberg/gocode/src/examplerace/example_test.go:14 +0x1b9
  testing.runExample()
      /usr/lib/google-golang/src/testing/example.go:114 +0x1fb
  testing.RunExamples()
      /usr/lib/google-golang/src/testing/example.go:38 +0x1b1
  testing.(*M).Run()
      /usr/lib/google-golang/src/testing/testing.go:746 +0x189
  main.main()
      examplerace/_test/_testmain.go:54 +0x1b8
==================
Found 1 data race(s)
exit status 66
FAIL	examplerace	1.029s

[JayNakrani]

I'll give it a shot if this issue is not already taken.

[quentinmit]

The Run call is racing with the shutdown of the test. I'm not sure how much we actually care about this data race - in practice you are not going to have your program exit as you're in the midst of attempting to start a child process.

@Dhananjay92 You're welcome to investigate trying to fix this.

[JayNakrani]

I don't see any locking/synchronization in exec.go or file_unix.go. Perhaps, it is by design that users should prevent such data races by avoiding (*File).Close() while cmd.Run() is in progress.

[stapelberg]

The Run call is racing with the shutdown of the test. I'm not sure how much we actually care about this data race - in practice you are not going to have your program exit as you're in the midst of attempting to start a child process.

FWIW, the same race detector report is printed when a time.Sleep(1 * time.Second) is added like so:

package example_test

import (
    "fmt"
    "os"
    "os/exec"
    "time"
)

func ExampleFoo() {
    fmt.Println("foo")

    cmd := exec.Command("/bin/sh", "-c", "sleep 999d")
    cmd.Stdout = os.Stdout
    go cmd.Run()

    time.Sleep(1 * time.Second)

    // OUTPUT:
    // foo
}

I don’t 100% understand why the race detector is flagging this, but in the real-life situtation in which I encountered this issue, I don’t think a child process was being started while the test was exiting. Rather, that child process was already running.

[ianlancetaylor]

The race detector doesn't care about sleeps. It cares about reads and writes of the same memory location with no happens-before relationship (see https://golang.org/ref/mem).

This is a race between the close of os.Stdout in runExample, which sets os.Stdout.fd = -1, and the read of os.Stdout.fd (because os.Stdout is in sysattr.Files) in startProcess.

As far as I can tell this is a real race. The code in package example is going to close stdout. At the same time, the goroutine is getting stdout's file descriptor to pass it to the child process. There is no synchronization between those two steps, and even if something were added it would still be a race whether the child process got an open file descriptor or not. So, closing.

[stapelberg]

Thanks for looking into this.

I don’t entirely understand what closing this issue implies. Are you saying that one must not use os.Stdout in example code?

[ianlancetaylor]

It's fine to use os.Stdout in example code. What is not fine is using os/exec to start a process running in a separate goroutine, where the stdout of that process is set to os.Stdout, and to then use os.Stdout in any way before waiting for the process to complete, including putting using an example with a // OUTPUT comment.

Basically, don't write

cmd.Stdout = os.Stdout
go cmd.Run()

in an example with a // OUTPUT comment. I don't actually see how that is a meaningful thing to do anyhow. If you aren't waiting for the process to complete, how can you know what the output is? If you don't care what the output is, why are you setting cmd.Stdout?

[stapelberg]

Thanks for clarifying.

In the scenario where this issue was filed from, a library external to my code was creating a subprocess with cmd.Stdout = os.Stdout.

IIUC, the data race happens if and only if processes are not terminated correctly. I’ll take this up with the authors of said library, possibly there’s a bug related to context cancellation here.