Programmer

Will Change The World

记一次由垃圾回收造成的诡异问题

背景

在Go程序运行的过程中,很有可能造成程序panic,并且这个panic的信息是不会被记录在日志文件中的。这种情况该怎么办?
一种方法就是使用recover,通过recover来捕获panic信息,然后再写入日志文件。但是这种方法有两个缺陷​:

  1. recover只能恢复同一个goroutine中的panic,不同goroutine的不能被捕获,这就要求每次启动goroutine的时候要写一遍recover代码,这太麻烦了。
  2. 遇到并发读写map这种fatal error​的时候,panic是无法恢复的。

​另外一种方法就比较简单了,因为panic信息实际上是被输出到标准​错误了,默认的标准错误设备是终端​。我们可以将标准错误重定向至文件,这样就可以捕获到​程序的panic信息了。​

而重定向的话也大概有两种方法:

  1. 启动的时候重定向
1nohup ./program start  1>stdout.log  2>stderr.log &

命令行可用以上方式来重定向。如果使用supervisor等来管理程序的话,也可以通过配置stdout_logfile和stderr_logfile来重定向,原理都是一致的。

  1. 程序内通过Dup2系统调用来重定向

我们用的是第二种方法。

代码也很简单,如下:

 1// 2// coredump.go 3 4func init() { 5    fd, err := os.OpenFile("coredump.log", os.O_WRONLY|os.O_APPEND|os.O_CREATE, os.ModePerm) 6    if err != nil { 7        fmt.Println("create file descriptor error:", err) 8        return 9    }1011    SetStdHandle(fd, fd)12}1314func SetStdHandle(stdout, stderr *os.File) error {1516    if err := syscall.Dup2(int(stdout.Fd()), int(os.Stdout.Fd())); err != nil {17        return err18    }19    *os.Stdout = *stdout2021    if err := syscall.Dup2(int(stderr.Fd()), int(os.Stderr.Fd())); err != nil {22        return err23    }24    *os.Stderr = *stderr2526    return nil27}

问题

上面的代码在一开始测试的时候是没问题的,但是后面发现有时候还是无法捕获到panic信息。甚至更离奇的是,不使用init方法,改为显式调用后正常,但是重构代码、调整了调用位置后又不行了!

嗯????

排查

为什么coredump.log文件是空的?

首先,程序启动后,coredump.log文件确实是创建了的。简单排查后发现,init函数也是确实执行了并且没有返回错误。但是程序panic后文件里也确实是空的。

首先使用strace工具,查看系统调用情况,到底有没有往coredump.log文件中写数据。

1strace -ff -o trace -p 30526

可以看到,确实是调用了系统调用write,并且写到了2(标准错误)中,但是返回结果却是Bad file descriptor。通常出现这个错误的原因是文件的权限设置有问题,比如以只读方式打开。但是以上代码是没问题的啊,也有写权限。

没办法,看一下进程的文件描述符信息吧。接着查看了/proc/$pid/fd目录。

1ll /proc/30526/fd

不看不知道,一看吓一跳。

为什么1和2变成了socket?正常来说应该是/dev/pts/0,重定向后应该是重定向的文件才对,为什么会变成socket?

为什么1和2变成了socket句柄?

使用lsof工具查看该socket信息

1lsof -i |grep 209374

发现该socket居然是我http服务开启监听的socket。这就很奇怪了。

完整代码如下(为了复现写的示例,非真实代码):

 1// 2// main.go 3 4func main() { 5 6    ioutil.WriteFile("pidfile", []byte(strconv.Itoa(os.Getpid())), os.ModePerm) 7 8    go func() { 9        // 模拟程序panic10        time.Sleep(time.Second*5)11        panic("adalkdjlfjlsfjalsfjls")12    }()1314    // 下面的代码是为了使系统尽快进行垃圾回收操作15    // 16    //initSize := 10017    //for i := 0; i < 20; i++ {18    //  data = make([]byte, initSize)19    //  //time.Sleep(time.Second)20    //  initSize *= 221    //}2223    go func() {24        if err := http.ListenAndServe(":10086", nil); err != nil {25            panic(err)26        }27    }()2829    go func() {30        if err := http.ListenAndServe(":10010", nil); err != nil {31            panic(err)32        }33    }()343536    ch := make(chan os.Signal)37    signal.Notify(ch, syscall.SIGINT)38    <-ch39}

