Skip to content
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

io: Pipe reader loses last line if writer exits as soon as write is finished #33297

Closed
sunchao9 opened this issue Jul 26, 2019 · 13 comments
Closed
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@sunchao9
Copy link

sunchao9 commented Jul 26, 2019

I think this is a bug of io.Pipe, I want to use pipe files to write strings to the detached child process, but I find that the pipe reader always lost the last input line, here is the test case:

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

$ go version
go version go1.12.7 linux/amd64

Does this issue reproduce with the latest release?

yes, go1.12.7 is the latest release version

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

go env Output
$ go env
GOARCH="amd64"
GOBIN="/home/git/.local/gobin"
GOCACHE="/home/git/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/git/gopath"
GOPROXY=""
GORACE=""
GOROOT="/etc/alternatives/go"
GOTMPDIR=""
GOTOOLDIR="/etc/alternatives/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build257909325=/tmp/go-build -gno-record-gcc-switches"
$ uname -a
Linux SZX1000480217 3.10.0-693.el7.x86_64 #1 SMP Tue Aug 22 21:09:27 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

$ lsb_release -ir                                                                                                                                                                           0
Distributor ID: CentOS
Release:        7.6.1810

What did you do?

I have a writer.go and a reader.sh, the writer.go writes 100 lines to reader.sh which is started as a detached process. And I find that the reader.sh always lost the last line unless the writer.go sleep a while before exit.

// writer.go
package main
    
import (
    "fmt"
    "io"
    "os/exec"
)   
    
func main() {
    cmd := exec.Command("./reader.sh")
    
    pr, pw := io.Pipe()
    cmd.Stdin = pr
    
    err := cmd.Start()
    if err != nil {
        fmt.Print(err)
        return
    }
    
    n := 100
    for i := 1; i <= n; i++ {
        str := fmt.Sprintf("line %d\n", i)
        fmt.Print("writer: " + str)
        n, err := pw.Write([]byte(str))
        fmt.Printf("result = %d, %v\n", n, err)
    }
    pw.Close()
}
# reader.sh
while read line     
do                  
    echo "$line" >> ./reader.log
done

What did you expect to see?

I expect to see the reader.sh will read all the 100 lines from it's Stdin, because it's Stdin is a pipe reader, and the pipe writer received 100 lines from the parent process.

What did you see instead?

I run the writer.go to check if the reader.sh could print all the 100 lines, but the reader.sh lost the last line, and I tried lots of times, mostly it happens.

$ go run writer.go
writer: line 1
...
writer: line 98
writer: line 99
writer: line 100

and the reader.log 's content is like this:

writer: line 1
...
writer: line 98
writer: line 99

So, I think there is a BUG under some OS platform (I tried the MacOS, io.Pipe works find) , if the pipe writer exit as soon as possible, the pipe reader will lost the last line. Please check if it is true, thansk a lot.

@AlexRouSg
Copy link
Contributor

Try adding the following to the end of the program:

if err := cmd.Wait(); err != nil {
	fmt.Print(err)
}

@sunchao9
Copy link
Author

Try adding the following to the end of the program:

if err := cmd.Wait(); err != nil {
	fmt.Print(err)
}

If add cmd.Wait(), then no lines is lost. But if I want to create some detached sub processes by cmd.Start, this problem will happen.

And I also tries some other ways to avoid this:

  • call time.Sleep(time.Second) in writer.go before exit
  • call pw.Write([]byte{}) in writer.go before pw.Close

The 2 ways above will stop the pipe reader losting the last line, I don't know why.

@AlexRouSg
Copy link
Contributor

AlexRouSg commented Jul 26, 2019

This got nothing to do with io.Pipe, cmd.Start does not detach the process. So if the program terminates so does the child process. The program simply terminates before the child process writes the last line.

If your goal is to have a process monitor the output of another program, it is easier to just make it the parent process.

@sunchao9
Copy link
Author

sunchao9 commented Jul 26, 2019

cmd.Start does not detach the process. So if the program terminates so does the child process. The program simply terminates before the child process writes the last line.

Please try the test case, the parent program do not terminate a long running child process if it just os.Exit after cmd.Start.

// parent.go
package main
    
import (
    "fmt"
    "io"
    "os/exec"
)   
    
func main() {
    cmd := exec.Command("./child")
    
    pr, pw := io.Pipe()
    cmd.Stdin = pr
    
    err := cmd.Start()
    if err != nil {
        fmt.Print(err)
        return
    }
    
    n := 100
    for i := 1; i <= n; i++ {
        str := fmt.Sprintf("line %d\n", i)
        pw.Write([]byte(str))
    }
    pw.Close()
}
// child.go
package main

import (
        "bufio"
        "fmt"
        "os"
        "time"
)

func main() {
        f, _ := os.Create("./child.log")
        scanner := bufio.NewScanner(os.Stdin)
        for scanner.Scan() {
                time.Sleep(time.Second)
                fmt.Fprintln(f, scanner.Text())
        }

        f.Close()
}

I try this steps:

$ go build child.go
$ go run parent.go
$ tail -f child.log

