os/exec: data race between StdoutPipe and Wait

[xxorde]

Problem

If you are reading from cmd.StdoutPipe() and call cmd.Wait() concurrent you get a race condition.
I needed some time to find this in my code, but once I knew what I was looking for I found the same problem in other codebases, blogposts, ect.

This is really similar to: #9307
I am quite sure I am not the first one to find this, but I could not find a matching issue, please close this if there is one.

Example

Here is a little example.
I did not constructed it, I actually found it in a blog post.

package main

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

func main() {
	cmdName := "echo"
	cmdArgs := []string{"hello", "world"}

	cmd := exec.Command(cmdName, cmdArgs...)
	cmdReader, err := cmd.StdoutPipe()
	if err != nil {
		fmt.Fprintln(os.Stderr, "Error creating StdoutPipe for Cmd", err)
		os.Exit(1)
	}

	scanner := bufio.NewScanner(cmdReader)
	go func() {
		for scanner.Scan() {
			fmt.Printf("%s\n", scanner.Text())
		}
	}()

	err = cmd.Start()
	if err != nil {
		fmt.Fprintln(os.Stderr, "Error starting Cmd", err)
		os.Exit(1)
	}

	err = cmd.Wait()
	if err != nil {
		fmt.Fprintln(os.Stderr, "Error waiting for Cmd", err)
		os.Exit(1)
	}
}

Here you can see it failing on different CI / Go versions: https://github.com/xxorde/race

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

• 1.6.x
• 1.7.x
• 1.8.x
• master

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

linux, amd64

[bradfitz]

/cc @ianlancetaylor

[davecheney]

Could you please paste the data race report here. Thanks.

…

On Fri, 24 Mar 2017, 10:00 Brad Fitzpatrick ***@***.***> wrote: /cc @ianlancetaylor <https://github.com/ianlancetaylor> — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#19685 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAcA89SewVYFUnq2mBkVG87xGqUjCKTks5rovlvgaJpZM4MneFa> .

[xxorde]

Yes of course, here it is.

% go run --race main.go                                                                                              :(
hello world
==================
WARNING: DATA RACE
Write at 0x00c42009a120 by main goroutine:
  os.(*file).close()
      /usr/local/go/src/os/file_unix.go:143 +0x124
  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:262 +0x67
  os/exec.(*Cmd).Wait()
      /usr/local/go/src/os/exec/exec.go:447 +0x2bd
  main.main()
      /home/sosna/src/go/src/github.com/xxorde/race/main.go:37 +0x257

Previous read at 0x00c42009a120 by goroutine 6:
  os.(*File).read()
      /usr/local/go/src/os/file_unix.go:228 +0x50
  os.(*File).Read()
      /usr/local/go/src/os/file.go:101 +0x6f
  bufio.(*Scanner).Scan()
      /usr/local/go/src/bufio/scan.go:208 +0x526
  main.main.func1()
      /home/sosna/src/go/src/github.com/xxorde/race/main.go:26 +0x47

Goroutine 6 (finished) created at:
  main.main()
      /home/sosna/src/go/src/github.com/xxorde/race/main.go:29 +0x21e
==================
Found 1 data race(s)
exit status 66

[myitcv]

@xxorde I think (although not an expert on this) @ianlancetaylor's comment is relevant here. i.e. you
need to be explicit that you've completed the read before waiting (should really be error handling in the scanner go routine):

package main

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

func main() {
	cmdName := "echo"
	cmdArgs := []string{"hello", "world"}

	cmd := exec.Command(cmdName, cmdArgs...)
	cmdReader, err := cmd.StdoutPipe()
	if err != nil {
		fmt.Fprintln(os.Stderr, "Error creating StdoutPipe for Cmd", err)
		os.Exit(1)
	}

	done := make(chan struct{})

	scanner := bufio.NewScanner(cmdReader)
	go func() {
		for scanner.Scan() {
			fmt.Printf("%s\n", scanner.Text())
		}

		done <- struct{}{}
	}()

	err = cmd.Start()
	if err != nil {
		fmt.Fprintln(os.Stderr, "Error starting Cmd", err)
		os.Exit(1)
	}

	<-done

	err = cmd.Wait()
	if err != nil {
		fmt.Fprintln(os.Stderr, "Error waiting for Cmd", err)
		os.Exit(1)
	}
}

[xxorde]

@myitcv thank you for this hint. I will most likely do exactly this in my own code.

The problem why I consider this still as a bug is that this behavior is not obvious to most users.
My whole point was that I wanted to wait for the read to finish and I used cmd.Wait() because it seemed to be THE intended way to do. A quick search on google confirmed that other people make the same assumption.

[myitcv]

@xxorde again I'll defer to wiser heads on this, but I'm not sure this is a bug in implementation or documentation:

https://godoc.org/os/exec#Cmd.Wait

Wait waits for the command to exit

If c.Stdin is not an *os.File, Wait also waits for the I/O loop copying from c.Stdin into the process's standard input to complete.

Critically it waits for the command to exit. When this happens:

Wait releases any resources associated with the Cmd.

which implies it will tidy up the stdout and stderr pipes (if set). The race occurs if you still happen to be reading from the pipe when this tidy up happens.

By making it explicit that you're finished reading (which will happen either when you choose (i.e. you don't want to read all the output) or when you reach EOF when the command exits) you can then call Wait.

[nhooyr]

I can't reproduce the race anymore with the race detector with the example program. Maybe #7970 fixed this?

[ianlancetaylor]

Thanks for looking at this. I agree: I think this is fixed in 1.9. The closely related problem #18874 is not fixed, but this one should be OK now.