Go代码bug深入跟踪一例

2015-02-05

重构以前一个项目的代码，改动比较大，测试的时候出现一个bug。精简到最极致的复现方式是这样子的：

package main import ( "fmt" "github.com/gorilla/context" "github.com/gorilla/mux" "net/http" )

func main() { r := mux.NewRouter() r.HandleFunc("/", helloworld) http.ListenAndServe(":8080", r) }

func helloworld(w http.ResponseWriter, r *http.Request) { fmt.Println("hello world") input := context.Get(r, main) fmt.Println("never run here", input) }

从那一坨坨的业务代码中，定位到这个级别的复现，还是颇费了一番工夫的。

上面的程序，表现形式是，请求http://localhost:8080/之后整个程序都会挂起，不会打印"never run here"，程序不再接受任何请求。如果写了其它 的router，也不会响应的。

也许很多人能走到这一步，就已经开开心心的给gorilla提bug去了。但是，那样就不能算本文标题中的“深入跟踪”了。也许，读者对bug深入研究不感兴趣，那么... TL;DR

程序无响应最可能的两种情况，一种是死循环了，另一种是死锁了。查看CPU使用率很低，不像是死循环的样子。然后去读gorilla库的代码，有看到使用mutex，初步推测可能有死锁。

程序是运行到了context.Get后出问题的，这里是context.Get的源代码，乍看之下并没有发现什么问题：

func Get(r *http.Request, key interface{}) interface{} { mutex.RLock() if ctx := data[r]; ctx != nil { value := ctx[key] mutex.RUnlock() return value } mutex.RUnlock() return nil }

我加了几行print之后，发现是在ctx[key]这里没有再返回。

然后开始猜测，这一行并不是channel操作，理论上是不应该发生不再返回的情况的。难道map操作引起goroutine切换，然后什么场景下能触发到死锁让这个goroutine再也得不到调度？

现在要判定是gorilla的问题还是Go本身的问题。

我把mux换成标准库的mux后，好像一切正常：

func main() { http.HandleFunc("/", helloworld) http.ListenAndServe(":8080", nil) }

分析到这里卡了好久，直到我觉得，既然应该是跟mutex相关的，那我去掉试试。我把gorilla库中的mutex那几行代码注释掉了，然后真相大白：发现ctx[key]不返回的原因是这个goroutine挂掉了，不是死锁。

2015/02/05 12:21:10 http: panic serving [::1]:64076: runtime error: hash of unhashable type func(http.ResponseWriter, *http.Request) goroutine 7 [running]: net/http.func·011() /usr/local/Cellar/go/1.4.1/libexec/src/net/http/server.go:1130 +0xbb github.com/gorilla/context.Get(0xc208032a90, 0x246fe0, 0x368c30, 0x0, 0x0) /Users/genius/project/src/github.com/gorilla/context/context.go:39 +0x3b8 main.helloworld(0x713068, 0xc2080445a0, 0xc208032a90) /Users/genius/project/test/panic.go:22 +0x11b net/http.HandlerFunc.ServeHTTP(0x368c30, 0x713068, 0xc2080445a0, 0xc208032a90) /usr/local/Cellar/go/1.4.1/libexec/src/net/http/server.go:1265 +0x41 github.com/gorilla/mux.(*Router).ServeHTTP(0xc2080400a0, 0x713068, 0xc2080445a0, 0xc208032a90) /Users/genius/project/src/github.com/gorilla/mux/mux.go:98 +0x2b9 net/http.serverHandler.ServeHTTP(0xc20805c120, 0x713068, 0xc2080445a0, 0xc208032a90) /usr/local/Cellar/go/1.4.1/libexec/src/net/http/server.go:1703 +0x19a net/http.(*conn).serve(0xc208044500)

但是为什么没有打印panic信息？好坑爹!

初步结论：gorilla库中有用到一个全局mutex，如果某个goroutine获取锁后panic掉，没能释放锁，会导致程序不再处理任何请求。(而且由于这个锁的原因，不会打印panic ???)

也许很多人觉得能找到这里，就已经很开心了，可以停下来。但是，为什么会panic呢？不继续找出原因，就不能算本文标题中的“深入跟踪”。

其实到上面为止，我还是没找出到底是谁的错，gorilla或是Go自身？who's to blame。问题的关键在于为什么panic。

从panic信息来分析，runtime error: hash of unhashable type。gorilla的context底层是用的一个map[interface{}]interface{}的结构，然后我传入一个helloworld函数指针作为key，怎么就panic了？

首先，我想要更简单的重现这个panic。于是试了一下:

m := make(map[interface{}]interface{}) v := m[main]

确实是会panic的。难道函数不能作为map的key吗？看看Go的语言规范怎么说。

The comparison operators == and != must be fully defined for operands of the key type; thus the key type must not be a function, map, or slice. If the key type is an interface type, these comparison operators must be defined for the dynamic key values; failure will cause a run-time panic.

我勒个擦，函数是不能作为Go语言中map的key的...是我的错。

为什么Go语言中函数不能比较操作呢？这个话题跟本文跟踪bug无关，要写也是下一篇了～

另：Go语言规范说用不合规范的interface做key会panic，这个行为目前应该是未定义的。比如在目前Go1.4.1上，这一段代码就不会panic：

func main() { m := make(map[interface{}]interface{}) m[main] = 5 }

至于gorilla，不看底层实现并不知道context.Get是不能用函数作为key的。还有崩溃了没有panic打印的问题。gorilla的这种行为是否算是bug，就看各人怎么想了。我没有去提交issue，如果有人认定是bug，去帮忙提一下也无妨。