How to debug a panic stacktrace?

skruger · August 30, 2017, 8:06am

Are there any pointers on how to figure out what died when we see panics in the syslog?

Aug 30 08:00:16 ip-111-11-1-111 tyk-analytics[18661]: time=“Aug 30 08:00:16” level=warning msg=“Login opened from: 111.11.1.111:53446”
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: 2017/08/30 08:00:17 http: panic serving 203.125.62.60:57470: runtime error: invalid memory address or nil pointer dereference
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: goroutine 3634 [running]:
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: net/http.(*conn).serve.func1(0xc4209a5b80)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/usr/local/go/src/net/http/server.go:1721 +0xd0
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: panic(0xd155e0, 0x13ee420)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/usr/local/go/src/runtime/panic.go:489 +0x2cf
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: main.(*CoProcessor).ObjectPostProcess(0xc420740ea8, 0xc4209d9500, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/src/github.com/TykTechnologies/tyk/coprocess.go:138 +0x3e
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: main.(*CoProcessMiddleware).ProcessRequest(0xc42075b380, 0x133cba0, 0xc4202527e0, 0xc4209b5c00, 0xd374e0, 0xc42075b410, 0x1c, 0x0, 0x0)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/src/github.com/TykTechnologies/tyk/coprocess.go:281 +0x47f
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: main.CreateMiddleware.func1.1(0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/src/github.com/TykTechnologies/tyk/middleware.go:76 +0x65b
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: net/http.HandlerFunc.ServeHTTP(0xc420689400, 0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/usr/local/go/src/net/http/server.go:1942 +0x44
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: main.CreateMiddleware.func1.1(0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/src/github.com/TykTechnologies/tyk/middleware.go:100 +0x85b
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: net/http.HandlerFunc.ServeHTTP(0xc420689440, 0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/usr/local/go/src/net/http/server.go:1942 +0x44
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: main.CreateMiddleware.func1.1(0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/src/github.com/TykTechnologies/tyk/middleware.go:100 +0x85b
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: net/http.HandlerFunc.ServeHTTP(0xc420689480, 0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/usr/local/go/src/net/http/server.go:1942 +0x44
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: main.CreateMiddleware.func1.1(0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/src/github.com/TykTechnologies/tyk/middleware.go:100 +0x85b
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: net/http.HandlerFunc.ServeHTTP(0xc4206894c0, 0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/usr/local/go/src/net/http/server.go:1942 +0x44
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: main.CreateMiddleware.func1.1(0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/src/github.com/TykTechnologies/tyk/middleware.go:100 +0x85b
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: net/http.HandlerFunc.ServeHTTP(0xc420689500, 0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/usr/local/go/src/net/http/server.go:1942 +0x44
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: github.com/TykTechnologies/tyk/vendor/github.com/gorilla/context.ClearHandler.func1(0x133cba0, 0xc4202527e0, 0xc4209b5c00)
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: #011/src/github.com/TykTechnologies/tyk/vendor/github.com/gorilla/context/context.go:141 +0x8b
Aug 30 08:00:17 ip-111-11-1-111 tyk[27800]: net/http.HandlerFunc.ServeHTTP(0xc42082f000, 0x133cba0, 0xc4202527e0, 0xc4209b5c00)

Martin · August 30, 2017, 8:29am

Usually a go panic is more verbose than this - it looks like half the stack trace is missing?

Is this from a log file or from the process? One thing yu could try is to run the gateway directly with

./tyk --conf=/opt/tyk-gateway/tyk.conf

Then try the request again…

matiasb · August 30, 2017, 8:30am

Hi, do you get any log line with the “Python” keyword before/after these lines?

skruger · August 30, 2017, 11:10am

Not that I could see - here is the full trace from restart till error :

Aug 30 07:58:40 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:40” level=info msg=“Setting up analytics normaliser”
Aug 30 07:58:40 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:40” level=info msg=“PIDFile location set to: ./tyk-gateway.pid”
Aug 30 07:58:40 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:40” level=error msg=“Instrumentation is enabled, but no connectionstring set for statsd”
Aug 30 07:58:40 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:40” level=info msg=“Control API hostname set: ec2-34-205-122-77.compute-1.amazonaws.com”
Aug 30 07:58:40 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:40” level=info msg=“Initialising Tyk REST API Endpoints”
Aug 30 07:58:40 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:40” level=info msg=“–> Standard listener (http)”
Aug 30 07:58:40 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:40” level=info msg=“Setting up Server”
Aug 30 07:58:40 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:40” level=info msg=“Waiting for zeroconf signal…”
Aug 30 07:58:41 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:41” level=warning msg=“Insecure configuration detected (allowing)!”
Aug 30 07:58:41 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:41” level=info msg=“Hostname set with dashboard zeroconf signal”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Registering node.”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Node registered” id=84c06505-ada2-45cd-4b6f-c19b6abd6dfe
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Initialising distributed rate limiter”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Starting gateway rate imiter notifications…”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Detected 2 APIs”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“API hostname set: ec2-34-205-122-77.compute-1.amazonaws.com”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Loading API configurations.”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Tracking hostname” api_name=“Partner API” domain=“(no host)”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Tracking hostname” api_name=“Partner API 2” domain=“(no host)”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Loading API” api_name=“Partner API”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Checking security policy: Open” api_name=“Partner API”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Loaded: Partner API” api_id=c35aa58757d945f45ce5d3a4ae56a689 org_id=59818dd38326eb5cef645cd4 server_name=-- user_id=-- user_ip=–
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Loading API” api_name=“Partner API 2”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Loading existing bundle: bundle.zip”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“----> Loading bundle: bundle.zip”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“----> Using bundle: bundle.zip”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Checking security policy: CoProcess Plugin” api_name=“Partner API 2”
Aug 30 07:58:42 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:42” level=info msg=“Loaded: Partner API 2” api_id=3bd1804e2d6b4b5840de13b433b7f5e8 org_id=59818dd38326eb5cef645cd4 server_name=-- user_id=-- user_ip=–
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“Processed and listening on: /v1{rest:.}"
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg="Processed and listening on: /v2{rest:.}”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“Loading uptime tests…”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“—> Adding uptime test: http://ec2-34-205-122-77.compute-1.amazonaws.com:3000”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“—> Adding uptime test: http://ec2-34-205-122-77.compute-1.amazonaws.com:3000”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“Initialised API Definitions”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“Loading policies”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“Using Policies from Dashboard Service”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“Mutex lock acquired… calling”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“Calling dashboard service for policy list”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“Processing policy list”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“–> Processing policy ID: 5981a99f8326eb5cef645cdb”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“Gateway started (v2.3.8)”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“–> Listening on address: (open interface)”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“–> Listening on port: 80”
Aug 30 07:58:43 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:43” level=info msg=“–> PID: 27800”
Aug 30 07:58:45 ip-111-11-1-111 tyk-analytics[18661]: time=“Aug 30 07:58:45” level=info msg=“Sending config request for node: 84c06505-ada2-45cd-4b6f-c19b6abd6dfe-ip-111-11-1-111”
Aug 30 07:58:45 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:45” level=info msg=“Using /opt/tyk-gateway/tyk.conf for configuration”
Aug 30 07:58:45 ip-111-11-1-111 tyk-analytics[18661]: time=“Aug 30 07:58:45” level=info msg=“Got configuration for nodeID: 84c06505-ada2-45cd-4b6f-c19b6abd6dfe|ip-111-11-1-111”
Aug 30 07:58:50 ip-111-11-1-111 tyk[27800]: time=“Aug 30 07:58:50” level=info msg=“Starting Poller”
Aug 30 07:58:50 ip-111-11-1-111 tyk-analytics[18661]: time=“Aug 30 07:58:50” level=warning msg=“Login opened from: 111.11.1.111:53426”
Aug 30 07:59:00 ip-111-11-1-111 tyk-analytics[18661]: time=“Aug 30 07:59:00” level=warning msg=“Login opened from: 111.11.1.111:53430”
Aug 30 07:59:07 ip-111-11-1-111 tyk-analytics[18661]: time=“Aug 30 07:59:07” level=warning msg=“Login opened from: 111.11.1.111:53432”
Aug 30 07:59:16 ip-111-11-1-111 tyk-analytics[18661]: time=“Aug 30 07:59:16” level=warning msg=“Login opened from: 111.11.1.111:53434”
Aug 30 07:59:26 ip-111-11-1-111 tyk-analytics[18661]: time=“Aug 30 07:59:26” level=warning msg=“Login opened from: 111.11.1.111:53436”
Aug 30 07:59:28 ip-111-11-1-111 tyk[27800]: 2017/08/30 07:59:28 http: panic serving 203.125.62.60:57461: runtime error: invalid memory address or nil pointer dereference
Aug 30 07:59:28 ip-111-11-1-111 tyk[27800]: goroutine 2098 [running]:

matiasb · August 30, 2017, 5:01pm

Thanks, do you get this error everytime? Can you point some of the middleware or request characteristics?
It might be caused by a bad response object.

christyk · March 30, 2020, 2:43pm