go cmd 使用小坑一記

先說下使用場景，某服務在每臺服務器上啟動 agent, 用戶會在指定機器上執(zhí)行任務，并將結(jié)果返回到網(wǎng)頁上。執(zhí)行任務由用戶自定義腳本，一般也都是 shell 或是python，會不斷的產(chǎn)生子進程，孫進程，直到執(zhí)行完畢或是超時被 kill

最近發(fā)現(xiàn)經(jīng)常有任務，一直處于運行中，但實際上己經(jīng)超時被 kill，并未將輸出寫到系統(tǒng)，看不到任務的執(zhí)行情況。登錄機器，發(fā)現(xiàn)執(zhí)行腳本進程己經(jīng)殺掉，但是有子腳本卡在某個 http 調(diào)用。我司的網(wǎng)濫到無法直視，內(nèi)網(wǎng)還有不通的 case，并且還有很多公網(wǎng)機器，再看下這個腳本，python requests 默認沒有設置超時...

總結(jié)一下現(xiàn)象：agent 用 go cmd 啟動子進程，子進程還會啟動孫進程，孫進程因某種原因阻塞。此時，如果子進程因超時被 agent kill 殺掉, agent 卻仍然處于 wait 狀態(tài)。

復現(xiàn) case

agent 使用 exec.CommandContext 啟動任務，設置 ctx 超時 30s，并將結(jié)果寫到 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/sh
echo "in sleep"
sh /root/dongzerun/sleep1.sh

這是 sleep1.sh 模擬孫進程，sleep 1000 阻塞在這里

#!/bin/sh
sleep 1000

現(xiàn)象

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

ppid  pid   pgid
 2468 32690 32690 32690 ?           -1 Ss       0   0:00  \_ sshd: root@pts/6
32690 32818 32818 32818 pts/6    28746 Ss       0   0:00  |   \_ -bash
32818 28531 28531 32818 pts/6    28746 S        0   0:00  |       \_ strace ./wait
28531 28543 28531 32818 pts/6    28746 Sl       0   0:00  |       |   \_ ./wait
28543 28559 28531 32818 pts/6    28746 S        0   0:00  |       |       \_ /bin/sh /root/dongzerun/sleep.sh
28559 28560 28531 32818 pts/6    28746 S        0   0:00  |       |           \_ sh /root/dongzerun/sleep1.sh
28560 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/6
32690 32818 32818 32818 pts/6    36192 Ss       0   0:00  |   \_ -bash
32818 28531 28531 32818 pts/6    36192 S        0   0:00  |       \_ strace ./wait
28531 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.sh
28560 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}}) = 0
close(6)                                = 0
futex(0xc420054938, FUTEX_WAKE, 1)      = 1
waitid(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()                          = 0
futex(0x9a0378, FUTEX_WAKE, 1)          = 1
futex(0x9a02b0, FUTEX_WAKE, 1)          = 1
wait4(28559, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGKILL}], 0, {ru_utime={0, 0}, ru_stime={0, 0}, ...}) = 28559
futex(0x9a0b78, FUTEX_WAIT, 0, NULL

通過 go 源碼可以看到 go exec wait 時，會先執(zhí)行 waitid，阻塞在這里，然后再來一次 wait4 等待最終退出結(jié)果。不太明白為什么兩次 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=2

goroutine 1 [chan receive]:
os/exec.(*Cmd).Wait(0xc42017a000, 0x7c3d40, 0x0)
    /usr/local/go/src/os/exec/exec.go:454 +0x135
main.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 數(shù)據(jù)。那么 errch 是如何生成的呢？
查看 cmd.Start 源碼，go 將 cmd.Stdin, cmd.Stdout, cmd.Stderr 組織成 *os.File，并依次寫到數(shù)組 childFiles 中，這個數(shù)組索引就對應子進程的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,
    })

在執(zhí)行 setupFd 時，會有一個關鍵的操作，打開 pipe 管道，封裝一個匿名 func，功能就是將子進程的輸出結(jié)果寫到 pipe 或是將 pipe 數(shù)據(jù)寫到子進程標準輸入，最后關閉 pipe. 這個匿名函數(shù)最終在 Start 時執(zhí)行

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

原因總結(jié)

孫進程，啟動后，默認會繼承父進程打開的文件描述符，即 node 2005473170 的 pipe，那么當父進程被 kill -9 后會清理資源，關閉打開的文件，但是 close 只是引用計數(shù)減 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
    })

那么當子進程執(zhí)行結(jié)束后，go cmd 執(zhí)行這個匿名函數(shù)的 io.Copy 來讀取子進程輸出數(shù)據(jù)，永遠沒有數(shù)據(jù)可讀，也沒有超時，阻塞在 copy 這里。

解決方案

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

  1. 子進程啟動孫進程時，增加 CloseOnEec 標記，但不現(xiàn)實，還要看孫進程的輸出日志
  2. io.Copy 改寫，增加超時調(diào)用，理論上可行，但是要改源
  3. 超時 kill 時，不單殺子進程，而是殺掉進程組，此時 pipe 會被真正的關閉，觸發(fā) io.Copy 返回

最終采用方案 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
}
最后編輯于 ：
?著作權歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時請結(jié)合常識與多方信息審慎甄別。
平臺聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點，簡書系信息發(fā)布平臺，僅提供信息存儲服務。

相關閱讀更多精彩內(nèi)容

  • 官網(wǎng) 中文版本 好的網(wǎng)站 Content-type: text/htmlBASH Section: User ...
    不排版閱讀 4,707評論 0贊 5
  • https://nodejs.org/api/documentation.html 工具模塊 Assert 測試 ...
    KeKeMars閱讀 6,603評論 0贊 6
  • Spring Cloud為開發(fā)人員提供了快速構(gòu)建分布式系統(tǒng)中一些常見模式的工具（例如配置管理，服務發(fā)現(xiàn)，斷路器，智...
    卡卡羅2017閱讀 136,534評論 19贊 139
  • “這一杯我敬你，敬你漫不經(jīng)心進入我的生命又不動聲色地毀了我的生活，干了這杯酒我們只字不提愛情?！?不是個好學生 抽...
    鐘情陳尋閱讀 356評論 0贊 0
  • 你看到的或許不是最好的，卻是偶用心最真的，加油2018
    訫兒_閱讀 145評論 1贊 1

友情鏈接更多精彩內(nèi)容