go cmd 使用小坑一記

先說下使用情境，某服務在每台伺服器上啟動 agent, 使用者會在指定機器上執行任務，並將結果返回到網頁上。執行任務由使用者自訂指令碼，一般也都是 shell 或是python，會不斷的產生子進程，孫進程，直到執行完畢或是逾時被 kill

最近發現經常有任務，一直處於運行中，但實際上己經逾時被 kill，並未將輸出寫到系統，看不到任務的執行情況。登入機器，發現執行指令碼進程己經殺掉，但是有子指令碼卡在某個 http 調用。我司的網濫到無法直視，內網還有不通的 case，並且還有很多公網機器，再看下這個指令碼，python requests 預設沒有設定逾時...

總結一下現象：agent 用 go cmd 啟動子進程，子進程還會啟動孫進程，孫進程因某種原因阻塞。此時，如果子進程因逾時被 agent kill 殺掉, agent 卻仍然處於 wait 狀態。

複現 case

agent 使用 exec.CommandContext 啟動任務，設定 ctx 逾時 30s，並將結果寫到 bytes.Buffer, 最後列印。簡化例子如下：

func main() {    ctx, cancelFn := context.WithTimeout(context.Background(), time.Second*30)    defer cancelFn()    cmd := exec.CommandContext(ctx, "/root/dongzerun/sleep.sh")    var b bytes.Buffer    cmd.Stdout = &b //劇透，坑在這裡    cmd.Stderr = &b    cmd.Start()    cmd.Wait()    fmt.Println("recive: ", b.String())}

這個是 sleep.sh，類比子進程

#!/bin/shecho "in sleep"sh /root/dongzerun/sleep1.sh

這是 sleep1.sh 類比孫進程，sleep 1000 阻塞在這裡

#!/bin/shsleep 1000

現象

啟動測試 go 程式，查看 ps axjf | less

ppid  pid   pgid 2468 32690 32690 32690 ?           -1 Ss       0   0:00  \_ sshd: root@pts/632690 32818 32818 32818 pts/6    28746 Ss       0   0:00  |   \_ -bash32818 28531 28531 32818 pts/6    28746 S        0   0:00  |       \_ strace ./wait28531 28543 28531 32818 pts/6    28746 Sl       0   0:00  |       |   \_ ./wait28543 28559 28531 32818 pts/6    28746 S        0   0:00  |       |       \_ /bin/sh /root/dongzerun/sleep.sh28559 28560 28531 32818 pts/6    28746 S        0   0:00  |       |           \_ sh /root/dongzerun/sleep1.sh28560 28563 28531 32818 pts/6    28746 S        0   0:00  |       |               \_ sleep 1000

等過了 30s，通過 ps axjf | less 查看

 2468 32690 32690 32690 ?           -1 Ss       0   0:00  \_ sshd: root@pts/632690 32818 32818 32818 pts/6    36192 Ss       0   0:00  |   \_ -bash32818 28531 28531 32818 pts/6    36192 S        0   0:00  |       \_ strace ./wait28531 28543 28531 32818 pts/6    36192 Sl       0   0:00  |       |   \_ ./wait

    1 28560 28531 32818 pts/6    36192 S        0   0:00 sh /root/dongzerun/sleep1.sh28560 28563 28531 32818 pts/6    36192 S        0   0:00  \_ sleep 1000

通過上面的 case，可以看到 sleep1.sh 成了孤兒進程，被 init 1 認領，但是 28543 wait 並沒有退出，那他在做什嗎？？？

分析

使用 strace 查看 wait 程式

epoll_ctl(4, EPOLL_CTL_DEL, 6, {0, {u32=0, u64=0}}) = 0close(6)                                = 0futex(0xc420054938, FUTEX_WAKE, 1)      = 1waitid(P_PID, 28559, {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=28559, si_status=SIGKILL, si_utime=0, si_stime=0}, WEXITED|WNOWAIT, NULL) = 0卡在這裡約 30s--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=28559, si_status=SIGKILL, si_utime=0, si_stime=0} ---rt_sigreturn()                          = 0futex(0x9a0378, FUTEX_WAKE, 1)          = 1futex(0x9a02b0, FUTEX_WAKE, 1)          = 1wait4(28559, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGKILL}], 0, {ru_utime={0, 0}, ru_stime={0, 0}, ...}) = 28559futex(0x9a0b78, FUTEX_WAIT, 0, NULL

通過 go 源碼可以看到 go exec wait 時，會先執行 waitid，阻塞在這裡，然後再來一次 wait4 等待最終退出結果。不太明白為什麼兩次 wait... 但是最後卡在了 futex 這裡，看著像在等待什麼資源？？？

開啟 golang pprof, 再次運行程式，並 pprof

    go func() {        err := http.ListenAndServe(":6060", nil)        if err != nil {            fmt.Printf("failed to start pprof monitor:%s", err)        }    }()

curl http://127.0.0.1:6060/debug/pprof/goroutine?debug=2goroutine 1 [chan receive]:os/exec.(*Cmd).Wait(0xc42017a000, 0x7c3d40, 0x0)    /usr/local/go/src/os/exec/exec.go:454 +0x135main.main()    /root/dongzerun/wait.go:32 +0x167

程式沒有退出，並不可思義的卡在了 exec.go:454 行代碼，查看 go1.9.6 原碼：

// Wait releases any resources associated with the Cmd.func (c *Cmd) Wait() error {      ......    state, err := c.Process.Wait()    if c.waitDone != nil {        close(c.waitDone)    }    c.ProcessState = state    var copyError error    for range c.goroutine {        //卡在了這裡        if err := <-c.errch; err != nil && copyError == nil {            copyError = err        }    }    c.closeDescriptors(c.closeAfterWait)    ......    return copyError}

通過原始碼分析，程式 wait 卡在了 <-c.errch 擷取 chan 資料。那麼 errch 是如何產生的呢？
查看 cmd.Start 源碼，go 將 cmd.Stdin, cmd.Stdout, cmd.Stderr 組織成 *os.File，並依次寫到數組 childFiles 中，這個數組索引就對應子進程的0，1，2 文描術符，即子進程的標準輸入，輸出，錯誤。

    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)    }    c.childFiles = append(c.childFiles, c.ExtraFiles...)    var err error    c.Process, err = os.StartProcess(c.Path, c.argv(), &os.ProcAttr{        Dir:   c.Dir,        Files: c.childFiles,        Env:   dedupEnv(c.envv()),        Sys:   c.SysProcAttr,    })

