Constantly Reestablishing Connections to AWS ElastiCache Redis in Cluster Mode (Continued)

[ianjhoffman]

(See previous issue for additional context and discussion)

Expected Behavior

A ClusterClient with bare-minimum settings for connecting to an AWS ElastiCache Redis cluster (from here on referred to as ECRedis) will, at no point, contribute to a scenario in which it is constantly reestablishing connections to an ECRedis cluster node.

Example ClusterClient config:

redis.NewClusterClient(&redis.ClusterOptions{
    Addrs: []string{redisAddr},
    TLSConfig: &tls.Config{},
})

Current Behavior

(The Current Behavior section in the original issue is still accurate to this issue)

Occasionally, we see connections being constantly re-established to one of our ECRedis cluster nodes at the limit of how many new connections are possible (~15k/minute is the reported rate). Redis nodes are essentially single-threaded and negotiating TLS for new connections takes up 100% of this node's CPU, preventing it from doing any other work. The time at which this issue occurs seems random, and we cannot correlate it to:

• Amount of load on the system (# Redis commands)
• Events happening on the ECRedis cluster (resharding, cycling out nodes, failovers, etc.)
• Any other issues with the ECRedis cluster not normally visible in the AWS Console (we consulted with AWS support for this one)
• Service restarts for our Go service that communicates with ECRedis

When this issue happens, running CLIENT LIST on the affected Redis node shows age=0 or age=1 for all connections every time, which reinforces that connections are being dropped constantly for some reason. New connections plummet on other shards in the Redis cluster, and are all concentrated on one.

After discussion on the previous issue we are no longer the only ones experiencing this unknown problem, and it is blocking us from further relying on this service we've been building (and delaying full use of) for well over 6 months now.

Possible Solution

Redis ClusterClient should react more gracefully to that quickly devolves into constantly reestablishing connections to some node in the AWS ElastiCache Redis cluster.

After the previous issue, we have tried a variety of approaches to mitigate this problem, none of which have solved it entirely:

• Increasing all timeouts in context.Contexts passed to Redis commands to 1 second or greater
• Reducing # of goroutines exercising our Redis claim logic
• Lowering connection pool size
• Moving all operations out of MULTI/EXEC pipelines
• Completely disabling idle connection reaping
• Fuzzing the interval at which each individual cluster node's Client cleans idle connections
• Changing the instance type of the ElastiCache Redis nodes
• Rebalancing/increasing shard count for the ElastiCache Redis cluster

We are seeing the issue a lot less often after

• Reducing # of goroutines exercising our Redis claim logic
• Lowering pool size
• Fuzzing the interval at which each individual cluster node's Client cleans idle connections

but are not confident that these changes constitute a permanent fix and are instead a consequence of there being fewer potential resources to overload an individual ECRedis cluster node.

Details About Fuzzing Idle Connection Cleanup

We opted to set IdleTimeout and IdleCheckFrequency on the redis.ClusterOptions passed to our client to -1 and added a custom NewClient implementation:

// A new redis.Client is created for each Redis cluster node to which a redis.ClusterClient
// sends commands. Make each redis.Client clean idle connections at a different cadence.
redisOpts.NewClient = func(clientOptions *redis.Options) *redis.Client {
	rand.Seed(time.Now().UnixNano())
	idleTimeoutFuzz := time.Duration(rand.Int63n(int64(idleTimeoutFuzzRange)))

	// It's safe to modify this *redis.Options in this way - a new data
	// structure is created and passed to this function for each client created
	clientOptions.IdleTimeout = baseIdleTimeout + idleTimeoutFuzz

	return redis.NewClient(clientOptions)
}

Resetting the System to a Good State

When this issue happens, we are generally able to reset it to a good state by telling producers to stop producing new work to the system, which in turn means our consumer goroutines running the algorithm detailed later in this issue stop seeing new work items and their algorithm essentially just becomes SRANDMEMBER pending 10 -> sleep 10ms -> repeat. We can then resume producer writes and the system goes back into a good state without connections being constantly reestablished. This is an improvement from our solution in the previous issue: completely stopping all services and then turning them back on after some period of time. However, it's not a tenable solution to this issue if we are to continue onboarding more work to the system in production.

Steps to Reproduce

The description of our environment/service implementation below, as well as the snippet of our NewClusterClient call at the beginning of this issue, provide a fairly complete summary of how we're using both go-redis and ECRedis. We've not been able to consistently trigger this issue since it often happens when we're not load testing. I'd be interested to know if the other commenters on the original issue, @klakekent and @pedrocunha, have had any luck reproducing the issue. It sounds like it's been difficult to reproduce for them as well.

Context (Environment)

We're running a service that has a simple algorithm for claiming work from a Redis set, doing something (unrelated to Redis) with it, and then cleaning it up from Redis. In a nutshell, the algorithm is as follows:

• SRANDMEMBER pending 10 - grab up to 10 random items from the pool of available work
• ZADD in_progress <current_timestamp> <grabbed_item> for each of our items we got in the previous step
• Any work items we weren't able to ZADD have been claimed by some other instance of the service, skip them
• Once we're done with a work item, SREM pending <grabbed_item>
• Periodically ZREMRANGEBYSCORE in_progress -inf <5_seconds_ago> so that claimed items aren't claimed forever, but items can only be claimed exactly once during a 5 second window

Work item producers simply SADD pending <work_item> but the load they produce is miniscule compared to the consumers running the algorithm outlined above.

Currently we run this algorithm on 22 EC2 instances, each running one service. We've configured our ClusterClient to use a PoolSize of 10 (reduced from the default of 20 on these instances) for each child Client it creates. Each service has 25 goroutines performing this algorithm, and each goroutine sleeps 10ms between each invocation of the algorithm.

At a steady state with no load on the system (just a handful of heartbeat jobs being added to pending every minute) we see a maximum of ~8% EngineCPUUtilization on each Redis shard, and 1-5 new connections/minute. Overall, pretty relaxed. When this issue has triggered recently, it's happened from this steady state, not during load tests.

Our service is running on EC2 instances running Ubuntu 18.04 (Bionic), and we have tried using github.com/go-redis/redis/v8 v8.0.0, github.com/go-redis/redis/v8 v8.11.2, and github.com/go-redis/redis/v8 v8.11.4 - all 3 have run into this issue. We are now using a fork of v8.11.4 (see added commits here) with the following changes (some suggested in the previous issue, some thought of by us):

• Add logs in spots where bad connections are removed
• Add hooks in ClusterClient.process method for logging/metrics around various anomalies during processing commands (MOVED/ASK responses, errors getting nodes, node failures). We do not see these while the issue is happening.

We're currently running with a 24-shard ElastiCache Redis cluster with TLS enabled, where each shard is a primary/replica pair of cache.r6g.large instances.

Detailed Description

N/A

Possible Implementation

N/A

[vmihailenco]

@enjmusic thanks for creating the isssue.

Add logs in spots where bad connections are removed

Do you see any logs? I guess not which may indicate that the idle conns reaper is indeed the problem. You could try to disable it completely to confirm that. Or add some logging here and here if you really need IdleTimeout.

[ianjhoffman]

@vmihailenco if I remember correctly, we were seeing a mixture of I/O timeout and context deadline exceeded logs when this issue was triggered.

We did completely disable idle connection reaping for a while (both the reaper goroutine and the IdleTimeout) and while this made the issue happen less often, we did still see it triggered once! So while it may be a contributing factor I don't know if it's the root cause. We haven't seen this issue lately after:

• Reducing # of goroutines exercising our Redis claim logic
• Lowering pool size
• Fuzzing the interval at which each individual cluster node's Client cleans idle connections

but again, it's difficult to believe that we've completely addressed the issue or just made it exceedingly unlikely at our current scale. I'd be interested to know if we can get any more insights from @klakekent and @pedrocunha, assuming they're still seeing the issue periodically.

[vmihailenco]

I/O timeout and context deadline

Well, it may be an indication that you need a larger server / better network. There is no evidence it is a bug in go-redis.

[ianjhoffman]

Well, it may be an indication that you need a larger server / better network. There is no evidence it is a bug in go-redis.

Our web servers running go-redis code, as well as our ElastiCache Redis cluster, are both overprovisioned for the amount of work they're doing. They're always pretty bored when this issue is triggered. Given that:

• we have a ton of CPU/memory headroom
• multiple others have reported the same issue
• we use go-redis in non cluster mode in other applications with similar or greater load per node and never observed this issue over 2+ years in those contexts
• @klakekent, like us, was told by AWS support that there was nothing suspicious going on from AWS's view of the ElastiCache Redis clusters

With these points in mind, I think it's very reasonable to consider them enough evidence to continue taking a closer look at go-redis. I would love to see more engagement around getting to the bottom of this issue rather than dismissing it a second time.

[monkey92t]

According to your log report closing bad conn: context deadline exceeded, I checked the working process of go-redis in detail, it only appears in initConn and withConn, I believe this error is caused by context timeout .

But according to your reply:

• we use go-redis in non cluster mode in other applications with similar or greater load per node and never observed this issue over 2+ years in those contexts

You did not encounter this problem in non-redis cluster mode, so what is your context timeout in non-redis cluster mode? Is an ACL operation required(initConn)?

skip initConn:

if c.opt.Password == "" && c.opt.DB == 0 && !c.opt.readOnly && c.opt.OnConnect == nil {
        // skip initConn
}

[monkey92t]

go-redis ClusterClient additionally caches the results of cluster slots, but it is executed asynchronously (except when each node is initialized), but if your redis-cluster nodes change frequently, it may greatly increase the command execution time (ask moved).

In addition, you may need to consider network issues (aws vpc), or the time spent processing commands by redis-cluster(> context.Timeout).

[ianjhoffman]

So, we have a theory about what might be going on. AWS ElastiCache Redis best practices dictate that one should use the "Cluster Configuration Endpoint" for cluster discovery, which we took to mean that it was ok to use that as our one seed address for the ClusterClient, assuming that every time it was reached out to it would route to a different node in the cluster. The auto discovery section of the ElastiCache FAQ states that

the Amazon ElastiCache cluster is also given a unique Configuration Endpoint which is a DNS Record that is valid for the lifetime of the cluster. This DNS Record contains the DNS Names of the nodes that belong to the cluster. Amazon ElastiCache will ensure that the Configuration Endpoint always points to at least one such “target” node. A query to the target node then returns endpoints for all the nodes of the cluster in question

which we took to mean that it would balance between all nodes. However, there's likely some DNS caching going on. When I nslookup our Configuration Endpoint I see the full list of IPs for all primaries and replicas, but when I openssl s_client -nocommands -connect <configuration_endpoint> I always end up on the same node in the cluster. I think this means that when the ClusterClient is seeded with just the Configuration Endpoint, in any situation where several goroutines executing code in cluster.go all need to fall back on the initial Addrs list provided when the ClusterClient was created, they'll all hammer the same shard.

We may be able to get around this issue by performing a LookupIP or similar query to get our Addrs list so that the initial list of nodes lends itself well to a fair division of lookups across nodes when needed.

We're probably going to implement this safety measure no matter what, but my main question after looking into the Configuration Endpoint (and its use as the only seed address for a ClusterClient) a little more is: what are the different spots in cluster.go where we fall back on the initially provided Addrs list from the ClusterOptions? I started looking deeply into the code for this today but figured I'd miss some stuff given that there's a lot of code for clusterNodes and clusterStateHolder.

[monkey92t]

There seems to be no evidence of a DNS problem, in the logs you see "context deadline exceeded", we should determine where more time is being consumed causing the context to time out.

We were unable to reproduce this issue in a test environment, you can add more logs to go-redis to locate where time is consuming:

https://github.com/go-redis/redis/blob/40e84a79bfb4fafc2d7b6770f7434311de08ce48/cluster.go#L771

[dzqv]

We have a theory about what might be going on... The auto discovery section...

@enjmusic Have you seen this post https://medium.com/tinder-engineering/taming-elasticache-with-auto-discovery-at-scale-dc5e7c4c9ad0 ?

Tinder found a bug in their Java client failing to dynamically reconfigure which IP it was connecting to following AWS Elasticache cluster maintenance events.

[ianjhoffman]

We finally saw this issue again during the night yesterday, but it affected eight different nodes, which we've never seen before. Previously it was always one. This may or may not disprove the cluster configuration endpoint issue. Again, temporarily stopping new ingress of jobs into Redis resolved the issue.

[ianjhoffman]

@dzqv just read the blog post! It's an interesting study but doesn't look like our issue where connection floods occur to some nodes independent of any cluster maintenance events

[ianjhoffman]

This time we did see the issue happen within a couple minutes of a

Certificate renewed for replication group <REDACTED> on Sun Mar 20 08:14:05 UTC 2022

... curious about whether or not that could put clients into a bad state

[pedrocunha]

We still don't know what caused this but a couple of things:

1. This only happened for a particular service that uses context timeouts
2. We have not seen this issue re-occur since we upgraded to Redis 6.2
3. On the online upgrade to 6.2 there are multiple failover events and we didn't experience any issues in regards to new connections
4. Our limiter callback seems to trigger frequently but we aren't sure if this is "saving" us

[allanbenW]

Just wanna add that we are also seeing this issue.
We are using clustered Elasticache Redis 6.0.5 on r6g instances with TLS enabled, our clients are running on EC2 as well.

We were able to greatly mitigate the issue by passing empty context to go-redis, instead of the context with deadline/timeout.

A few other params we also tuned to mitigate this issue:

1. lowering poolSize, and also make number of connections stable by setting PoolSize = MinIdleConns
2. disabling idle conn reap
3. add random jitter in dialer
4. stick to higher timeouts, set dialTimeout = 5s; readTimeout = writeTimeout = PoolTimeout = 1s
5. disabling retry by setting MaxRetries to -1

The changes we made are helpful to reduce the symptom, but it's still happening from time to time.
Almost always it started with read timeouts on a single node, and then a huge TLS connection spike to that node.
It issue happens and self-resolves within a minutes

@pedrocunha
Are there any re-occurrences on Elasticache Redis 6.2 since you posted?
https://docs.aws.amazon.com/AmazonElastiCache/latest/red-ug/supported-engine-versions.html#redis-version-6.2
Their 6.2 version added multi-cpu optimization for TLS connections, so maybe that's helping.