and will see the child process is still running, and it's PPID is 1.

$ ps -o pid,ppid 65729
   PID   PPID
 65729      1

And my user case is like this:

  1. git push will create a post-receive process in the git server.
  2. post-receive will create some sub processes to do some long running works.
  3. I want to post-receive return quickly, so I let post-receive send the git ref changes to the child processs by pipes and detach them.
  4. Until now, I only find cmd.Start is useful to my user case, I don't know how to do it in other way...

@AlexRouSg
Copy link
Contributor

Please try the test case, the parent program do not terminate a long running child process if it just os.Exit after cmd.Start.

Ahh, sorry about that.

@AlexRouSg
Copy link
Contributor

So I found that if you use https://golang.org/pkg/os/exec/#Cmd.StdinPipe instead of creating your own pipes, the child process gets all 100 lines. Can you verify that works on your end too?

@sunchao9
Copy link
Author

So I found that if you use https://golang.org/pkg/os/exec/#Cmd.StdinPipe instead of creating your own pipes, the child process gets all 100 lines. Can you verify that works on your end too?

I don't know what is the different between the cmd.StdinPipe and the io.Pipe's Reader. But It works, thanks a lot.

@julieqiu julieqiu changed the title io.Pipe: the reader will lost last line if writer exit as soon as write finished io: Pipe reader loses last line if writer exits as soon as write is finished Jul 29, 2019
@julieqiu
Copy link
Member

@sunchao9 - has @AlexRouSg's suggestion addressed this issue?

@julieqiu julieqiu added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jul 29, 2019
@AlexRouSg
Copy link
Contributor

@julieqiu It's not entirely clear why there is or should there be a difference in behavior. I think at a minimum there should be a doc change if the difference is intentional.

@sunchao9
Copy link
Author

sunchao9 commented Jul 30, 2019

@sunchao9 - has @AlexRouSg's suggestion addressed this issue?

The suggestion could resolve my problem, thanks a lot. And I also agree with @AlexRouSg said, it would be nice if any one who want to use io.Pipe like me find a doc change explaining the difference between io.Pipe's reader and cmd.StdinPipe.

@jayconrod
Copy link
Contributor

@sunchao9 Could you confirm with an strace log that the last write system call is not being made? Also please edit the issue to follow the issue template. We don't know what version of Go this is, what platform you're on, or anything else.

I'd be surprised if there's a bug here, since this functionality is pretty close to the metal, and it's been stable for a long time. There's no error handling in this program, and I suspect at least one of the write calls is returning an error which is being ignored.

@sunchao9
Copy link
Author

sunchao9 commented Jul 31, 2019

@sunchao9 Could you confirm with an strace log that the last write system call is not being made? Also please edit the issue to follow the issue template. We don't know what version of Go this is, what platform you're on, or anything else.

I'd be surprised if there's a bug here, since this functionality is pretty close to the metal, and it's been stable for a long time. There's no error handling in this program, and I suspect at least one of the write calls is returning an error which is being ignored.

Sorry about that, I have updated the issue using the template.

And I add some trace log to check if the pw.Write returns error, like this:

    n := 100
    for i := 1; i <= n; i++ {
        str := fmt.Sprintf("line %d\n", i)
        fmt.Print("writer: " + str)
        n, err := pw.Write([]byte(str))
        fmt.Printf("result = %d, %v\n", n, err)
    }
    pw.Close()

and the returns just fine, there is no error happened, but the reader.sh always lost the 100th line.

I also tried this morning under MacOS, the reader.sh will print all the 100 lines, the io.Pipe wokrs fine.

@jayconrod
Copy link
Contributor

@sunchao9 Thanks for adding that info.

I looked into this a little closer, and I think I understand what's going wrong. If you look at the documentation for io.Pipe, it's an in-memory pipe which basically passes byte slices from a writer to a reader on a channel. It's not a pipe in the UNIX sense; that's os.Pipe, which returns *os.File.

The documentation for os/exec.Cmd explains the difference in behavior.

    // Stdin specifies the process's standard input.
    //
    // If Stdin is nil, the process reads from the null device (os.DevNull).
    //
    // If Stdin is an *os.File, the process's standard input is connected
    // directly to that file.
    //
    // Otherwise, during the execution of the command a separate
    // goroutine reads from Stdin and delivers that data to the command
    // over a pipe. In this case, Wait does not complete until the goroutine
    // stops copying, either because it has reached the end of Stdin
    // (EOF or a read error) or because writing to the pipe returned an error.

Because Stdin is not an *os.File, there is a goroutine that polls Stdin and then writes to an actual *os.File. The main goroutine races with this goroutine and exits before it has a chance to copy the last message. You must call os/exec.Cmd.Wait to ensure that goroutine is finished. Alternatively, use os.Pipe so you have direct access to the pipe. os/exec.Cmd.StdinPipe is a convenient way to do this.

Closing because this is working as designed. Process synchronization is always a little tricky, but there are some useful examples in the os/exec package.

@golang golang locked and limited conversation to collaborators Jul 30, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

5 participants