Golang控制panic|Golang控制panic stack trace的深度

缘起 在进行Golang开发过程中,出现一个问题:运行golang写的程序时出现异常,信息如下:

bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ go version go version go1.10.3 linux/amd64 bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ ./build.sh bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ ./mygate panic: http: multiple registrations for /debug/requestsgoroutine 1 [running]: net/http.(*ServeMux).Handle(0x149f340, 0xdbfe9b, 0xf, 0xe524a0, 0xdf2318) /software/servers/go1.10.3/src/net/http/server.go:2353 +0x239 net/http.(*ServeMux).HandleFunc(0x149f340, 0xdbfe9b, 0xf, 0xdf2318) /software/servers/go1.10.3/src/net/http/server.go:2368 +0x55 net/http.HandleFunc(0xdbfe9b, 0xf, 0xdf2318) /software/servers/go1.10.3/src/net/http/server.go:2380 +0x4b golang.org/x/net/trace.init.0() /sourcecode/go/work/src/golang.org/x/net/trace/trace.go:115 +0x42

看到这样的错误堆栈,我也是醉了,根本没有任何实际的价值。从错误堆栈中看不出到底是引用的哪个包导致重复注册 /debug/requests。
解决方案 有两种方案可以解决该问题,从而展现出更多的错误堆栈信息:
方案一:降低Golang版本 先前我使用的golang的版本是:1.10.3,将golang的版本换成1.9.0之后,重新编译运行,可以看到打印出了更多的信息:
bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ go version go version go1.9.2 linux/amd64 bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ ./build.sh bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ ./mygate panic: http: multiple registrations for /debug/requestsgoroutine 1 [running]: net/http.(*ServeMux).Handle(0x152e9c0, 0xe32ad5, 0xf, 0x13617e0, 0xe64468) /software/servers/go1.9.2/src/net/http/server.go:2270 +0x627 net/http.(*ServeMux).HandleFunc(0x152e9c0, 0xe32ad5, 0xf, 0xe64468) /software/servers/go1.9.2/src/net/http/server.go:2302 +0x55 net/http.HandleFunc(0xe32ad5, 0xf, 0xe64468) /software/servers/go1.9.2/src/net/http/server.go:2314 +0x4b golang.org/x/net/trace.init.0() /sourcecode/go/work/src/golang.org/x/net/trace/trace.go:115 +0x42 golang.org/x/net/trace.init() :1 +0x1cd google.golang.org/grpc.init() :1 +0x9b vitess.io/vitess/go/vt/callinfo.init() :1 +0x53 github.com/tiger/mygate/gate.init() :1 +0xaa main.init() :1 +0x4e

