Go exec 包执行命令超时失效问题分析及解决方案

来自：指月 https://www.lixueduan.com

原文：https://www.lixueduan.com/post/go/exex-cmd-timeout/

本文主要从源码层面分析了 Go exec 包执行命令超时失效问题，找出具体原因并给出相关解决方案。

现象

使用 os/exec 执行 shell 脚本并设置超时时间，然后到超时时间之后程序并未超时退出，反而一直阻塞。

具体代码如下：

func main() {ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)defer cancel()// 二者都可以触发cmd := exec.CommandContext(ctx, "bash","/root/sleep.sh")// cmd := exec.CommandContext(ctx, "bash","-c","echo hello && sleep 1200")out, err := cmd.CombinedOutput()fmt.Printf("ctx.Err : [%v]\n", ctx.Err())fmt.Printf("error   : [%v]\n", err)fmt.Printf("out     : [%s]\n", string(out))
}

/root/sleep.sh：

#!/bin/bash
sleep 1200

运行上述代码

[root@kc ~]# go run main.go

会创建一个 bash 进程，bash 进程又会创建一个 sleep 子进程：

[root@kc ~]# ps -ef|grep sleep
root     15485 15479  0 11:38 pts/1    00:00:00 bash /root/sleep.sh
root     15486 15485  0 11:38 pts/1    00:00:00 sleep 1200
root     15491 15239  0 11:38 pts/2    00:00:00 grep --color=auto sleep

等 context 超时之后，bash 进程被 kill 掉，进而 sleep 进程被 1 号进程托管，并且此时程序并未退出。

[root@kc ~]# ps -ef|grep sleep
root     15486     1  0 11:38 pts/1    00:00:00 sleep 1200
root     15499 15239  0 11:38 pts/2    00:00:00 grep --color=auto sleep

手动 kill 掉 sleep 进程

kill 15486

此时程序退出

[root@kc ~]# go run main.go
ctx.Err : [context deadline exceeded]
error   : [signal: killed]
out     : []

原因分析

执行流程

exec.cmd 执行流程如下：

图源： PureLife

首先 go 中调用 fork 创建子进程，在子进程中执行具体命令，并通过管道和子进程进行连接，子进程将结果输出到管道，go 从管道中读取。

go 与 /bin/bash 之间通过两个管道进行连接，分别用于捕获 stderr 和 stdout 输出，/bin/bash 程序退出后，管道写入端被关闭，从而 go 可以感知到子进程退出，从而立刻返回。

猜想：根据现象可知，创建了两个进程，超时后 bash 进程退出，但是 sleep 进程还在，如果 sleep 进程继续占有管道，那么就可能导致阻塞。后续手动 kill 掉 sleep 进程后程序退出也能印证这一点。

相关源码

带着这个猜想去查看一下源码，相关源码均在 os/exec/exec.go 中。

CombinedOutput

func (c *Cmd) CombinedOutput() ([]byte, error) {if c.Stdout != nil {return nil, errors.New("exec: Stdout already set")}if c.Stderr != nil {return nil, errors.New("exec: Stderr already set")}var b bytes.Bufferc.Stdout = &bc.Stderr = &berr := c.Run()return b.Bytes(), err
}func (c *Cmd) Run() error {if err := c.Start(); err != nil {return err}return c.Wait()
}

CombinedOutput 逻辑很简单，和方法名一样，将 Stdout 和 Stderr 设置为同一个 writer。

Run 方法中则调用了 Start 和 Wait 方法：

Start 方法用于启动子进程，启动后立即返回
Wait 方法则阻塞，等待子进程结束并回收资源。

阻塞大概率出现在 Wait 方法中，因此先看 Wait 方法。

Wait

Wait 方法具体如下

func (c *Cmd) Wait() error {if c.Process == nil {return errors.New("exec: not started")}if c.finished {return errors.New("exec: Wait was already called")}c.finished = truestate, err := c.Process.Wait()if c.waitDone != nil {close(c.waitDone)}c.ProcessState = statevar copyError errorfor range c.goroutine {if err := <-c.errch; err != nil && copyError == nil {copyError = err}}c.closeDescriptors(c.closeAfterWait)if err != nil {return err} else if !state.Success() {return &ExitError{ProcessState: state}}return copyError
}

