背景
在Go程序运行的过程中，很有可能造成程序panic，并且这个panic的信息是不会被记录在日志文件中的。这种情况该怎么办？
一种方法就是使用recover，通过recover来捕获panic信息，然后再写入日志文件。但是这种方法有两个缺陷：
- recover只能恢复同一个goroutine中的panic，不同goroutine的不能被捕获，这就要求每次启动goroutine的时候要写一遍recover代码，这太麻烦了。
- 遇到并发读写map这种fatal error的时候，panic是无法恢复的。
另外一种方法就比较简单了，因为panic信息实际上是被输出到标准错误了，默认的标准错误设备是终端。我们可以将标准错误重定向至文件，这样就可以捕获到程序的panic信息了。
而重定向的话也大概有两种方法：
- 启动的时候重定向
nohup ./program start 1>stdout.log 2>stderr.log &
命令行可用以上方式来重定向。如果使用supervisor等来管理程序的话，也可以通过配置stdout_logfile和stderr_logfile来重定向，原理都是一致的。
- 程序内通过Dup2系统调用来重定向
我们用的是第二种方法。
代码也很简单，如下:
//
// coredump.go
func init() {
fd, err := os.OpenFile("coredump.log", os.O_WRONLY|os.O_APPEND|os.O_CREATE, os.ModePerm)
if err != nil {
fmt.Println("create file descriptor error:", err)
return
}
SetStdHandle(fd, fd)
}
func SetStdHandle(stdout, stderr *os.File) error {
if err := syscall.Dup2(int(stdout.Fd()), int(os.Stdout.Fd())); err != nil {
return err
}
*os.Stdout = *stdout
if err := syscall.Dup2(int(stderr.Fd()), int(os.Stderr.Fd())); err != nil {
return err
}
*os.Stderr = *stderr
return nil
}
问题
上面的代码在一开始测试的时候是没问题的，但是后面发现有时候还是无法捕获到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。这就很奇怪了。
完整代码如下（为了复现写的示例，非真实代码）：
//
// main.go
func main() {
ioutil.WriteFile("pidfile", []byte(strconv.Itoa(os.Getpid())), os.ModePerm)
go func() {
// 模拟程序panic
time.Sleep(time.Second * 5)
panic("adalkdjlfjlsfjalsfjls")
}()
// 下面的代码是为了使系统尽快进行垃圾回收操作
//
//initSize := 100
//for i := 0; i < 20; i++ {
// data = make([]byte, initSize)
// //time.Sleep(time.Second)
// initSize *= 2
//}
go func() {
if err := http.ListenAndServe(":10086", nil); err != nil {
panic(err)
}
}()
go func() {
if err := http.ListenAndServe(":10010", nil); err != nil {
panic(err)
}
}()
ch := make(chan os.Signal)
signal.Notify(ch, syscall.SIGINT)
<-ch
}
问题到这里就陷入了死胡同，以上代码应该不会有任何问题，但为什么会出现上述情形呢？
柳暗花明
在经过漫长的调整代码位置、加调试日志、一次次不同情形下复现后，终于发现了问题可能出在变量被垃圾回收这个问题上了。
再后头看下最开始的重定向的代码：
package main
import (
"os"
"syscall"
)
func init() {
fd, err := os.OpenFile("coredump.log", os.O_WRONLY|os.O_APPEND|os.O_CREATE, os.ModePerm)
if err != nil {
fmt.Println("create file descriptor error:", err)
return
}
SetStdHandle(fd, fd)
}
func SetStdHandle(stdout, stderr *os.File) error {
if err := syscall.Dup2(int(stdout.Fd()), int(os.Stdout.Fd())); err != nil {
return err
}
*os.Stdout = *stdout
if err := syscall.Dup2(int(stderr.Fd()), int(os.Stderr.Fd())); err != nil {
return err
}
*os.Stderr = *stderr
return nil
}
其中第16行和第21行当初是为了其他地方在直接使用os.Stdout和os.Stderr的时候也会直接写入文件中，所以加的（事实证明是我画蛇添足了）。
但是问题就出在这里了。这两个变量指向了新的地址，而原来指向的内存由于没被引用了（不可达），所以会被垃圾回收掉。
关键到了，看一下这两个变量的定义：
var (
Stdin = NewFile(uintptr(syscall.Stdin), "/dev/stdin")
Stdout = NewFile(uintptr(syscall.Stdout), "/dev/stdout")
Stderr = NewFile(uintptr(syscall.Stderr), "/dev/stderr")
)
NewFile函数定义：
func NewFile(fd uintptr, name string) *File {
kind := kindNewFile
if nb, err := unix.IsNonblock(int(fd)); err == nil && nb {
kind = kindNonBlock
}
return newFile(fd, name, kind)
}
newFile:
func newFile(fd uintptr, name string, kind newFileKind) *File {
f := &File{&file{
pfd: poll.FD{
Sysfd: fdi,
IsStream: true,
ZeroReadIsEOF: true,
},
name: name,
stdoutOrErr: fdi == 1 || fdi == 2,
}}
// 此处省略n行
runtime.SetFinalizer(f.file, (*file).close)
return f
}
也就是说，当这块内存被回收时，会调用close方法，当句柄没有被引用时，会被关闭。
为了验证这个想法，改写了标准库的代码，在close方法中增加了一行日志：
//file.go
var (
Stdin = NewFile(uintptr(syscall.Stdin), "/dev/stdin")
Stdout = NewFile(uintptr(syscall.Stdout), "/dev/stdout")
Stderr = NewFile(uintptr(syscall.Stderr), "/dev/stderr")
debuger *File
)
func init() {
debuger, _ = OpenFile("debuger.log", O_WRONLY|O_CREAT|O_APPEND, os.ModPerm)
}
// file_unix.go
func (file *file) close() error {
debuger.WriteString("file descriptor closed:" + strconv.Itoa(Getpid()) + "\n")
if file == nil {
return syscall.EINVAL
}
if file.dirinfo != nil {
file.dirinfo.close()
}
var err error
if e := file.pfd.Close(); e != nil {
if e == poll.ErrFileClosing {
e = ErrClosed
}
err = &PathError{"close", file.name, e}
}
// no need for a finalizer anymore
runtime.SetFinalizer(file, nil)
return err
}
重新运行程序，然后查看debuger.log文件：
果然，标准输出和标准错误都被关闭了！
后来，又查了linux下文件描述符的分配方法（fs/file.c: alloc_fd）：每次优先分配fd值最小的空闲fd。
至此，问题已经明了了：
- 乱给变量赋值，造成垃圾回收，调用Finalizer，释放了文件描述符。
- 后续有申请文件描述符操作（打开文件、监听端口、接受连接等），重新分配了1和2。
- 后续调用write系统调用的时候，不可写，无法写入。
总结
- strace很好很强大
/proc/$pid/下面可以查看进程的很多信息- 没事别瞎动标准库的东西
