Ingesters continuously log the warning message method=/cortex.Ingester/QueryStream err="context canceled" msg="gRPC\n"

[nrjpoddar]

We are running cortex version master-4d5a8a70 and see that all the ingesters are continuously logging this warning message:

level=warn ts=2019-03-13T20:38:59.792970914Z caller=gokit.go:46 method=/cortex.Ingester/QueryStream duration=61.047µs err="rpc error: code = Canceled desc = context canceled" msg="gRPC\n"

This log doesn't really contain all the information needed to debug the issue. These are our options for the ingester Pod if it's related to configuration:

        - -ingester.join-after=30s
        - -ingester.claim-on-rollout=true
        - -ingester.search-pending-for=5m
        - -consul.hostname=<>
        - -dynamodb.original-table-name=<>
        - -dynamodb.url=dynamodb://$(AWS_DEFAULT_REGION)
        - -s3.url=<>
        - -dynamodb.chunk-table.prefix=cortex_chunks_
        - -dynamodb.chunk-table.tag=cortex=chunks
        - -dynamodb.chunk-table.from=<>
        - -dynamodb.chunk-table.period=168h
        - -dynamodb.periodic-table.prefix=cortex_weekly_
        - -dynamodb.periodic-table.tag=cortex=periodic-table
        - -dynamodb.periodic-table.from=<>
        - -dynamodb.periodic-table.period=168h
        - -dynamodb.v6-schema-from=<>
        - -dynamodb.use-periodic-tables
        - -memcached.hostname=<>
        - -memcached.timeout=100ms
        - -memcached.service=memcache
        - -memcached.timeout=500ms
        - -store.index-cache-write.memcached.hostname=<>
        - -store.index-cache-write.memcached.service=memcache
        - -store.index-cache-write.memcached.timeout=500ms
        - -store.index-cache-read.memcached.hostname=<>
        - -store.index-cache-read.memcached.service=memcache
        - -store.index-cache-read.memcached.timeout=500ms

[bboreham]

Thanks for filing this. Mine are the same.

Note that the querier will always send requests to N ingesters and cancel the remaining ones when it gets enough replies to make a quorum.

In other words, context cancelled should not be logged as an error (or flagged as such to OpenTracing) because it’s expected.

[nrjpoddar]

That makes sense, I will try and submit a PR to address it.

[nrjpoddar]

Looks like the logging is handled at the common layer via interceptors on the gRPC server: https://github.com/cortexproject/cortex/blob/master/vendor/github.com/weaveworks/common/middleware/grpc_logging.go#L42

Should we add a custom logging gRPC interceptor for the ingester server?
We can also filter based on methods passed in the interceptor during initialization but that seems like a maintenance nightmare.

[csmarchbanks]

You can also try setting -distributor.extra-query-delay on your queriers and ruler to about the 95th percentile response time of the latency to your ingester. This will cause the queries needed for more than a quorum will wait to be sent and you will only have a context cancelled error if talking to an ingester is actually slow.

The 95th percentile recommendation comes from http://www.cs.duke.edu/courses/cps296.4/fall13/838-CloudPapers/dean_longtail.pdf You can set it to whatever you want though.

[bboreham]

Should we add a custom logging gRPC interceptor for the ingester server?

As opposed to changing weaveworks/common for every server? I'm for that (i.e. changing common).
"Context cancelled" is always expected, in my view. User can hit x on their browser, etc.

[nrjpoddar]

@csmarchbanks I will try that option and see if it works as expected.

@bboreham I don't know if weaveworks/common is used in other places where you might want to log "Context cancelled". I am thinking of cases where an API is exposed for server-to-server communication which is invoked asynchronously and not in the context of an end user request. Ruler is a good example of this. Changing weaveworks/common to always ignore "Context cancelled" error messages might be too broad.

[bboreham]

Context cancelled is not an error, it is expected in any client-server interaction.

[nrjpoddar]

@bboreham I filed this PR: weaveworks/common#151 for addressing this issue. Once you're review/approve it, I will submit a PR to cortex to update dependencies.

[bboreham]

This is probably a duplicate of #465