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/requests

goroutine 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/requests

goroutine 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()
    <autogenerated>:1 +0x1cd
google.golang.org/grpc.init()
    <autogenerated>:1 +0x9b
vitess.io/vitess/go/vt/callinfo.init()
    <autogenerated>:1 +0x53
github.com/tiger/mygate/gate.init()
    <autogenerated>:1 +0xaa
main.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=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/requests

goroutine 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()
    <autogenerated>:1 +0x158 fp=0xc42007bef0 sp=0xc42007bec8 pc=0x9d9088
google.golang.org/grpc.init()
    <autogenerated>:1 +0x9b fp=0xc42007bf28 sp=0xc42007bef0 pc=0xa39eeb
vitess.io/vitess/go/vt/callinfo.init()
    <autogenerated>:1 +0x53 fp=0xc42007bf38 sp=0xc42007bf28 pc=0xa3c5d3
github.com/tiger/mygate/gate.init()
    <autogenerated>:1 +0xaa fp=0xc42007bf78 sp=0xc42007bf38 pc=0xba060a
main.init()
    <autogenerated>: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=0x457fa1

goroutine 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 +0x35

goroutine 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 +0x58

goroutine 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 +0x62

goroutine 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 +0x203

goroutine 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 +0x107

goroutine 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

吕信个人原创，转载请注明出处

最后编辑于：2018.08.15 16:11:41

人面猴
序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
沈念sama阅读 216,163评论 6赞 498
死咒
序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
沈念sama阅读 92,301评论 3赞 392
救了他两次的神仙让他今天三更去死
文/潘晓璐我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
开封第一讲书人阅读 162,089评论 0赞 352
道士缉凶录：失踪的卖姜人
文/不坏的土叔我叫张陵，是天一观的道长。经常有香客问我，道长，这世上最难降的妖魔是什么？我笑而不...
开封第一讲书人阅读 58,093评论 1赞 292
港岛之恋（遗憾婚礼）
正文为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
茶点故事阅读 67,110评论 6赞 388
恶毒庶女顶嫁案：这布局不是一般人想出来的
文/花漫我一把揭开白布。她就那样静静地躺着，像睡着了一般。火红的嫁衣衬着肌肤如雪。梳的纹丝不乱的头发上，一...
开封第一讲书人阅读 51,079评论 1赞 295
城市分裂传说
那天，我揣着相机与录音，去河边找鬼。笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。我是一名探鬼主播，决...
沈念sama阅读 40,005评论 3赞 417
双鸳鸯连环套：你想象不到人心有多黑
文/苍兰香墨我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
开封第一讲书人阅读 38,840评论 0赞 273
万荣杀人案实录
序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
沈念sama阅读 45,278评论 1赞 310
护林员之死
正文独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋以下内容为张勋视角年9月15日...
茶点故事阅读 37,497评论 2赞 332
白月光启示录
正文我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
茶点故事阅读 39,667评论 1赞 348
活死人
序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
沈念sama阅读 35,394评论 5赞 343
日本核电站爆炸内幕
正文年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
茶点故事阅读 40,980评论 3赞 325
男人毒药：我在死后第九天来索命
文/蒙蒙一、第九天我趴在偏房一处隐蔽的房顶上张望。院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
开封第一讲书人阅读 31,628评论 0赞 21
一桩弑父案，背后竟有这般阴谋
文/苍兰香墨我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。一阵脚步声响...
开封第一讲书人阅读 32,796评论 1赞 268
情欲美人皮
我被黑心中介骗来泰国打工，没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。一个月前我还...
沈念sama阅读 47,649评论 2赞 368
代替公主和亲
正文我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
茶点故事阅读 44,548评论 2赞 352

Golang控制panic stack trace的深度

缘起

解决方案

方案一：降低Golang版本

方案二：设置环境变量：export GOTRACEBACK=system

总结

参考

推荐阅读更多精彩内容