bbs: invalid memory address or nil pointer dereference

[paolostivanin]

Hello,
we saw a problem with the bbs process on our database_z2/0 vm (all Diego apps went down for ~15min). Basically, according to monit the process was "running" but, looking at the logs, we saw the following error:

 http: panic serving $IP:$PORT: runtime error: invalid memory address or nil pointer dereference
goroutine 69969 [running]:
net/http.(*conn).serve.func1(0xc421b17c00)
        /var/vcap/data/packages/golang/65a8c296d8c2319d411165f5dc837a63b3846c7b.1-00ec6370feac3239ea93612eaa1d289ddee2c031/src/net/http/server.go:1491 +0x12a
panic(0xb6d600, 0xc420014050)
        /var/vcap/data/packages/golang/65a8c296d8c2319d411165f5dc837a63b3846c7b.1-00ec6370feac3239ea93612eaa1d289ddee2c031/src/runtime/panic.go:458 +0x243
code.cloudfoundry.org/bbs/handlers.(*EvacuationHandler).EvacuateRunningActualLRP(0xc42019ca20, 0xfc85c0, 0xc4219c5ec0, 0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/packages/bbs/src/code.cloudfoundry.org/bbs/handlers/evacuation_handler.go:236 +0x966
code.cloudfoundry.org/bbs/handlers.(*EvacuationHandler).EvacuateRunningActualLRP-fm(0xfc85c0, 0xc4219c5e00, 0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/packages/bbs/src/code.cloudfoundry.org/bbs/handlers/handlers.go:75 +0x5c
code.cloudfoundry.org/bbs/handlers/middleware.LogWrap.func3(0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/packages/bbs/src/code.cloudfoundry.org/bbs/handlers/middleware/middleware.go:49 +0x1d5
code.cloudfoundry.org/bbs/handlers/middleware.LatencyEmitter.EmitLatency.func1(0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/packages/bbs/src/code.cloudfoundry.org/bbs/handlers/middleware/middleware.go:68 +0x8c
net/http.HandlerFunc.ServeHTTP(0xc420211cc0, 0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/data/packages/golang/65a8c296d8c2319d411165f5dc837a63b3846c7b.1-00ec6370feac3239ea93612eaa1d289ddee2c031/src/net/http/server.go:1726 +0x44
github.com/bmizerany/pat.(*PatternServeMux).ServeHTTP(0xc420026430, 0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/packages/bbs/src/github.com/bmizerany/pat/mux.go:109 +0x5de
code.cloudfoundry.org/bbs/handlers.(*UnavailableHandler).ServeHTTP(0xc42021a720, 0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/packages/bbs/src/code.cloudfoundry.org/bbs/handlers/unavailable_handler.go:22 +0x85
code.cloudfoundry.org/bbs/handlers.UnavailableWrap.func1(0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/packages/bbs/src/code.cloudfoundry.org/bbs/handlers/unavailable_handler.go:32 +0x4d
net/http.HandlerFunc.ServeHTTP(0xc42021a740, 0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/data/packages/golang/65a8c296d8c2319d411165f5dc837a63b3846c7b.1-00ec6370feac3239ea93612eaa1d289ddee2c031/src/net/http/server.go:1726 +0x44
code.cloudfoundry.org/bbs/handlers/middleware.RequestCountWrap.func1(0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/packages/bbs/src/code.cloudfoundry.org/bbs/handlers/middleware/middleware.go:79 +0x7a
net/http.HandlerFunc.ServeHTTP(0xc42021a760, 0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/data/packages/golang/65a8c296d8c2319d411165f5dc837a63b3846c7b.1-00ec6370feac3239ea93612eaa1d289ddee2c031/src/net/http/server.go:1726 +0x44
net/http.serverHandler.ServeHTTP(0xc4202a2680, 0xfc44e0, 0xc42070ac30, 0xc42394f770)
        /var/vcap/data/packages/golang/65a8c296d8c2319d411165f5dc837a63b3846c7b.1-00ec6370feac3239ea93612eaa1d289ddee2c031/src/net/http/server.go:2202 +0x7d
net/http.(*conn).serve(0xc421b17c00, 0xfc5060, 0xc421edf200)
        /var/vcap/data/packages/golang/65a8c296d8c2319d411165f5dc837a63b3846c7b.1-00ec6370feac3239ea93612eaa1d289ddee2c031/src/net/http/server.go:1579 +0x4b7
created by net/http.(*Server).Serve
        /var/vcap/data/packages/golang/65a8c296d8c2319d411165f5dc837a63b3846c7b.1-00ec6370feac3239ea93612eaa1d289ddee2c031/src/net/http/server.go:2293 +0x44d

Any idea what could have caused this?

PS: we are using CF 249 and Diego 1.2.0 on AWS and postgres as data store instead of etcd

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/139675175

The labels on this github issue will be updated when the story is started.

[paolostivanin]

The IPs written on the log are cell_z1 VMs.

[crhino]

@paolostivanin Taking a look at the stack trace. We are interested by what you mean when you say all Diego apps were down for 15 minutes. Were the app's routes unavailable (returning a 404), or something else?

Can we have some context about what was happening at this point in time? Was there a deploy happening? Do you have logs from that cell_z1 VM?

[crhino]

@paolostivanin For the panic, this story has implemented a fix. That should not have caused any application downtime though.

[jvshahid]

just to be redundant, the commit that fixed this is e78a747 and is part of diego starting from version 1.5.2. Like @crhino I'm interested in understanding how that could've resulted in the apps going down.