Exec package: Run() and Output() behaviours for process launched in background

[celine (Céline)]

I’m using https://golang.org/pkg/os/exec/
If I have a simple program running something like this:

cmd := exec.Command("/bin/sh", "-c", "sleep 10 &")
err := cmd.Run()

In this case, the command is launched and the program exits.
On the other hand, if I’m using Output() or CombinedOutput() instead of Run():

cmd := exec.Command("/bin/sh", "-c", "sleep 10 &")
out, err := cmd.Output()

Then the program waits for 10 seconds before exiting. Basically it is running until the command sleep 10 & finishes.

I’m just wondering if that’s normal behaviour… I didn’t expect Output() to hang like this. Thanks!

[dfc (Dave Cheney)]

Could you please provide a runnable code sample that demonstrates the problem.

[celine (Céline)]

Runnable code sample:

package main

import (
    "log"
    "os/exec"
    "strings"
)

func main() {
    cmd := exec.Command("/bin/sh", "-c", "sleep 10 &")
    //err := cmd.Run()
    out, err := cmd.CombinedOutput()
    if err != nil {
       log.Printf("Error running notify command: %s, %s\n", "sleep 10 &", err)
    }
    for _, line := range strings.Split(string(out), "\n") {
      if line != "" {
          log.Printf("[%s]: %s", "sleep 10 &", line)
      }
    }
}

[dfc (Dave Cheney)]

Thank you for posting your sample code. What you are seeing is normal behaviour, but it’s a little unusual. What happens is your program forks /bin/sh, which forks sleep. Now you are waiting on CombinedOutput, which means the stdout and stderr from the command you executed, /bin/sh, which has forked sleep, then returned.

lucky(~/src/t) % ./t &
[1] 29285
lucky(~/src/t) % ps -lf
F S UID        PID  PPID  C PRI  NI ADDR SZ WCHAN  STIME TTY          TIME CMD
0 S dfc      28919 28918  0  80   0 -  6125 wait   22:08 pts/26   00:00:00 -bash
0 S dfc      29285 28919  0  80   0 -   809 futex_ 22:16 pts/26   00:00:00 ./t
0 S dfc      29290     1  0  80   0 -  1798 hrtime 22:16 pts/26   00:00:00 sleep 1000
4 R dfc      29291 28919  0  80   0 -  4611 -      22:16 pts/26   00:00:00 ps -lf

Here t is your program (i just called it that), and modified it to run sleep longer so I could get the rest of these details. So, you see t, your program is running, and so is sleep. Let’s look at stdout and stderr are connected to.

You’ll also note that the PPID of sleep is 1, as it’s been “daemonised” (sorta).

lucky(~/src/t) % ls -al /proc/{29285,29290}/fd
/proc/29285/fd:
total 0
dr-x------ 2 dfc dfc  0 Mar 10 22:16 .
dr-xr-xr-x 9 dfc dfc  0 Mar 10 22:16 ..
lrwx------ 1 dfc dfc 64 Mar 10 22:17 0 -> /dev/pts/26
lrwx------ 1 dfc dfc 64 Mar 10 22:17 1 -> /dev/pts/26
lrwx------ 1 dfc dfc 64 Mar 10 22:16 2 -> /dev/pts/26
lr-x------ 1 dfc dfc 64 Mar 10 22:17 4 -> pipe:[4788359]

This is t, note file descriptor four is connected to a pipe, this is the connection to the command you executed. There is only one pipe because we gave the same file descriptor to the child for both stdout and stderr, this is what CombinedOutput does.

So, t is connected to the child process and is waiting for fd 4 to be closed. Let’s look at the other end

/proc/29290/fd:
total 0
dr-x------ 2 dfc dfc  0 Mar 10 22:16 .
dr-xr-xr-x 9 dfc dfc  0 Mar 10 22:16 ..
lr-x------ 1 dfc dfc 64 Mar 10 22:17 0 -> /dev/null
l-wx------ 1 dfc dfc 64 Mar 10 22:17 1 -> pipe:[4788359]
l-wx------ 1 dfc dfc 64 Mar 10 22:16 2 -> pipe:[4788359]

This is the child process, sleep, stdin is connected to /dev/null, which makes sense, you didn’t supply anything for that (check the docs on exec.Cmd for details), and both 1 and 2, stdout and stderr are connected to the same pipe.

Now, sleep doesn’t say anything, so nothing will be sent back to t on the pipe, when sleep does finally exit, the operating system will close all the file descriptors associated with this process. So, the write side of the pipe will be closed, which will send EOF to the read side, which will unblock CombinedOutput and t will exit.

So, why does this behave differently when you just call cmd.Run ? Because your program forks /bin/sh, which then forks sleep, and returns. Your program is not waiting to read the output of the program, it’s just looking for the exit status of /bin/sh, which returns immediately.

Here are some exercises:

1. Modify your code sample to use cmd.StdoutPipe
2. Observe the changes in behaviour between waiting on cmd.StdoutPipe().Read() to return io.EOF (ioutils.ReadAll will be useful here) and another goroutine waiting on cmd.Run(). Be sure not to let your main goroutine exit til the other one reading from the pipe has exited.

[celine (Céline)]

thank you for this really detailed answer!