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/sh
echo "in sleep"
sh /root/dongzerun/sleep1.sh

这是 sleep1.sh 模拟孙进程，sleep 1000 阻塞在这里

#!/bin/sh
sleep 1000

现象

启动测试 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 时，会先执行 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=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 数据。那么 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 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

原因总结

孙进程，启动后，默认会继承父进程打开的文件描述符，即 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 时，不单杀子进程，而是杀掉进程组，此时 pipe 会被真正的关闭，触发 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
}
最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 204,684评论 6赞 478
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 87,143评论 2赞 381
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 151,214评论 0赞 337
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 54,788评论 1赞 277
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 63,796评论 5赞 368
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 48,665评论 1赞 281
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 38,027评论 3赞 399
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 36,679评论 0赞 258
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 41,346评论 1赞 299
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,664评论 2赞 321
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,766评论 1赞 331
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,412评论 4赞 321
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 39,015评论 3赞 307
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,974评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,203评论 1赞 260
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 45,073评论 2赞 350
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,501评论 2赞 343

推荐阅读更多精彩内容

  • bash
    官网 中文版本 好的网站 Content-type: text/htmlBASH Section: User ...
    不排版阅读 4,364评论 0赞 5
  • NodeJS 官方文档v5.3.0 学习笔记
    https://nodejs.org/api/documentation.html 工具模块 Assert 测试 ...
    KeKeMars阅读 6,301评论 0赞 6
  • Spring Cloud
    Spring Cloud为开发人员提供了快速构建分布式系统中一些常见模式的工具（例如配置管理，服务发现，断路器，智...
    卡卡罗2017阅读 134,596评论 18赞 139
  • 爱你
    “这一杯我敬你，敬你漫不经心进入我的生命又不动声色地毁了我的生活，干了这杯酒我们只字不提爱情。” 不是个好学生 抽...
    钟情陈寻阅读 309评论 0赞 0
  • 2018-02-05
    你看到的或许不是最好的，却是偶用心最真的，加油2018
    訫兒_阅读 118评论 1赞 1