在執行 setupFd 時，會有一個關鍵的操作，開啟 pipe 管道，封裝一個匿名 func，功能就是將子進程的輸出結果寫到 pipe 或是將 pipe 資料寫到子進程標準輸入，最後關閉 pipe. 這個匿名函數最終在 Start 時執行

func (c *Cmd) stdin() (f *os.File, err error) {    if c.Stdin == nil {        f, err = os.Open(os.DevNull)        if err != nil {            return        }        c.closeAfterStart = append(c.closeAfterStart, f)        return    }    if f, ok := c.Stdin.(*os.File); ok {        return f, nil    }    pr, pw, err := os.Pipe()    if err != nil {        return    }    c.closeAfterStart = append(c.closeAfterStart, pr)    c.closeAfterWait = append(c.closeAfterWait, pw)    c.goroutine = append(c.goroutine, func() error {        _, err := io.Copy(pw, c.Stdin)        if skip := skipStdinCopyError; skip != nil && skip(err) {            err = nil        }        if err1 := pw.Close(); err == nil {            err = err1        }        return err    })    return pr, nil}

重新運行測試 case，並用 lsof 查看進程開啟了哪些資源

root@nb1963:~/dongzerun# ps aux |grep waitroot      4531  0.0  0.0 122180  6520 pts/6    Sl   17:24   0:00 ./waitroot      4726  0.0  0.0  10484  2144 pts/6    S+   17:24   0:00 grep --color=auto waitroot@nb1963:~/dongzerun#root@nb1963:~/dongzerun# ps aux |grep sleeproot      4543  0.0  0.0   4456   688 pts/6    S    17:24   0:00 /bin/sh /root/dongzerun/sleep.shroot      4548  0.0  0.0   4456   760 pts/6    S    17:24   0:00 sh /root/dongzerun/sleep1.shroot      4550  0.0  0.0   5928   748 pts/6    S    17:24   0:00 sleep 1000root      4784  0.0  0.0  10480  2188 pts/6    S+   17:24   0:00 grep --color=auto sleeproot@nb1963:~/dongzerun#root@nb1963:~/dongzerun# lsof -p 4531COMMAND  PID USER   FD   TYPE     DEVICE SIZE/OFF       NODE NAMEwait    4531 root    0w   CHR        1,3      0t0       1029 /dev/nullwait    4531 root    1w   REG        8,1    94371    4991345 /root/dongzerun/nohup.outwait    4531 root    2w   REG        8,1    94371    4991345 /root/dongzerun/nohup.outwait    4531 root    3u  IPv6 2005568215      0t0        TCP *:6060 (LISTEN)wait    4531 root    4u  0000       0,10        0       9076 anon_inodewait    4531 root    5r  FIFO        0,9      0t0 2005473170 piperoot@nb1963:~/dongzerun# lsof -p 4543COMMAND   PID USER   FD   TYPE DEVICE SIZE/OFF       NODE NAMEsleep.sh 4543 root    0r   CHR    1,3      0t0       1029 /dev/nullsleep.sh 4543 root    1w  FIFO    0,9      0t0 2005473170 pipesleep.sh 4543 root    2w  FIFO    0,9      0t0 2005473170 pipesleep.sh 4543 root   10r   REG    8,1       55    4993949 /root/dongzerun/sleep.shroot@nb1963:~/dongzerun# lsof -p 4550COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF       NODE NAMEsleep   4550 root  mem    REG    8,1  1607664    9179617 /usr/lib/locale/locale-archivesleep   4550 root    0r   CHR    1,3      0t0       1029 /dev/nullsleep   4550 root    1w  FIFO    0,9      0t0 2005473170 pipesleep   4550 root    2w  FIFO    0,9      0t0 2005473170 pipe

