Query from Grafana to Mimir timing out

[SunSparc]

I am writing a query in Grafana with Mimir as the datasource. When I run the query as an instant query or even with a time range up to 6 hours, it responds well. However, when I surpass 6 hours, the query times out.

The query itself does not really matter, though this is what it looks like:

haproxy_backend_active_servers{job="haproxy", ecosystem="live", proxy="target-service-name", datacenter="dallas"}

And this is the query and response that Grafana receives:

Get "http://mimir.address/prometheus/api/v1/query_range?
    end=1680570090
    &query=haproxy_backend_active_servers%7Bjob%3D%22haproxy%22
        %2C+ecosystem%3D%22live%22%2C+proxy%3D%22target-service-name%22
        %2C+datacenter%3D%22dallas%22%7D
    &start=1680526890
    &step=30": 
    net/http: timeout awaiting response headers (Client.Timeout exceeded while awaiting headers)

I assume this can be solved by modifying some settings in Mimir, and/or providing the Mimir instances with some more resources. Aside from just throwing more CPU and RAM at the problem, are there some settings that I can update that will help?

[SunSparc]

Looking through the documentation I found a setting named frontend.split_queries_by_interval that looks interesting.

[dimitarvdimitrov]

you can try increasing the timeout setting of the datasource

[SunSparc]

Yes, that could be a good option to try out. Thanks for the reminder.

[SunSparc]

I switched the datasource to use POST instead of GET. The problem is the same, the message that Grafana reports is different: Query error: 504.

These appear to be relevant logs from one of the Mimir servers:

22:26:14.263812799Z caller=retry.go:78 level=error user=anonymous msg="error processing request" try=1 err="context canceled"

22:26:14.264472728Z caller=handler.go:295
    level=info
    user=anonymous
    msg="query stats"
    component=query-frontend
    method=POST
    path=/prometheus/api/v1/query_range user_agent=Grafana/9.5.1
    response_time=59.99648771s
    query_wall_time_seconds=0
    fetched_series_count=0
    fetched_chunk_bytes=0
    fetched_chunks_count=0
    fetched_index_bytes=0
    sharded_queries=0
    split_queries=1
    estimated_series_count=0
    param_start=1683109500
    param_step=30
    param_end=1683152700
    param_query="web_requests{ecosystem=\"live\"}\n"
    status=canceled
    err="context canceled"

22:26:14.264803419Z caller=frontend_processor.go:88 level=error msg="error processing requests" 
    address=10.132.0.5:64842 err="rpc error: code = Canceled desc = context canceled"

22:26:14.264958235Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch series" remote=10.10.0.21:64241 
    err="rpc error: code = Canceled desc = context canceled"

22:26:14.265039449Z caller=spanlogger.go:85 user=anonymous method=blocksStoreQuerier.selectSorted level=warn user=anonymous 
    msg="failed consistency check" err=null

22:26:14.265074346Z caller=frontend_processor.go:168 level=error msg="error processing requests" err=EOF

---

22:26:16.496646617Z caller=pool.go:193 
    level=warn
    msg="removing store-gateway failing healthcheck"
    addr=10.10.0.22:64842 
    reason="rpc error: code = Unavailable desc = connection error: 
        desc = \"transport: Error while dialing dial tcp 10.10.0.22:64842: connect: connection refused\""

22:26:26.497271026Z caller=pool.go:193
    level=warn
    msg="removing store-gateway failing healthcheck"
    addr=10.10.0.21:64241 
    reason="rpc error: code = DeadlineExceeded desc = context deadline exceeded"

I wonder if this is because my storage is on GCS. Perhaps the latency from using remote storage is too high to be effective. Or more likely I need to adjust some store-gateway settings.

(Here is a similar discussion.)

[SunSparc]

