23

迁到 K8s 后服务老莫名重启?把 Go 的运行时错误重定向到文件

 4 years ago
source link: https://mp.weixin.qq.com/s/mitu71qNjtfzFzB6nkmHJA
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

前言

之前把 Go 服务都迁到 Kubernetes 上后有些服务的某个 Pod 总是时不时的重启一下,通过查业务日志根本查不到原因,我分析了一下肯定是哪里代码不严谨造成引用空指针导致 Go 发送运行时 panic 才会挂掉的,但是容器重启后之前输出到 stderrpanic 是会被清空的,所以才有了这篇文章里后面的分析和方案解决。

解决思路分析

在Go编写的应用程序里无论是在主协程(main goroutine)还是其他子协程里,一旦出了运行时 panic 错误后,整个程序都会宕掉。一般的部署Go项目的时候都会使用 supervisor 监控应用程序进程,一旦应用程序发生 panic 停掉后 supervisor 会把进程再启动起来。

那么在把项目部署到 Kubernetes 集群后,因为每个节点上的 kubelet 会对主进程崩溃的容器进行重启,所以就再引入 supervisor 就有些功能重叠。但是 Gopanic 信息是直接写到标准错误的,容器重启后之前的 panic 错误就没有了,没法排查导致容器崩溃的原因。所以排查容器重启的关键点就变成了:怎么把 panicstderr 重定向到文件,这样就能通过容器的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 的功能。

最后就只有一个办法了,想办法把程序运行时的标准错误替换成日志文件,这样 Gopanic 的时候它还是往标准错误里写,只不过我们偷偷把标准错误的文件描述符换成了日志文件的描述符(在系统眼里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 有专门对类似问题的解答,是这样说的:

zE3qAbA.jpg!mobile

把高层包创建的变量直接赋值到底层的 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代码 》也提到过,项目一旦复杂起来谁写的代码也不能保证说不会发生空指针,不过我们事先做好检查很多都是能够避免的明显错误,对于特别细微条件下引发的错误只能靠分析事故当时的日志来解决啦。

看到这里了,如果喜欢我的文章可以帮我点个赞,我会每周通过技术文章分享我的所学所见和第一手实践经验,感谢你的支持。微信搜索关注公众号「网管叨bi叨」第一时间获取我的文章推送,回复「GoCookBook」获取文章里的完整源码。

推荐阅读

- END -

关注公众号,获取更多精选技术原创文章

qeMRvmN.png!mobile


Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK