carbonapi icon indicating copy to clipboard operation
carbonapi copied to clipboard
verified publisher icon go-graphite

[BUG] Index out of range

Open keliss opened this issue 4 years ago • 6 comments

Describe the bug Hi. I'm using carbonapi with victoria metrics and seeing that some charts don't get rendered from time to time with a 500 error caused by a panic on "index out of range".

CarbonAPI Version carbonapi-0.15.4~1-1

Logs ERROR render panic during eval: {"carbonapi_uuid": "261e4d03-b470-4ba4-8bd5-ba7dbe5f39a9", "username": "", "request_headers": {}, "cache_key": "format=json&from=-3h&maxDataPoints=1212&target=exclude%28aliasByNode%28sumSeriesWithWildcards%28keepLastValue%28removeAbovePercentile%28scaleToSeconds%28nonNegativeDerivative%28metric.ssp-aggregated.prod.%2A.dc.service.%2A.%2A.display.sum.values.%2A.value_type.count%29%2C+1%29%2C+99.5%29%2C+1000%29%2C+4%2C+5%2C+6%2C+3%29%2C+7%29%2C+%27all%27%29&until=now", "reason": "runtime error: index out of range [220] with length 220", "stack": "github.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:234\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:971\nruntime.goPanicIndex\n\t/usr/local/go/src/runtime/panic.go:88\ngithub.com/go-graphite/carbonapi/expr/functions/sumSeriesWithWildcards.(*sumSeriesWithWildcards).Do\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/functions/sumSeriesWithWildcards/function.go:90\ngithub.com/go-graphite/carbonapi/expr.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:160\ngithub.com/go-graphite/carbonapi/expr.evaluator.Eval\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:119\ngithub.com/go-graphite/carbonapi/expr/helper.GetSeriesArg\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/helper/helper.go:41\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:160\ngithub.com/go-graphite/carbonapi/expr.evaluator.Eval\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:119\ngithub.com/go-graphite/carbonapi/expr/helper.GetSeriesArg\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/helper/helper.go:41\ngithub.com/go-graphite/carbonapi/expr/functions/exclude.(*exclude).Do\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/functions/exclude/function.go:33\ngithub.com/go-graphite/carbonapi/expr.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:160\ngithub.com/go-graphite/carbonapi/expr.evaluator.Eval\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:119\ngithub.com/go-graphite/carbonapi/expr.evaluator.FetchAndEvalExp\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:96\ngithub.com/go-graphite/carbonapi/expr.FetchAndEvalExp\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:131\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:268\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\ngithub.com/go-graphite/carbonapi/util/ctx.ParseCtx.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/util/ctx/ctx.go:90\ngithub.com/go-graphite/carbonapi/cmd/carbonapi/http.enrichContextWithHeaders.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/cmd/carbonapi/http/enrichcontext.go:32\ngithub.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/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:2069\nnet/http.(*ServeMux).ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2448\ngithub.com/gorilla/handlers.CompressHandlerLevel.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/compress.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\ngithub.com/gorilla/handlers.(*cors).ServeHTTP\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/cors.go:54\ngithub.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:2069\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2887\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1952"}

CarbonAPI Configuration:

listen: "0.0.0.0:8182"
cache:
  type: "mem"
  size_mb: 0
  defaultTimeoutSec: 60
cpus: 0
tz: ""
graphite:
  host: "localhost:2003"
  interval: "60s"
  prefix: "carbon.api"
  pattern: "{prefix}.{fqdn}"
pidFile: ""
logger:
  - logger: ""
    file: "/var/log/carbonapi/carbonapi-1.log"
    level: "warn"
    encoding: "console"
upstreams:
  buckets: 10
  slowLogThreshold: 7s
  timeouts:
    find: "3s"
    render: "15s"
    connect: "200ms"
  keepAliveInterval: "30s"
  maxIdleConnsPerHost: 1000
  backendsv2:
    backends:
      - groupName: "victoriametrics"
        protocol: "prometheus" # also tried the victoriametrics protocol
        lbMethod: "rr"
        maxTries: 2
        backendOptions:
          step: "1m"
        servers:
          - "http://localhost:8481/select/0/prometheus"

Would be great to get this fixed or to know some way to get rid of the error. Thank you.

keliss avatar Aug 23 '21 09:08 keliss

Hi,

With the current state of bugreport that likely would never be fixed (sorry) as I have no way on reproducing your problem other than getting a random data in.