@dimitarvdimitrov, thank you for the reply. I am not using Kubernetes (or Helm charts). I am running Mimir in a Nomad infrastructure. I am not using nginx or any other reverse proxy server. Requests from Grafana go directly to the Mimir service (eg http://mimir.service.consul:63909/prometheus). Are there settings in the Mimir configuration parameters that relate to the settings you referred to in the helm charts?

[dimitarvdimitrov]

the default query timeout in mimir is 2 minutes (querier.timeout). You said you switched the datasoruce config to use POST instead of GET. Did you also change the timeout settings on the datasource? IIRC Grafana's default query timeout is also 1 minute.

[SunSparc]

Grafana has a Timeout ("request timeout") and a Query timeout. Both are defaulted to 60 seconds. That seems like a really long time for a query. I will bump those up to 120s and observe the effects.

[SunSparc]

Well, it now takes longer to result in the same error.

[SunSparc]

Some extra information for others who might have this problem. I discovered the problem when I saw these kinds of messages in the logs. The instances were using addresses that were firewall blocked instead of the correct addresses.

ts=2023-06-06T21:40:16.044433899Z caller=pool.go:193 level=warn msg="removing store-gateway failing healthcheck" addr=<mimir1-incorrect-ip>:63813 reason="rpc error: code = DeadlineExceeded desc = context deadline exceeded"
ts=2023-06-06T21:40:16.044459257Z caller=pool.go:193 level=warn msg="removing store-gateway failing healthcheck" addr=<mimir2-incorrect-ip>:64842 reason="rpc error: code = DeadlineExceeded desc = context deadline exceeded"
ts=2023-06-06T21:40:16.044809174Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch label values" remote=<mimir2-incorrect-ip>:64842 err="rpc error: code = Canceled desc = grpc: the client connection is closing"
ts=2023-06-06T21:40:16.044795948Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch series" remote=<mimir1-incorrect-ip>:63813 err="rpc error: code = Canceled desc = grpc: the client connection is closing"
ts=2023-06-06T21:40:16.045543493Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch series" remote=<mimir3-incorrect-ip>:64241 err="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp <mimir3-incorrect-ip>:64241: connect: connection refused\""
ts=2023-06-06T21:40:26.045650221Z caller=pool.go:193 level=warn msg="removing store-gateway failing healthcheck" addr=<mimir3-incorrect-ip>:64241 reason="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp <mimir3-incorrect-ip>:64241: connect: connection refused\""
ts=2023-06-06T21:40:36.045018769Z caller=pool.go:193 level=warn msg="removing store-gateway failing healthcheck" addr=<mimir2-incorrect-ip>:64842 reason="rpc error: code = DeadlineExceeded desc = context deadline exceeded"
ts=2023-06-06T21:40:36.045290717Z caller=pool.go:193 level=warn msg="removing store-gateway failing healthcheck" addr=<mimir1-incorrect-ip>:63813 reason="rpc error: code = DeadlineExceeded desc = context deadline exceeded"
ts=2023-06-06T21:40:36.045337796Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch series" remote=<mimir2-incorrect-ip>:64842 err="rpc error: code = Canceled desc = grpc: the client connection is closing"
ts=2023-06-06T21:40:36.04541879Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch label values" remote=<mimir1-incorrect-ip>:63813 err="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp <mimir1-incorrect-ip>:63813: i/o timeout\""
ts=2023-06-06T21:40:36.046191162Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch label values" remote=<mimir3-incorrect-ip>:64241 err="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp <mimir3-incorrect-ip>:64241: connect: connection refused\""
ts=2023-06-06T21:40:46.044837188Z caller=pool.go:193 level=warn msg="removing store-gateway failing healthcheck" addr=<mimir3-incorrect-ip>:64241 reason="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp <mimir3-incorrect-ip>:64241: connect: connection refused\""
ts=2023-06-06T21:40:56.044452047Z caller=pool.go:193 level=warn msg="removing store-gateway failing healthcheck" addr=<mimir1-incorrect-ip>:63813 reason="rpc error: code = DeadlineExceeded desc = context deadline exceeded"
ts=2023-06-06T21:40:56.045073942Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch series" remote=<mimir1-incorrect-ip>:63813 err="rpc error: code = Canceled desc = grpc: the client connection is closing"
ts=2023-06-06T21:40:56.045948157Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch series" remote=<mimir3-incorrect-ip>:64241 err="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp <mimir3-incorrect-ip>:64241: connect: connection refused\""
ts=2023-06-06T21:41:02.953304318Z caller=frontend_processor.go:88 level=error msg="error processing requests" address=10.132.0.3:64241 err="rpc error: code = Canceled desc = context canceled"
ts=2023-06-06T21:41:02.953418587Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch series" remote=<mimir2-incorrect-ip>:64842 err="rpc error: code = Canceled desc = context canceled"
ts=2023-06-06T21:41:06.044533167Z caller=pool.go:193 level=warn msg="removing store-gateway failing healthcheck" addr=<mimir3-incorrect-ip>:64241 reason="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp <mimir3-incorrect-ip>:64241: connect: connection refused\""
ts=2023-06-06T21:41:16.044742903Z caller=pool.go:193 level=warn msg="removing store-gateway failing healthcheck" addr=<mimir2-incorrect-ip>:64842 reason="rpc error: code = DeadlineExceeded desc = context deadline exceeded"
ts=2023-06-06T21:41:16.045158285Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch label values" remote=<mimir2-incorrect-ip>:64842 err="rpc error: code = Canceled desc = grpc: the client connection is closing"
ts=2023-06-06T21:41:16.046178899Z caller=spanlogger.go:85 user=anonymous level=warn msg="failed to fetch label values" remote=<mimir3-incorrect-ip>:64241 err="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp <mimir3-incorrect-ip>:64241: connect: connection refused\""

[SunSparc]

Finally figured it out. Mimir was grabbing incorrect IP addresses to use for ring communication. On my nodes, by default, Mimir was seeing four interfaces:

- eth0
- eth1
- consul0
- docker0

I specifically configured each component to use only the interface that I wanted them to use:

instance_interface_names:
  - eth1

Now I can query over months!!! 🎉

[mdvaliyullah]

I am getting the same error and i have set up the above config for ingester, store-gateway, frontend. please advise

[SunSparc]

If you are experiencing the same problem that I was experiencing, then implementing my solution should fix your problem. If it does not, then you probably have a different problem and should open a separate discussion.

[citrocity]

same issue however there is no connection refused nor OOM.

I tried all the config SunSparc did but i am still getting 1m timeout.

grafana error:

<html> <head><title>504 Gateway Time-out</title></head> <body> <center><h1>504 Gateway Time-out</h1></center> <hr><center>nginx</center> </body> </html> <!-- a padding to disable MSIE and Chrome friendly error page --> <!-- a padding to disable MSIE and Chrome friendly error page --> <!-- a padding to disable MSIE and Chrome friendly error page --> <!-- a padding to disable MSIE and Chrome friendly error page --> <!-- a padding to disable MSIE and Chrome friendly error page --> <!-- a padding to disable MSIE and Chrome friendly error page -->

frontend_query error:

ts=2024-04-25T07:37:53.940930616Z caller=handler.go:324 level=info user=k6-loadtest msg="query stats" component=query-frontend method=POST path=/prometheus/api/v1/query_range user_agent=Grafana/10.1.5 response_time=59.98316282s response_size_bytes=0 query_wall_time_seconds=0 fetched_series_count=0 fetched_chunk_bytes=0 fetched_chunks_count=0 fetched_index_bytes=0 sharded_queries=16 split_queries=1 estimated_series_count=0 queue_time_seconds=0 param_end=2024-04-23T12:59:45Z param_query="count({__name__=~\"k6_generated_metric_([0-9]{1,4})\"})" param_start=2024-04-23T12:00:00Z param_step=15000 length=1h4m45s time_since_min_time=43h41m53.957717903s time_since_max_time=42h37m8.957717903s results_cache_hit_bytes=0 results_cache_miss_bytes=0 status=failed err="context canceled"

store-gateway error:

ts=2024-04-25T07:37:53.955870912Z caller=grpc_logging.go:87 level=warn method=/gatewaypb.StoreGateway/Series duration=59.993503619s msg=gRPC err="rpc error: code = Unknown desc = rpc error: code = Unknown desc = send series response: rpc error: code = Canceled desc = context canceled"

Anyone with any suggestions? or is it a bug somewhere?

[citrocity]

would that be directly to frontend instead of the gateway?
btw the mimir gateway (nginx) I have added 120s on send_timeout, proxy_read_timeout and proxy_send_timeout under http directive.

[SunSparc]

Yes, try bypassing the gateway.

[lukasmrtvy]

This comes from other component than Nginx Gateway. ( In my case Grafana datasource is pointing to query-frontend )

[dimitarvdimitrov]

grafana also has a timeout towards the datasource

[lukasmrtvy]

Yes, this one is probably from dataproxy timeout in Grafana. There was another timeout in my case.., AWS ALB idle timeout ( defaults to 60s too ).