之前把Go
服务都迁到Kubernetes
上后有些服务的某个 Pod
总是时不时的重启一下,通过查业务日志根本查不到原因,我分析了一下肯定是哪里代码不严谨造成引用空指针导致Go
发送运行时panic
才会挂掉的,但是容器重启后之前输出到stderr
的panic
是会被清空的,所以才有了这篇文章里后面的分析和方案解决。
在Go编写的应用程序里无论是在主协程(main goroutine)还是其他子协程里,一旦出了运行时panic
错误后,整个程序都会宕掉。一般的部署Go项目的时候都会使用supervisor
监控应用程序进程,一旦应用程序发生panic
停掉后supervisor
会把进程再启动起来。
那么在把项目部署到Kubernetes
集群后,因为每个节点上的kubelet
会对主进程崩溃的容器进行重启,所以就再引入supervisor
就有些功能重叠。但是Go
的panic
信息是直接写到标准错误的,容器重启后之前的panic
错误就没有了,没法排查导致容器崩溃的原因。所以排查容器重启的关键点就变成了:怎么把panic从stderr重定向到文件,这样就能通过容器的volume持久化日志文件的目录方式保留程序崩溃时的信息。
那么以前在supervisor
里可以直接通过配置stderr_logfile把程序运行时的标准错误设置成一个文件:
[program: go-xxx...]
directory=/home/go/src...
environment=...
command=/home/go/src.../bin/app
stderr_logfile=/home/xxx/log/..../app_err.log
现在换成了Kubernetes
,不再使用supervisor
后就只能是想办法在程序里实现了。针对在Go里实现记录panic到日志文件你可能首先会考虑:在recover
里把导致panic的错误记录到文件里,不过引用的第三方包里也有可能panic
,这个不现实。而且Go
也没有其他语言那样的Exception,未捕获的异常能由全局的ExceptionHandler捕获到的机制,实现不了用一个recover
捕获所有的panic
的功能。
最后就只有一个办法了,想办法把程序运行时的标准错误替换成日志文件,这样Go
再panic
的时候它还是往标准错误里写,只不过我们偷偷把标准错误的文件描述符换成了日志文件的描述符(在系统眼里stderr也是个文件,Unix系统里一切皆文件)。
按照这个思路我先用下面的例子试了一下:
package main
import (
"fmt"
"os"
)
const stdErrFile = "/tmp/go-app1-stderr.log"
func RewriteStderrFile() error {
file, err := os.OpenFile(stdErrFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
if err != nil {
fmt.Println(err)
return err
}
os.Stderr = file
return nil
}
func testPanic() {
panic("test panic")
}
func main() {
RewriteStderrFile()
testPanic()
}
这个例子,我们尝试使用 os.Stderr = file
来强制转换,但运行程序后,发现不起作用,/tmp/go-app1-stderr.log没有任何信息流入,panic
信息照样输出到标准错误里。
关于原因,搜索了一下,幸运的是 Rob Pike有专门对类似问题的解答,是这样说的:
把高层包创建的变量直接赋值到底层的runtime
是不行的,我们用syscall.Dup2
实现替换描述符再试一次,并且增加一个全局变量对日志文件描述符的引用,避免常驻线程运行中文件描述符被GC回收掉:
var stdErrFileHandler *os.File
func RewriteStderrFile() error {
if runtime.GOOS == "windows" {
return nil
}
file, err := os.OpenFile(stdErrFile, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
if err != nil {
fmt.Println(err)
return err
}
stdErrFileHandler = file //把文件句柄保存到全局变量,避免被GC回收
if err = syscall.Dup2(int(file.Fd()), int(os.Stderr.Fd())); err != nil {
fmt.Println(err)
return err
}
// 内存回收前关闭文件描述符
runtime.SetFinalizer(stdErrFileHandler, func(fd *os.File) {
fd.Close()
})
return nil
}
因为Windows
系统不支持的syscall.Dup2
这个函数,所以我加了个判读,Windows
环境下的Go
运行时加载系统的一个dll
文件也能实现这里的功能,不过我们服务器环境都是Linux
的,所以我认为这部分要兼容Windows
是无用功,保证项目在Windows
下能跑不受影响就行了。
再次运行程序后,打开日志文件/tmp/go-app1-stderr.log后就能看到刚才程序崩溃时的panic
信息,以及导致panic
时整个调用栈的信息:
➜ ~ cat /tmp/go-app1-stderr.log
panic: test panic
goroutine 1 [running]:
main.testPanic(...)
/Users/kev/Library/Application Support/JetBrains/GoLand2020.1/scratches/scratch_4.go:39
main.main()
/Users/kev/Library/Application Support/JetBrains/GoLand2020.1/scratches/scratch_4.go:44 +0x3f
panic: test panic
goroutine 1 [running]:
main.testPanic(...)
/Users/kev/Library/Application Support/JetBrains/GoLand2020.1/scratches/scratch_4.go:39
main.main()
/Users/kev/Library/Application Support/JetBrains/GoLand2020.1/scratches/scratch_4.go:44 +0x3f
目前这个方案已经在我们线上运行一个月了,已发现的Pod
重启事件都能把程序崩溃时的调用栈准确记录到日志文件里,帮助我们定位了几个代码里的问题。其实问题都是空指针相关的问题,这些问题我在之前的文章《[如何避免用动态语言的思维写Go代码] 》也提到过,项目一旦复杂起来谁写的代码也不能保证说不会发生空指针,不过我们事先做好检查很多都是能够避免的明显错误,对于特别细微条件下引发的错误只能靠分析事故当时的日志来解决啦。
Copyright© 2013-2020
All Rights Reserved 京ICP备2023019179号-8