Index out of range during expression eval

[gunnihinn]

I see this error in carbonapi.log on one of our hosts:

{
  "level": "ERROR",
  "timestamp": "2018-05-09T16:30:15.181+0200",
  "logger": "render",
  "message": "panic during eval:",
  "cache_key": "format=json&from=1525872253&maxDataPoints=100&target=movingAverage%28scaleToSeconds%28highestMax%28nonNegativeDerivative%28carbon.relays.%2A.metricsQueued%29%
2C+1%29%2C+1%29%2C+%275min%27%29&until=1525875973",
  "reason": "runtime error: index out of range",
  "stack": [see below]
}

Stack trace:

main.renderHandler.func2.1
    /home/redacted/go/src/github.com/go-graphite/carbonapi/http_handlers.go:348
runtime.call32
    /usr/lib64/go/src/runtime/asm_amd64.s:573
runtime.gopanic
    /usr/lib64/go/src/runtime/panic.go:505
runtime.panicindex
    /usr/lib64/go/src/runtime/panic.go:28
github.com/go-graphite/carbonapi/expr/functions/moving.(*moving).Do
    /home/redacted/go/src/github.com/go-graphite/carbonapi/expr/functions/moving/function.go:72
github.com/go-graphite/carbonapi/expr.EvalExpr
    /home/redacted/go/src/github.com/go-graphite/carbonapi/expr/expr.go:46
main.renderHandler.func2
    /home/redacted/go/src/github.com/go-graphite/carbonapi/http_handlers.go:352
main.renderHandler
    /home/redacted/go/src/github.com/go-graphite/carbonapi/http_handlers.go:360
net/http.HandlerFunc.ServeHTTP
    /usr/lib64/go/src/net/http/server.go:1947
net/http.(*ServeMux).ServeHTTP
    /usr/lib64/go/src/net/http/server.go:2337
github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers.CompressHandlerLevel.func1
    /home/redacted/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/compress.go:146
net/http.HandlerFunc.ServeHTTP
    /usr/lib64/go/src/net/http/server.go:1947
github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers.(*cors).ServeHTTP
    /home/redacted/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/cors.go:51
github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers.ProxyHeaders.func1
    /home/redacted/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/proxy_headers.go:59
net/http.HandlerFunc.ServeHTTP
    /usr/lib64/go/src/net/http/server.go:1947
net/http.serverHandler.ServeHTTP
    /usr/lib64/go/src/net/http/server.go:2694
net/http.(*conn).serve
    /usr/lib64/go/src/net/http/server.go:1830

This issue is mostly a reminder to myself to debug this further. The first step should be to recover from that panic and dump the data that's causing it to disk so we can stare at it.

[hanzhinstas]

This issue also affects me, it happens from time to time and I see no chance to debug it.

Jun  1 03:53:01 graphite-sv-lx-01 carbonapi[7882]: 2018-06-01T03:53:01.653Z#011ERROR#011render#011panic during eval:#011{"cache_key": "format=json&from=-5min&maxDataPoints=500&target=aliasByNode%28hitcount%28stats.counters.production.yupmaster.error.unknown_launcher_project.%2A.rate%2C+%271min%27%29%2C+5%2C+6%29&until=now", "reason": "runtime error: index out of range", "stack": "main.renderHandler.func3.1\n\t/root/go/src/github.com/go-graphite/carbonapi/http_handlers.go:408\nruntime.call32\n\t/usr/local/go/src/runtime/asm_amd64.s:509\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:491\nruntime.panicindex\n\t/usr/local/go/src/runtime/panic.go:28\ngithub.com/go-graphite/carbonapi/expr/functions/hitcount.(*hitcount).Do\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/functions/hitcount/function.go:53\ngithub.com/go-graphite/carbonapi/expr.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:46\ngithub.com/go-graphite/carbonapi/expr.evaluator.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:17\ngithub.com/go-graphite/carbonapi/expr.(*evaluator).EvalExpr\n\t<autogenerated>:1\ngithub.com/go-graphite/carbonapi/expr/helper.GetSeriesArg\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/helper/helper.go:43\ngithub.com/go-graphite/carbonapi/expr/functions/aliasByNode.(*aliasByNode).Do\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/functions/aliasByNode/function.go:30\ngithub.com/go-graphite/carbonapi/expr.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:46\nmain.renderHandler.func3\n\t/root/go/src/github.com/go-graphite/carbonapi/http_handlers.go:412\nmain.renderHandler\n\t/root/go/src/github.com/go-graphite/carbonapi/http_handlers.go:420\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\nnet/http.(*ServeMux).ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2254\ngithub.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers.CompressHandlerLevel.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/compress.go:146\nnet/http.HandlerFu
Jun  1 03:53:01 graphite-sv-lx-01 carbonapi[7882]: nc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\ngithub.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers.(*cors).ServeHTTP\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/cors.go:51\ngithub.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers.ProxyHeaders.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/proxy_headers.go:59\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1918\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2619\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1801"}