原因總結

孫進程，啟動後，預設會繼承父進程開啟的檔案描述符，即 node 2005473170 的 pipe，那麼當父進程被 kill -9 後會清理資源，關閉開啟的檔案，但是 close 只是引用計數減 1。實際上 孫進程 仍然開啟著 pipe。回頭看 agent 代碼

    c.goroutine = append(c.goroutine, func() error {        _, err := io.Copy(pw, c.Stdin)        if skip := skipStdinCopyError; skip != nil && skip(err) {            err = nil        }        if err1 := pw.Close(); err == nil {            err = err1        }        return err    })

那麼當子進程執行結束後，go cmd 執行這個匿名函數的 io.Copy 來讀取子進程輸出資料，永遠沒有資料可讀，也沒有逾時，阻塞在 copy 這裡。

解決方案

原因找到了，解決方案也就有了。

1. 子進程啟動孫進程時，增加 CloseOnEec 標記，但不現實，還要看孫進程的輸出日誌
2. io.Copy 改寫，增加逾時調用，理論上可行，但是要改源
3. 逾時 kill 時，不單殺子進程，而是殺掉進程組

最終採用方案 3，簡化代碼如下，主要改動點有兩處：

1. SysProcAttr 配置 Setpgid，讓子進程與孫進程，擁有獨立的進程組id，即子進程的 pid
2. syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL) 殺進程時指定進程組

func Run(instance string, env map[string]string) bool {    var (        cmd         *exec.Cmd        proc        *Process        sysProcAttr *syscall.SysProcAttr    )    t := time.Now()    sysProcAttr = &syscall.SysProcAttr{        Setpgid: true, // 使子進程擁有自己的 pgid，等同於子進程的 pid        Credential: &syscall.Credential{            Uid: uint32(uid),            Gid: uint32(gid),        },    }    // 逾時控制    ctx, cancel := context.WithTimeout(context.Background(), time.Duration(j.Timeout)*time.Second)    defer cancel()    if j.ShellMode {        cmd = exec.Command("/bin/bash", "-c", j.Command)    } else {        cmd = exec.Command(j.cmd[0], j.cmd[1:]...)    }    cmd.SysProcAttr = sysProcAttr    var b bytes.Buffer    cmd.Stdout = &b    cmd.Stderr = &b    if err := cmd.Start(); err != nil {        j.Fail(t, instance, fmt.Sprintf("%s\n%s", b.String(), err.Error()), env)        return false    }    waitChan := make(chan struct{}, 1)    defer close(waitChan)    // 逾時殺掉進程組 或正常退出    go func() {        select {        case <-ctx.Done():            log.Warnf("timeout kill job %s-%s %s ppid:%d", j.Group, j.ID, j.Name, cmd.Process.Pid)            syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL)        case <-waitChan:        }    }()    if err := cmd.Wait(); err != nil {        j.Fail(t, instance, fmt.Sprintf("%s\n%s", b.String(), err.Error()), env)        return false    }    return true}