问题到这里就陷入了死胡同,以上代码应该不会有任何问题,但为什么会出现上述情形呢?

柳暗花明

在经过漫长的调整代码位置、加调试日志、一次次不同情形下复现后,终于发现了问题可能出在变量被垃圾回收这个问题上了。

再后头看下最开始的重定向的代码:

 1func init() { 2    fd, err := os.OpenFile("coredump.log", os.O_WRONLY|os.O_APPEND|os.O_CREATE, os.ModePerm) 3    if err != nil { 4        fmt.Println("create file descriptor error:", err) 5        return 6    } 7 8    SetStdHandle(fd, fd) 9}1011func SetStdHandle(stdout, stderr *os.File) error {1213    if err := syscall.Dup2(int(stdout.Fd()), int(os.Stdout.Fd())); err != nil {14        return err15    }16    *os.Stdout = *stdout1718    if err := syscall.Dup2(int(stderr.Fd()), int(os.Stderr.Fd())); err != nil {19        return err20    }21    *os.Stderr = *stderr2223    return nil24}

其中第16行和第21行当初是为了其他地方在直接使用os.Stdout和os.Stderr的时候也会直接写入文件中,所以加的(事实证明是我画蛇添足了)。

但是问题就出在这里了。这两个变量指向了新的地址,而原来指向的内存由于没被引用了(不可达),所以会被垃圾回收掉。

关键到了,看一下这两个变量的定义:

1var (2    Stdin  = NewFile(uintptr(syscall.Stdin), "/dev/stdin")3    Stdout = NewFile(uintptr(syscall.Stdout), "/dev/stdout")4    Stderr = NewFile(uintptr(syscall.Stderr), "/dev/stderr")5)

NewFile函数定义:

1func NewFile(fd uintptr, name string) *File {2    kind := kindNewFile3    if nb, err := unix.IsNonblock(int(fd)); err == nil && nb {4        kind = kindNonBlock5    }6    return newFile(fd, name, kind)7}

newFile:

 1func newFile(fd uintptr, name string, kind newFileKind) *File { 2    f := &File{&file{ 3        pfd: poll.FD{ 4            Sysfd:         fdi, 5            IsStream:      true, 6            ZeroReadIsEOF: true, 7        }, 8        name:        name, 9        stdoutOrErr: fdi == 1 || fdi == 2,10    }}1112    // 此处省略n行1314    runtime.SetFinalizer(f.file, (*file).close)15    return f1617}

也就是说,当这块内存被回收时,会调用close方法,当句柄没有被引用时,会被关闭。

为了验证这个想法,改写了标准库的代码,在close方法中增加了一行日志:

 1//file.go 2 3var ( 4    Stdin  = NewFile(uintptr(syscall.Stdin), "/dev/stdin") 5    Stdout = NewFile(uintptr(syscall.Stdout), "/dev/stdout") 6    Stderr = NewFile(uintptr(syscall.Stderr), "/dev/stderr") 7    debuger *File 8) 9func init(){10    debuger, _ = OpenFile("debuger.log",O_WRONLY|O_CREAT|O_APPEND,os.ModPerm)11}1213// file_unix.go14func (file *file) close() error {15    debuger.WriteString("file descriptor closed:"+strconv.Itoa(Getpid())+"\n")16    if file == nil {17        return syscall.EINVAL18    }19    if file.dirinfo != nil {20        file.dirinfo.close()21    }22    var err error23    if e := file.pfd.Close(); e != nil {24        if e == poll.ErrFileClosing {25            e = ErrClosed26        }27        err = &PathError{"close", file.name, e}28    }2930    // no need for a finalizer anymore31    runtime.SetFinalizer(file, nil)32    return err33}

重新运行程序,然后查看debuger.log文件:

果然,标准输出和标准错误都被关闭了!

后来,又查了linux下文件描述符的分配方法(fs/file.c: alloc_fd):每次优先分配fd值最小的空闲fd

至此,问题已经明了了:

  1. 乱给变量赋值,造成垃圾回收,调用Finalizer,释放了文件描述符。
  2. 后续有申请文件描述符操作(打开文件、监听端口、接受连接等),重新分配了1和2。
  3. 后续调用write系统调用的时候,不可写,无法写入。

总结

  1. strace很好很强大
  2. /proc/$pid/下面可以查看进程的很多信息
  3. 没事别瞎动标准库的东西
点赞

发表评论

电子邮件地址不会被公开。 必填项已用*标注