从上面的输出中可以看到,将golang的版本改为1.9.0之后,打印出了更多的错误堆栈信息,而且可以看出,是在执行gate.init()方法的时候导致了问题。
方案二:设置环境变量:export GOTRACEBACK=system 【Golang控制panic|Golang控制panic stack trace的深度】通过研究官方文档,发现可以通过设置环境变量GOTRACEBACK来控制Golang panic stack trace输出的信息的多少。说明如下:
环境变量GOTRACEBACK可以控制Go程序由于不可恢复的panic或者未预料到的其他运行时异常而产生的错误堆栈输出的信息的多少。默认情况下(single),当产生错误的时候,只会打印出异常goroutine的异常堆栈,当不存在当前goroutine或者是由于runtime内部的错误导致的panic,则会打印出所有goroutine的堆栈。 GOTRACEBACK的设置值有几种,下面分别说明:
export GOTRACEBACK=none :完全省略panic的 stack traces 。
export GOTRACEBACK=single (默认值)只打印当前goroutine的部分stack traces。当不存在当前goroutine或者是由于runtime内部的错误导致的panic,则会打印出所有goroutine的堆栈。
export GOTRACEBACK=all :打印用户创建的所有goroutine的stack trace。
export GOTRACEBACK=system :与all的行为很像,只不过会将runtime的goroutine的stace trace也打出来,并且还会显示出runtime内部创建的所有goroutine。
export GOTRACEBACK=crash:与“system”的行为很像,只不过当程序crash的时候不是直接退出,而是可以按照操作系统指定的方式进行后续处理。
例如,在Unix操作系统中,crash会发送一个SIGABRT信号触发core dump。由于历史原因,当将系统环境变量GOTRACEBACK设置为:0, 1, 和 2 的时候,分别代表none, all和system。通过包runtime/debug package中的方法SetTraceback,也可以设置相应的GOTRACEBACK的值,进而控制输出的stack trace的内容的多少,但是通过该方法,不能够设置比系统环境变量的level更低的值。而level的高低顺序为:
none
#在~/.bashrc文件中添加环境变量GOTRACEBACK:export GOTRACEBACK=system bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ vim ~/.bashrc bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ source ~/.bashrc bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ ./build.sh bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ ./mygate panic: http: multiple registrations for /debug/requestsgoroutine 1 [running]: panic(0xc2e240, 0xc4200315d0) /software/servers/go1.10.3/src/runtime/panic.go:551 +0x3c1 fp=0xc42007bdd8 sp=0xc42007bd38 pc=0x42b681 net/http.(*ServeMux).Handle(0x149f340, 0xdbfe9b, 0xf, 0xe524a0, 0xdf2318) /software/servers/go1.10.3/src/net/http/server.go:2353 +0x239 fp=0xc42007be38 sp=0xc42007bdd8 pc=0x8642c9 net/http.(*ServeMux).HandleFunc(0x149f340, 0xdbfe9b, 0xf, 0xdf2318) /software/servers/go1.10.3/src/net/http/server.go:2368 +0x55 fp=0xc42007be70 sp=0xc42007be38 pc=0x864375 net/http.HandleFunc(0xdbfe9b, 0xf, 0xdf2318) /software/servers/go1.10.3/src/net/http/server.go:2380 +0x4b fp=0xc42007bea0 sp=0xc42007be70 pc=0x8643db golang.org/x/net/trace.init.0() /sourcecode/go/work/src/golang.org/x/net/trace/trace.go:115 +0x42 fp=0xc42007bec8 sp=0xc42007bea0 pc=0x9d3c92 golang.org/x/net/trace.init() :1 +0x158 fp=0xc42007bef0 sp=0xc42007bec8 pc=0x9d9088 google.golang.org/grpc.init() :1 +0x9b fp=0xc42007bf28 sp=0xc42007bef0 pc=0xa39eeb vitess.io/vitess/go/vt/callinfo.init() :1 +0x53 fp=0xc42007bf38 sp=0xc42007bf28 pc=0xa3c5d3 github.com/tiger/mygate/gate.init() :1 +0xaa fp=0xc42007bf78 sp=0xc42007bf38 pc=0xba060a main.init() :1 +0x4e fp=0xc42007bf88 sp=0xc42007bf78 pc=0xba21ae runtime.main() /software/servers/go1.10.3/src/runtime/proc.go:186 +0x1ca fp=0xc42007bfe0 sp=0xc42007bf88 pc=0x42d34a runtime.goexit() /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc42007bfe8 sp=0xc42007bfe0 pc=0x457fa1goroutine 2 [force gc (idle)]: runtime.gopark(0xdf2ed0, 0x149d570, 0xdc053a, 0xf, 0xdf2d14, 0x1) /software/servers/go1.10.3/src/runtime/proc.go:291 +0x11a fp=0xc420058768 sp=0xc420058748 pc=0x42d7ea runtime.goparkunlock(0x149d570, 0xdc053a, 0xf, 0x14, 0x1) /software/servers/go1.10.3/src/runtime/proc.go:297 +0x5e fp=0xc4200587a8 sp=0xc420058768 pc=0x42d89e runtime.forcegchelper() /software/servers/go1.10.3/src/runtime/proc.go:248 +0xcc fp=0xc4200587e0 sp=0xc4200587a8 pc=0x42d62c runtime.goexit() /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc4200587e8 sp=0xc4200587e0 pc=0x457fa1 created by runtime.init.4 /software/servers/go1.10.3/src/runtime/proc.go:237 +0x35goroutine 3 [GC sweep wait]: runtime.gopark(0xdf2ed0, 0x149dea0, 0xdbe7ab, 0xd, 0x420014, 0x1) /software/servers/go1.10.3/src/runtime/proc.go:291 +0x11a fp=0xc420058f60 sp=0xc420058f40 pc=0x42d7ea runtime.goparkunlock(0x149dea0, 0xdbe7ab, 0xd, 0x14, 0x1) /software/servers/go1.10.3/src/runtime/proc.go:297 +0x5e fp=0xc420058fa0 sp=0xc420058f60 pc=0x42d89e runtime.bgsweep(0xc4200440e0) /software/servers/go1.10.3/src/runtime/mgcsweep.go:52 +0xa3 fp=0xc420058fd8 sp=0xc420058fa0 pc=0x420073 runtime.goexit() /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc420058fe0 sp=0xc420058fd8 pc=0x457fa1 created by runtime.gcenable /software/servers/go1.10.3/src/runtime/mgc.go:216 +0x58goroutine 4 [finalizer wait]: runtime.gopark(0xdf2ed0, 0x14bd6a8, 0xdbf876, 0xe, 0x14, 0x1) /software/servers/go1.10.3/src/runtime/proc.go:291 +0x11a fp=0xc420059718 sp=0xc4200596f8 pc=0x42d7ea runtime.goparkunlock(0x14bd6a8, 0xdbf876, 0xe, 0x14, 0x1) /software/servers/go1.10.3/src/runtime/proc.go:297 +0x5e fp=0xc420059758 sp=0xc420059718 pc=0x42d89e runtime.runfinq() /software/servers/go1.10.3/src/runtime/mfinal.go:175 +0xad fp=0xc4200597e0 sp=0xc420059758 pc=0x41711d runtime.goexit() /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc4200597e8 sp=0xc4200597e0 pc=0x457fa1 created by runtime.createfing /software/servers/go1.10.3/src/runtime/mfinal.go:156 +0x62goroutine 5 [chan receive]: runtime.gopark(0xdf2ed0, 0xc4200e4058, 0xdbe01e, 0xc, 0xc420049317, 0x3) /software/servers/go1.10.3/src/runtime/proc.go:291 +0x11a fp=0xc420059e88 sp=0xc420059e68 pc=0x42d7ea runtime.goparkunlock(0xc4200e4058, 0xdbe01e, 0xc, 0x17, 0x3) /software/servers/go1.10.3/src/runtime/proc.go:297 +0x5e fp=0xc420059ec8 sp=0xc420059e88 pc=0x42d89e runtime.chanrecv(0xc4200e4000, 0xc420059fb0, 0xc4200e8001, 0xc4200e4000) /software/servers/go1.10.3/src/runtime/chan.go:518 +0x2f2 fp=0xc420059f60 sp=0xc420059ec8 pc=0x406082 runtime.chanrecv2(0xc4200e4000, 0xc420059fb0, 0x0) /software/servers/go1.10.3/src/runtime/chan.go:405 +0x2b fp=0xc420059f90 sp=0xc420059f60 pc=0x405d7b github.com/golang/glog.(*loggingT).flushDaemon(0x149fc20) /sourcecode/go/work/src/github.com/golang/glog/glog.go:882 +0x8b fp=0xc420059fd8 sp=0xc420059f90 pc=0x589ebb runtime.goexit() /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc420059fe0 sp=0xc420059fd8 pc=0x457fa1 created by github.com/golang/glog.init.0 /sourcecode/go/work/src/github.com/golang/glog/glog.go:410 +0x203goroutine 18 [syscall]: runtime.notetsleepg(0x14a3e20, 0x6fc233bba, 0x0) /software/servers/go1.10.3/src/runtime/lock_futex.go:227 +0x42 fp=0xc420054760 sp=0xc420054730 pc=0x410d82 runtime.timerproc(0x14a3e00) /software/servers/go1.10.3/src/runtime/time.go:261 +0x2e7 fp=0xc4200547d8 sp=0xc420054760 pc=0x4493a7 runtime.goexit() /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc4200547e0 sp=0xc4200547d8 pc=0x457fa1 created by runtime.(*timersBucket).addtimerLocked /software/servers/go1.10.3/src/runtime/time.go:160 +0x107goroutine 6 [syscall]: runtime.notetsleepg(0x14bdcc0, 0xffffffffffffffff, 0x0) /software/servers/go1.10.3/src/runtime/lock_futex.go:227 +0x42 fp=0xc42005a780 sp=0xc42005a750 pc=0x410d82 os/signal.signal_recv(0x0) /software/servers/go1.10.3/src/runtime/sigqueue.go:139 +0xa6 fp=0xc42005a7a8 sp=0xc42005a780 pc=0x4414e6 os/signal.loop() /software/servers/go1.10.3/src/os/signal/signal_unix.go:22 +0x22 fp=0xc42005a7e0 sp=0xc42005a7a8 pc=0x99f782 runtime.goexit() /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc42005a7e8 sp=0xc42005a7e0 pc=0x457fa1 created by os/signal.init.0 /software/servers/go1.10.3/src/os/signal/signal_unix.go:28 +0x41

从上面的输出中可以看到,除了打印出了方案一中所看到的错误堆栈信息,还打印了其他的goroutine的堆栈信息。
总结 不知道为什么,默认的情况下golang1.10.3打印的错误堆栈信息要比1.9.0的错误堆栈信息要少,我也没有查看golang具体的源代码,有兴趣的同学,可以研究下golang的源代码。但是我们可以知道有两种方法可以得到更多的goroutine堆栈信息:
(1)使用golang 1.9.0版本
(2)export GOTRACEBACK=system
参考 https://golang.org/pkg/runtime/
https://golang.org/pkg/runtime/debug/#SetTraceback
吕信个人原创,转载请注明出处

    推荐阅读