Golang控制panic stack trace的深度

緣起

在進行Golang開發過程中，出現一個問題：運行golang寫的程式時出現異常，資訊如下：

bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ go versiongo version go1.10.3 linux/amd64bjlvxin@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 +0x239net/http.(*ServeMux).HandleFunc(0x149f340, 0xdbfe9b, 0xf, 0xdf2318)    /software/servers/go1.10.3/src/net/http/server.go:2368 +0x55net/http.HandleFunc(0xdbfe9b, 0xf, 0xdf2318)    /software/servers/go1.10.3/src/net/http/server.go:2380 +0x4bgolang.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 versiongo version go1.9.2 linux/amd64bjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ ./build.shbjlvxin@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 +0x627net/http.(*ServeMux).HandleFunc(0x152e9c0, 0xe32ad5, 0xf, 0xe64468)    /software/servers/go1.9.2/src/net/http/server.go:2302 +0x55net/http.HandleFunc(0xe32ad5, 0xf, 0xe64468)    /software/servers/go1.9.2/src/net/http/server.go:2314 +0x4bgolang.org/x/net/trace.init.0()    /sourcecode/go/work/src/golang.org/x/net/trace/trace.go:115 +0x42golang.org/x/net/trace.init()    <autogenerated>:1 +0x1cdgoogle.golang.org/grpc.init()    <autogenerated>:1 +0x9bvitess.io/vitess/go/vt/callinfo.init()    <autogenerated>:1 +0x53github.com/tiger/mygate/gate.init()    <autogenerated>:1 +0xaamain.init()    <autogenerated>:1 +0x4e

從上面的輸出中可以看到，將golang的版本改為1.9.0之後，列印出了更多的錯誤堆棧資訊，而且可以看出，是在執行gate.init()方法的時候導致了問題。

方案二：設定環境變數：export GOTRACEBACK=system

通過研究官方文檔，發現可以通過設定環境變數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<single<all<system<crash
具體SetTraceback方法的時候可以參考： https://golang.org/pkg/runtime/debug/#SetTraceback.

