Problem
I am occasionally getting the error http: panic serving 127.0.0.1:52703: assignment to entry in nil map
2015/06/18 15:10:00 http: panic serving 127.0.0.1:52703: assignment to entry in nil map
goroutine 98 [running]:
net/http.func路011()
/home/ian/go/src/net/http/server.go:1130 +0xbb
github.com/go-zoo/bone.(*Route).Match(0xc20808d9a0, 0xc2081581a0, 0xc208152900)
/home/ian/code/tester/src/github.com/go-zoo/bone/route.go:102 +0x523
github.com/go-zoo/bone.(*Mux).ServeHTTP(0xc2080c2ca0, 0x7f1d53fa5860, 0xc20807c5a0, 0xc2081581a0)
/home/ian/code/tester/src/github.com/go-zoo/bone/bone.go:55 +0x5ec
net/http.serverHandler.ServeHTTP(0xc20808ecc0, 0x7f1d53fa5860, 0xc20807c5a0, 0xc2081581a0)
/home/ian/go/src/net/http/server.go:1703 +0x19a
net/http.(*conn).serve(0xc2080b2460)
/home/ian/go/src/net/http/server.go:1204 +0xb57
created by net/http.(*Server).Serve
/home/ian/go/src/net/http/server.go:1751 +0x35e
This only happens intermittently and seemed to be only when the server had many simultaneous requests to the same url (but different parameters), eg calling /test/:id/result
with ids 0-100 asynchronously via ajax.
Cause
The initial search for the cause was in route.go#L102 which is assigning a variable in a map created on L91. But between L91 and L102 the map was apparently being deleted somehow.
The deletion happens in bone.go#L56. I figured possibly the key was not unique across requests. So I tested it.
It turns out the request pointers are not unique in some circumstances. By logging just before delete(vars, token)
in bone.go#L56 it was revealed that the same pointer is used for multiple requests (see full log below).
Solution
The solution is to make each request unique and use the unique key in the map, not the pointer.
edit: This did not solve it. See pull request below for the solution using locks.
In some proof-of-concept code I wrote I added a unique token to each request (by adding a unique header to the request) just before r.Match(req)
is called (bone.go#L54).
Then instead of using *http.Request
as the key for vars
, change the key to be a string
and use the unique request header value instead of the request itself.
This has fixed the issue.
I can submit a pull request if you like.
Full log
Log that shows reuse of pointers.
Before bone.go#L56 add log.Println(&req, req.URL.Path)
2015/06/18 15:09:58 0xc208120030 /api/v1/test/3/inputs
2015/06/18 15:09:58 0xc208030068 /api/v1/test/3/results
2015/06/18 15:09:58 0xc2080ec070 /api/v1/test/4/results
2015/06/18 15:09:58 0xc2080ec0a8 /api/v1/test/4/inputs
2015/06/18 15:09:58 0xc2080ec0b0 /api/v1/test/2/results
2015/06/18 15:09:58 0xc20816c000 /api/v1/test/5/inputs
2015/06/18 15:09:58 0xc2080ec0b8 /api/v1/test/2/inputs
2015/06/18 15:09:58 0xc208120038 /api/v1/test/5/results
2015/06/18 15:09:58 0xc208030028 /api/v1/test/6/results
2015/06/18 15:09:58 0xc208030048 /api/v1/test/6/inputs
2015/06/18 15:09:58 0xc2080ec070 /api/v1/test/1/inputs
2015/06/18 15:09:59 0xc208120050 /api/v1/test/8/results
2015/06/18 15:09:59 0xc2080ec0e0 /api/v1/test/9/results
2015/06/18 15:09:59 0xc2080ec010 /api/v1/test/7/inputs
2015/06/18 15:09:59 0xc2080ec0c0 /api/v1/test/7/results
2015/06/18 15:09:59 0xc2080ec068 /api/v1/test/1/results
2015/06/18 15:09:59 0xc2080ec0c8 /api/v1/test/8/inputs
2015/06/18 15:09:59 0xc20816c028 /api/v1/test/9/inputs
2015/06/18 15:09:59 0xc208030040 /api/v1/test/10/results
2015/06/18 15:09:59 0xc20816c040 /api/v1/test/10/inputs
2015/06/18 15:09:59 0xc20816c058 /api/v1/test/11/inputs
2015/06/18 15:09:59 0xc208030060 /api/v1/test/11/results
2015/06/18 15:09:59 0xc208030070 /api/v1/test/12/results
2015/06/18 15:09:59 0xc208120058 /api/v1/test/13/results
2015/06/18 15:09:59 0xc208030090 /api/v1/test/12/inputs
2015/06/18 15:09:59 0xc2080300a0 /api/v1/test/14/inputs
2015/06/18 15:09:59 0xc2080ec028 /api/v1/result/14/detail
2015/06/18 15:09:59 0xc2080ec018 /api/v1/result/13/detail
2015/06/18 15:09:59 0xc20816c068 /api/v1/test/14/results
2015/06/18 15:09:59 0xc208030020 /api/v1/result/15/detail
2015/06/18 15:09:59 0xc208120060 /api/v1/test/13/inputs
2015/06/18 15:09:59 0xc2080ec070 /api/v1/result/11/detail
2015/06/18 15:09:59 0xc2080ec078 /api/v1/result/12/detail
2015/06/18 15:09:59 0xc208120020 /api/v1/result/10/detail
2015/06/18 15:09:59 0xc208030038 /api/v1/result/2/detail
2015/06/18 15:09:59 0xc208030040 /api/v1/result/3/detail
2015/06/18 15:09:59 0xc208120058 /api/v1/result/4/detail
2015/06/18 15:09:59 0xc208120068 /api/v1/result/5/detail
2015/06/18 15:09:59 0xc2080ec0a0 /api/v1/result/6/detail
2015/06/18 15:09:59 0xc208030060 /api/v1/result/7/detail
2015/06/18 15:09:59 0xc208120080 /api/v1/result/8/detail
2015/06/18 15:09:59 0xc2080ec0d8 /api/v1/result/9/detail
2015/06/18 15:10:00 0xc2081200a0 /api/v1/test/3/results
2015/06/18 15:10:00 0xc20816c010 /api/v1/test/3/inputs
2015/06/18 15:10:00 0xc208030020 /api/v1/test/4/results
2015/06/18 15:10:00 0xc208030048 /api/v1/test/2/results
2015/06/18 15:10:00 0xc208030040 /api/v1/test/4/inputs
2015/06/18 15:10:00 0xc208030058 /api/v1/test/2/inputs
2015/06/18 15:10:00 0xc2080ec028 /api/v1/test/5/inputs
2015/06/18 15:10:00 0xc208120038 /api/v1/test/5/results
2015/06/18 15:10:00 http: panic serving 127.0.0.1:52703: assignment to entry in nil map
goroutine 98 [running]:
net/http.func路011()
/home/ian/go/src/net/http/server.go:1130 +0xbb
github.com/go-zoo/bone.(*Route).Match(0xc20808d9a0, 0xc2081581a0, 0xc208152900)
/home/ian/code/tester/src/github.com/go-zoo/bone/route.go:102 +0x523
github.com/go-zoo/bone.(*Mux).ServeHTTP(0xc2080c2ca0, 0x7f1d53fa5860, 0xc20807c5a0, 0xc2081581a0)
/home/ian/code/tester/src/github.com/go-zoo/bone/bone.go:55 +0x5ec
net/http.serverHandler.ServeHTTP(0xc20808ecc0, 0x7f1d53fa5860, 0xc20807c5a0, 0xc2081581a0)
/home/ian/go/src/net/http/server.go:1703 +0x19a
net/http.(*conn).serve(0xc2080b2460)
/home/ian/go/src/net/http/server.go:1204 +0xb57
created by net/http.(*Server).Serve
/home/ian/go/src/net/http/server.go:1751 +0x35e
2015/06/18 15:10:00 0xc208030068 /api/v1/test/6/results
2015/06/18 15:10:01 0xc208120060 /api/v1/test/1/results
2015/06/18 15:10:01 0xc20816c040 /api/v1/test/1/inputs
2015/06/18 15:10:01 0xc208120038 /api/v1/test/7/results
2015/06/18 15:10:01 0xc208120050 /api/v1/test/7/inputs
2015/06/18 15:10:01 0xc208030030 /api/v1/test/8/results
2015/06/18 15:10:01 0xc208030048 /api/v1/test/8/inputs
2015/06/18 15:10:01 0xc208030068 /api/v1/test/9/results
2015/06/18 15:10:01 0xc208030078 /api/v1/test/10/results
2015/06/18 15:10:01 0xc208120088 /api/v1/test/9/inputs
2015/06/18 15:10:01 0xc2081200a8 /api/v1/test/11/results
2015/06/18 15:10:01 0xc2080300a0 /api/v1/test/11/inputs
2015/06/18 15:10:01 0xc2081200c0 /api/v1/test/12/results
2015/06/18 15:10:01 0xc2080300b0 /api/v1/test/12/inputs
2015/06/18 15:10:01 0xc2080ec008 /api/v1/test/10/inputs
2015/06/18 15:10:01 0xc2080300b8 /api/v1/test/13/results
2015/06/18 15:10:01 0xc208030020 /api/v1/result/13/detail
2015/06/18 15:10:01 0xc20816c020 /api/v1/test/13/inputs
2015/06/18 15:10:01 0xc208030048 /api/v1/test/14/inputs
2015/06/18 15:10:01 0xc208030058 /api/v1/result/14/detail
2015/06/18 15:10:01 0xc2080ec010 /api/v1/test/14/results
2015/06/18 15:10:01 0xc208120030 /api/v1/result/15/detail
2015/06/18 15:10:01 0xc20816c008 /api/v1/result/11/detail
2015/06/18 15:10:01 0xc20816c040 /api/v1/result/12/detail
2015/06/18 15:10:01 0xc20816c048 /api/v1/result/2/detail
2015/06/18 15:10:01 0xc20816c060 /api/v1/result/3/detail
2015/06/18 15:10:01 0xc208120050 /api/v1/result/4/detail
2015/06/18 15:10:01 0xc208120068 /api/v1/result/5/detail
2015/06/18 15:10:01 0xc20816c078 /api/v1/result/6/detail
2015/06/18 15:10:01 0xc20816c090 /api/v1/result/7/detail
2015/06/18 15:10:01 0xc20816c0b8 /api/v1/result/8/detail
2015/06/18 15:10:01 0xc2080ec020 /api/v1/result/9/detail
2015/06/18 15:10:01 0xc208120000 /api/v1/result/10/detail