Could you clarify more information about the replies that you have. It is sometimes important to provide insight into data (if that's single series or multiple series, does any of the series have NaNs, if so on roughly what position, etc.) and ideally minimal viable query, basically query from your logs:

exclude(aliasByNode(sumSeriesWithWildcards(keepLastValue(removeAbovePercentile(scaleToSeconds(nonNegativeDerivative(metric.ssp-aggregated.prod.*.dc.service.*.*.display.sum.values.*.value_type.count), 1), 99.5), 1000), 4, 5, 6, 3), 7), 'all')

And panic happens at sumSeriesWithWildcards state. It is still interesting to see if aliasByNode and exclude affects it, if you try to remove some of the other functions - will the panic still occur? What are the intermediate computation results on step before (keepLastValue). That all are extremely important information to find what the root cause is.

Civil avatar Aug 23 '21 10:08 Civil

Yeah, sure. >if that's single series or multiple series Multiple series. >does any of the series have NaNs Only in the very first data point. I'm tracking this in the Grafana query inspector, it looks like this: datapoints:Array[169] 0:Array[null,1629705504000] 1:Array[9159,1629705564000] ... Also, this error only occurs if I leave the Grafana tab for a few minutes. Spamming the refresh button doesn't lead to the reproduction of the issue. It's hard to reproduce, so I don't have much insight yet. If I catch any information you requested, I'll post it here.

keliss avatar Aug 23 '21 11:08 keliss

I was able to pinpoint the function causing this, here's the query:

averageSeriesWithWildcards(basename.*.*.*.service.type.metric.*.time.p95, 6)

And it's very likely that in the previous example the culprit was the sumSeriesWithWildcards function. And here's what I get in the logs:

2021-08-23T20:04:12.091Z        ERROR   render  panic during eval:      {"carbonapi_uuid": "58bad8a0-fe77-4f52-b2f2-782d7dd45503", "username": "", "request_headers": {}, "cache_key": "format=json&from=-6h&maxDataPoints=2510&target=<metric above>&until=now", "reason": "runtime error: index out of range [3] with length 3", "stack": "github.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:234\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:971\nruntime.goPanicIndex\n\t/usr/local/go/src/runtime/panic.go:88\ngithub.com/go-graphite/carbonapi/expr/functions/averageSeriesWithWildcards.(*averageSeriesWithWildcards).Do\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/functions/averageSeriesWithWildcards/function.go:91\ngithub.com/go-graphite/carbonapi/expr.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:160\ngithub.com/go-graphite/carbonapi/expr.evaluator.Eval\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:119\ngithub.com/go-graphite/carbonapi/expr.evaluator.FetchAndEvalExp\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:96\ngithub.com/go-graphite/carbonapi/expr.FetchAndEvalExp\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:131\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:268\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\ngithub.com/go-graphite/carbonapi/util/ctx.ParseCtx.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/util/ctx/ctx.go:90\ngithub.com/go-graphite/carbonapi/cmd/carbonapi/http.enrichContextWithHeaders.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/cmd/carbonapi/http/enrichcontext.go:32\ngithub.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/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:2069\nnet/http.(*ServeMux).ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2448\ngithub.com/gorilla/handlers.CompressHandlerLevel.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/compress.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\ngithub.com/gorilla/handlers.(*cors).ServeHTTP\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/cors.go:54\ngithub.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:2069\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2887\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1952"}
2021-08-23T20:04:12.092Z        ERROR   access  request failed  {"data": {"handler":"render","carbonapi_uuid":"58bad8a0-fe77-4f52-b2f2-782d7dd45503","url":"/render","peer_ip":"<ip>","host":"localhost:8182","format":"json","use_cache":true,"targets":["<metric above>"],"cache_timeout":60,"runtime":2.3324980220000002,"http_code":500,"reason":"runtime error: index out of range [3] with length 3\nStack trace: github.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:239\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:971\nruntime.goPanicIndex\n\t/usr/local/go/src/runtime/panic.go:88\ngithub.com/go-graphite/carbonapi/expr/functions/averageSeriesWithWildcards.(*averageSeriesWithWildcards).Do\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/functions/averageSeriesWithWildcards/function.go:91\ngithub.com/go-graphite/carbonapi/expr.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:160\ngithub.com/go-graphite/carbonapi/expr.evaluator.Eval\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:119\ngithub.com/go-graphite/carbonapi/expr.evaluator.FetchAndEvalExp\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:96\ngithub.com/go-graphite/carbonapi/expr.FetchAndEvalExp\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:131\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:268\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\ngithub.com/go-graphite/carbonapi/util/ctx.ParseCtx.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/util/ctx/ctx.go:90\ngithub.com/go-graphite/carbonapi/cmd/carbonapi/http.enrichContextWithHeaders.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/cmd/carbonapi/http/enrichcontext.go:32\ngithub.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/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:2069\nnet/http.(*ServeMux).ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2448\ngithub.com/gorilla/handlers.CompressHandlerLevel.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/compress.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\ngithub.com/gorilla/handlers.(*cors).ServeHTTP\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/cors.go:54\ngithub.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:2069\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2887\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1952","from":1629727449,"until":1629749049,"from_raw":"-6h","until_raw":"now","uri":"/render","from_cache":false,"used_backend_cache":false,"request_headers":{}}}

The wildcarded node has lots of distinct values, I'd say hundreds.

keliss avatar Aug 23 '21 20:08 keliss

Here's another simplified query causing the same error:

asPercent(timeShift(groupByNode(node1.node2.node3.*.*.node4.*.node5.node6.node7.node8.node9.*.count, 11, 'sum'), '5min'), timeShift(groupByNode(node1.node2.node3.*.*.node4.*.node5.node6.node7.node8.node9.*.count, 11, 'sum'), '20min'))

The error:

2021-08-24T16:53:31.941Z        ERROR   access  request failed  {"data": {"handler":"render","carbonapi_uuid":"f78cf345-7108-4034-b413-90c2da07abaf","url":"/render","peer_ip":"<ip>","host":"<host>:8182","format":"json","use_cache":true,"targets":["<metric above>"],"cache_timeout":60,"runtime":11.388484146,"http_code":500,"reason":"runtime error: index out of range [0] with length 0\nStack trace: github.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:239\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:971\nruntime.goPanicIndex\n\t/usr/local/go/src/runtime/panic.go:88\ngithub.com/go-graphite/carbonapi/expr/functions/asPercent.(*asPercent).Do\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/functions/asPercent/function.go:294\ngithub.com/go-graphite/carbonapi/expr.EvalExpr\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:160\ngithub.com/go-graphite/carbonapi/expr.evaluator.Eval\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:119\ngithub.com/go-graphite/carbonapi/expr.evaluator.FetchAndEvalExp\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:96\ngithub.com/go-graphite/carbonapi/expr.FetchAndEvalExp\n\t/root/go/src/github.com/go-graphite/carbonapi/expr/expr.go:131\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:268\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\ngithub.com/go-graphite/carbonapi/util/ctx.ParseCtx.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/util/ctx/ctx.go:90\ngithub.com/go-graphite/carbonapi/cmd/carbonapi/http.enrichContextWithHeaders.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/cmd/carbonapi/http/enrichcontext.go:32\ngithub.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/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:2069\nnet/http.(*ServeMux).ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2448\ngithub.com/gorilla/handlers.CompressHandlerLevel.func1\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/compress.go:141\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\ngithub.com/gorilla/handlers.(*cors).ServeHTTP\n\t/root/go/src/github.com/go-graphite/carbonapi/vendor/github.com/gorilla/handlers/cors.go:54\ngithub.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:2069\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2887\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1952","from":1629823700,"until":1629824000,"from_raw":"-5min","until_raw":"now","uri":"/render","from_cache":false,"used_backend_cache":false,"request_headers":{}}}

keliss avatar Aug 24 '21 16:08 keliss

I'm also seeing issues with 'Index out of range' errors. In my case, grafana is attempting to merge >10 (sometimes 20-30) graphs together, which is presenting some difficulty. Are there any control surfaces for managing the number of parallel queries, the length of time to wait for all queries to be returned, the ability to recreate graphs if some arrive late, etc?

gkramer avatar Jul 07 '22 11:07 gkramer

@gkramer can you post here the stacktrace of the error, carbonapi version and ideally config file. As the case above at least as far as I understand was fixed some time ago and current latest version should work fine.

Also, Index out of range errors are always a bug and shouldn't depend on amount of queries you have.

As about control surfaces to manage number of parallel queries - there are few options that might help, but it's better to discuss that in a separate discussion/issue (also at this particualar moment I don't have enough time to explain them, but you can try to read the documentation about: https://github.com/go-graphite/carbonapi/blob/main/doc/configuration.md#concurency https://github.com/go-graphite/carbonapi/blob/main/doc/configuration.md#maxbatchsize https://github.com/go-graphite/carbonapi/blob/main/doc/configuration.md#upstreams (same options as above)

Civil avatar Jul 07 '22 12:07 Civil

Overall there were a LOT of bugfixes for similar problems, I would suggest to try with current master and see if your problem went away. If not - please reopen this issue.

Civil avatar Sep 19 '22 15:09 Civil