[hanzhinstas]

And it seems to be the same with #302 and #186

[gunnihinn]

Ack. This is on my stack, but there are higher-priority issues before it in line.

[hanzhinstas]

@gunnihinn any news on this? May there be a fix in booking.com fork?

[Civil]

Issue is quite old, since then there was a commit that should fix it: a94b484#diff-2ed1bb34a4e0bd489fb6a97a4300aede

As when the issue was open, line 72 was:

71	if scaleByStep {
72		windowSize /= int(arg[0].StepTime)
73		offset = windowSize
74	}

So the panic with "index out of range" message might occur only if len(arg) == 0 and there is no arg[0], which was fixed by the commit I've referenced above.

[Civil]

If you have a reproduction based on current master - please update the issue (likely it won't be possible to get this panic anymore).

However I'd need at least following information:

1. stacktrace of a panic
2. panic message
3. query
4. some information about the data (were there nulls? did all the series have the same length?)

[cjagus]

Still noticing the same issue on current master @Civil

2019-03-22T22:14:27.461Z ERROR render panic during eval: {"carbonapi_uuid": "adb0f4cb-5db7-41bf-9f85-e9f1e99dab7c", "username": "", "cache_key": "format=json&from=-7d&maxDataPoints=960&target=groupByNode%28sortByMaxima%28apps.webserver.entity-%2A.counters.flask.%2A.entity.%2A.%2A.count%29%2C+7%2C+%27sum%27%29&until=-2min", "reason": "runtime error: index out of range", "stack": "github.com/go-graphite/carbonapi/cmd/carbonapi/http.renderHandler.func2.1\n\t/root/go/src/github.com/go-graphite/carbonapi/cmd/carbonapi/http/render_handler.go:287\nruntime.call32\n\t/usr/local/go/src/runtime/asm_amd64.s:522\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:513\nruntime.panicindex\n\t/usr/local/go/src/runtime/panic.go:44\ngithub.com/go-graphite/carbonapi/expr/helper.AggregateSeries\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/helper/helper.go:199\ngithub.com/go-graphite/carbonapi/expr/functions/sum.(*sum).Do\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/functions/sum/function.go:37\ngithub.com/go-graphite/carbonapi/expr.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:46\ngithub.com/go-graphite/carbonapi/expr.evaluator.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:17\ngithub.com/go-graphite/carbonapi/expr/functions/groupByNode.(*groupByNode).Do\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/functions/groupByNode/function.go:109\ngithub.com/go-graphite/carbonapi/expr.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:46\ngithub.com/go-graphite/carbonapi/cmd/carbonapi/http.renderHandler.func2\n\t/root/go/src/github.com/go-graphite/carbonapi/cmd/carbonapi/http/render_handler.go:291\ngithub.com/go-graphite/carbonapi/cmd/carbonapi/http.renderHandler\n\t/root/go/src/github.com/go-graphite/carbonapi/cmd/carbonapi/http/render_handler.go:299\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/go-graphite/carbonapi/util/ctx.ParseCtx.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/util/ctx/ctx.go:43\ngithub.com/go-graphite/carbonapi/vendor/github.com/dgryski/httputil.TimeHandler.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/dgryski/httputil/times.go:26\ngithub.com/go-graphite/carbonapi/vendor/github.com/dgryski/httputil.TrackConnections.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/dgryski/httputil/track.go:40\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\nnet/http.(*ServeMux).ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2361\ngithub.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers.CompressHandlerLevel.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/compress.go:146\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\ngithub.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers.(*cors).ServeHTTP\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/cors.go:52\ngithub.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers.ProxyHeaders.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/proxy_headers.go:59\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:1964\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2741\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1847"} 2019-03-22T22:14:27.461Z INFO render empty response or no response {"carbonapi_uuid": "adb0f4cb-5db7-41bf-9f85-e9f1e99dab7c", "username": ""}

[Civil]

@cjagus it seems that your case is related to a different issue like #186

TLDR; carbonapi currently assume that all Metrics for the function will have same resolution, if they don't - it won't extrapolate or interpolate them as graphite-web do, and that likely causes your panic to appear. It's a long known issue, but different from the one that's discussed here.

[Civil]

This should be obsolete and work better after #496

If this still happens with current master or newer, please open new bug with stacktraces and/or test cases.