根据 debug 得知阻塞点就是 err := <-c.errch 这句。从 errch 中读取错误信息并最终返回给调用者。而 <-ch 命令阻塞的原因只有发送方未准备好，那么 errch 对应的发送方是谁呢，就在 Start 方法中：

Start

func (c *Cmd) Start() error {// ...if len(c.goroutine) > 0 {c.errch = make(chan error, len(c.goroutine))for _, fn := range c.goroutine {go func(fn func() error) {c.errch <- fn()}(fn)}}if c.ctx != nil {c.waitDone = make(chan struct{})go func() {select {case <-c.ctx.Done():c.Process.Kill()case <-c.waitDone:}}()}//...

第一部分，通过启动后台 goroutine 执行 c.goroutine 中的方法并将错误写入 c.errch，可以猜测一下应该是这里的产生了阻塞，需要继续追踪 c.goroutine 是哪儿来的。

第二部分则是开启了另一个 goroutine，用来监听 context，在超时之后会 kill 掉子进程。

这也符合现象中看到的，超时后 bash 进程被 kill 掉了。

接下来继续追踪 c.goroutine 是哪儿赋值的,同样是在 Start 方法中，前面提到了 go 通过管道来连接子进程以收集结果，具体逻辑就在这里：

 func (c *Cmd) Start() error {// ...type F func(*Cmd) (*os.File, error)for _, setupFd := range []F{(*Cmd).stdin, (*Cmd).stdout, (*Cmd).stderr} {fd, err := setupFd(c)if err != nil {c.closeDescriptors(c.closeAfterStart)c.closeDescriptors(c.closeAfterWait)return err}c.childFiles = append(c.childFiles, fd)}}

通过 (*Cmd).stdin, (*Cmd).stdout, (*Cmd).stderr 三个方法来分别处理 stdin、stdout、stderr。

这里先忽略掉 stdin，只看 stdout、stderr

具体 stdout、stderr 方法如下：

func (c *Cmd) stdout() (f *os.File, err error) {return c.writerDescriptor(c.Stdout)
}func (c *Cmd) stderr() (f *os.File, err error) {// 如果 stderr 和 stdout 一样的就不重复处理了if c.Stderr != nil && interfaceEqual(c.Stderr, c.Stdout) {return c.childFiles[1], nil}return c.writerDescriptor(c.Stderr)
}

二者都是调用的 writerDescriptor，不过 stderr 中简单判断了一下避免重复处理。

writerDescriptor 方法如下：

func (c *Cmd) writerDescriptor(w io.Writer) (f *os.File, err error) {// case1if w == nil {f, err = os.OpenFile(os.DevNull, os.O_WRONLY, 0)if err != nil {return}c.closeAfterStart = append(c.closeAfterStart, f)return}// case2if f, ok := w.(*os.File); ok {return f, nil}// case3pr, pw, err := os.Pipe()if err != nil {return}c.closeAfterStart = append(c.closeAfterStart, pw)c.closeAfterWait = append(c.closeAfterWait, pr)c.goroutine = append(c.goroutine, func() error {_, err := io.Copy(w, pr)pr.Close() // in case io.Copy stopped due to write errorreturn err})return pw, nil
}

有三个分支逻辑：

case1：如果没有指定 stderr 或者 stdout 就直接写入 os.DevNull
case2：如果指定的 stderr 或者 stdout 是 *os.File 类型也直接返回，后续直接写入该文件
case3：如果前两种情况都不是就进行最后一种情况，也即是最终的阻塞点。创建管道，子进程写入管道写端点，go 中启动一个 goroutine 从管道读端点读取并写入到指定的 stderr 或者 stdout 中。

这里只分析 case3，首先 io.Copy 方法会一直阻塞到 reader 被关闭才会返回，这也就是为什么这里会产生阻塞。

正常情况下 context 超时后，子进程会被 kill 掉，那么管道的写端点自然会被关闭， io.Copy 则在 copy 完成后正常返回，给 c.errch 中发送一个 nil，Wait 方法则从 c.errch 中读取到 error 就返回了，一切正常