Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
stapelberg opened this issue Nov 3, 2016 · 8 comments
Closed

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

stapelberg opened this issue Nov 3, 2016 · 8 comments
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@stapelberg
Copy link
Contributor

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
@josharian josharian changed the title Example test using exec.Command.Stdout causes data race os/exec: example test using Command.Stdout causes data race Nov 3, 2016
@JayNakrani
Copy link
Contributor

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

@quentinmit
Copy link
Contributor

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.

@quentinmit quentinmit added the NeedsFix The path to resolution is known, but the work has not been done. label Nov 4, 2016
@quentinmit quentinmit added this to the Go1.8Maybe milestone Nov 4, 2016
@JayNakrani
Copy link
Contributor

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
Copy link
Contributor Author

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
Copy link
Member

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
Copy link
Contributor Author

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
Copy link
Member

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
Copy link
Contributor Author

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.

@golang golang locked and limited conversation to collaborators Nov 7, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

5 participants