[[409900]]

本文轉載自微信公眾號「董澤潤的技術筆記」，作者董澤潤。轉載本文請聯系董澤潤的技術筆記公眾號。

上家公司的案例。先說下使用背景，服務在每臺服務器上啟動 agent, 用戶會在指定機器上執行任務，并將結果返回到網頁上。執行任務由用戶自定義腳本，一般也都是 shell 或是 python，會不斷的產生子進程，孫進程，直到執行完畢或是超時被 kill。

問題

最近發現經常有任務，一直處于運行中，但實際上己經超時被 kill，并未將輸出寫到系統，看不到任務的執行情況

登錄機器，發現執行腳本進程己經殺掉，但是有子腳本卡在某個 http 調用。再看下這個腳本，python requests 默認沒有設置超時...

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

復現

環境是 go version go1.16.5 linux/amd64, agent 使用 exec.CommandContext 啟動任務，設置 ctx 超時 30s，并將結果寫到 bytes.Buffer, 最后打印。簡化例子如下：

~/zerun.dong/code/gotest# cat wait.go 
package main 
 
import ( 
    "bytes" 
    "context" 
    "fmt" 
    "os/exec" 
    "time" 
) 
 
func main() { 
    ctx, cancelFn := context.WithTimeout(context.Background(), time.Second*30) 
    defer cancelFn() 
    cmd := exec.CommandContext(ctx, "./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 ./sleep1.sh 

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

#!/bin/sh 
sleep 1000 

###現象 啟動測試 wait 程序，查看 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 行代碼，查看源碼：

// 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，簡化代碼如下，主要改動點有兩處：

SysProcAttr 配置 Setpgid，讓子進程與孫進程，擁有獨立的進程組id，即子進程的 pid

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 
} 

但這種方式，也有個局限，目前只適用于類 linux 平臺

小結 

大家也可以看到，只要權限足夠，問題穩定復現，沒有查不出來的問題。套路也都差不多，回歸問題開始，python request 庫不寫 timeout 的比比皆是 ...