#在～/.bashrc檔案中添加環境變數GOTRACEBACK：export GOTRACEBACK=systembjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ vim ~/.bashrcbjlvxin@bjlvxin-Vostro-270:/sourcecode/go/work/src/github.com/tiger/mygate/cmd$ source ~/.bashrcbjlvxin@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=0x42b681net/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=0x8642c9net/http.(*ServeMux).HandleFunc(0x149f340, 0xdbfe9b, 0xf, 0xdf2318)    /software/servers/go1.10.3/src/net/http/server.go:2368 +0x55 fp=0xc42007be70 sp=0xc42007be38 pc=0x864375net/http.HandleFunc(0xdbfe9b, 0xf, 0xdf2318)    /software/servers/go1.10.3/src/net/http/server.go:2380 +0x4b fp=0xc42007bea0 sp=0xc42007be70 pc=0x8643dbgolang.org/x/net/trace.init.0()    /sourcecode/go/work/src/golang.org/x/net/trace/trace.go:115 +0x42 fp=0xc42007bec8 sp=0xc42007bea0 pc=0x9d3c92golang.org/x/net/trace.init()    <autogenerated>:1 +0x158 fp=0xc42007bef0 sp=0xc42007bec8 pc=0x9d9088google.golang.org/grpc.init()    <autogenerated>:1 +0x9b fp=0xc42007bf28 sp=0xc42007bef0 pc=0xa39eebvitess.io/vitess/go/vt/callinfo.init()    <autogenerated>:1 +0x53 fp=0xc42007bf38 sp=0xc42007bf28 pc=0xa3c5d3github.com/tiger/mygate/gate.init()    <autogenerated>:1 +0xaa fp=0xc42007bf78 sp=0xc42007bf38 pc=0xba060amain.init()    <autogenerated>:1 +0x4e fp=0xc42007bf88 sp=0xc42007bf78 pc=0xba21aeruntime.main()    /software/servers/go1.10.3/src/runtime/proc.go:186 +0x1ca fp=0xc42007bfe0 sp=0xc42007bf88 pc=0x42d34aruntime.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=0x42d7earuntime.goparkunlock(0x149d570, 0xdc053a, 0xf, 0x14, 0x1)    /software/servers/go1.10.3/src/runtime/proc.go:297 +0x5e fp=0xc4200587a8 sp=0xc420058768 pc=0x42d89eruntime.forcegchelper()    /software/servers/go1.10.3/src/runtime/proc.go:248 +0xcc fp=0xc4200587e0 sp=0xc4200587a8 pc=0x42d62cruntime.goexit()    /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc4200587e8 sp=0xc4200587e0 pc=0x457fa1created 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=0x42d7earuntime.goparkunlock(0x149dea0, 0xdbe7ab, 0xd, 0x14, 0x1)    /software/servers/go1.10.3/src/runtime/proc.go:297 +0x5e fp=0xc420058fa0 sp=0xc420058f60 pc=0x42d89eruntime.bgsweep(0xc4200440e0)    /software/servers/go1.10.3/src/runtime/mgcsweep.go:52 +0xa3 fp=0xc420058fd8 sp=0xc420058fa0 pc=0x420073runtime.goexit()    /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc420058fe0 sp=0xc420058fd8 pc=0x457fa1created 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=0x42d7earuntime.goparkunlock(0x14bd6a8, 0xdbf876, 0xe, 0x14, 0x1)    /software/servers/go1.10.3/src/runtime/proc.go:297 +0x5e fp=0xc420059758 sp=0xc420059718 pc=0x42d89eruntime.runfinq()    /software/servers/go1.10.3/src/runtime/mfinal.go:175 +0xad fp=0xc4200597e0 sp=0xc420059758 pc=0x41711druntime.goexit()    /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc4200597e8 sp=0xc4200597e0 pc=0x457fa1created 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=0x42d7earuntime.goparkunlock(0xc4200e4058, 0xdbe01e, 0xc, 0x17, 0x3)    /software/servers/go1.10.3/src/runtime/proc.go:297 +0x5e fp=0xc420059ec8 sp=0xc420059e88 pc=0x42d89eruntime.chanrecv(0xc4200e4000, 0xc420059fb0, 0xc4200e8001, 0xc4200e4000)    /software/servers/go1.10.3/src/runtime/chan.go:518 +0x2f2 fp=0xc420059f60 sp=0xc420059ec8 pc=0x406082runtime.chanrecv2(0xc4200e4000, 0xc420059fb0, 0x0)    /software/servers/go1.10.3/src/runtime/chan.go:405 +0x2b fp=0xc420059f90 sp=0xc420059f60 pc=0x405d7bgithub.com/golang/glog.(*loggingT).flushDaemon(0x149fc20)    /sourcecode/go/work/src/github.com/golang/glog/glog.go:882 +0x8b fp=0xc420059fd8 sp=0xc420059f90 pc=0x589ebbruntime.goexit()    /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc420059fe0 sp=0xc420059fd8 pc=0x457fa1created 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=0x410d82runtime.timerproc(0x14a3e00)    /software/servers/go1.10.3/src/runtime/time.go:261 +0x2e7 fp=0xc4200547d8 sp=0xc420054760 pc=0x4493a7runtime.goexit()    /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc4200547e0 sp=0xc4200547d8 pc=0x457fa1created 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=0x410d82os/signal.signal_recv(0x0)    /software/servers/go1.10.3/src/runtime/sigqueue.go:139 +0xa6 fp=0xc42005a7a8 sp=0xc42005a780 pc=0x4414e6os/signal.loop()    /software/servers/go1.10.3/src/os/signal/signal_unix.go:22 +0x22 fp=0xc42005a7e0 sp=0xc42005a7a8 pc=0x99f782runtime.goexit()    /software/servers/go1.10.3/src/runtime/asm_amd64.s:2361 +0x1 fp=0xc42005a7e8 sp=0xc42005a7e0 pc=0x457fa1created 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

呂信個人原創，轉載請註明出處