Pool TLS connections aren't long-lived anymore

[rentziass]

👋 We've been investigating an increase in CPU load both in our apps and our Redis clusters for a while now, and after noticing that a big portion of our CPU time was being spent on TLS handshakes we started looking at our connections and noticed exorbitant amounts of stale connections. Importantly, these are all TLS connections from connections pools. We tracked it down to us upgrading to go-redis 9.5.4 and when we downgraded to 9.5.2 we went back to the usual occasional stale connection:

Expected Behavior

Under normal conditions have only a handful of connections being reported as stale.

Current Behavior

Connections are barely being re-used.

Possible Solution

It looks like the issue started with this commit, specifically reading directly from the (*tls.Conn).NetConn(); from NetConn() docs:

NetConn returns the underlying connection that is wrapped by c. Note that writing to or reading from this connection directly will corrupt the TLS session.

Unfortunately, until Go supports non-blocking readable connection testing I'm not sure there's a good reliable way to check the health of TLS connections here. Until then reverting this direct read on the underlying connection is probably the way to go?

MySQL driver has also had a similar issue.

Steps to Reproduce

1. Create a ClusterClient, connecting to a cluster using TLS (ours is an Azure Enterprise cluster, not that it should make a difference). Configuring the client to have MinIdleConns adds a multiplier to this and makes much more apparent.
2. Observe the number of stale connections grow linearly over time as more and more operations are done
3. Downgrade to < 9.5.4 (9.5.2 is the first prior available version right now) and observe almost no stale connection (with the cluster in healthy conditions of course)

Context (Environment)

Detailed Description

Reading directly from the underlying net.Conn of a TLS connection as part of connCheck is corrupting the TLS session, resulting in the closing of tons of (eventually all) TLS connections in connection pools that then have to be recreated.

We can fork go-redis and add some more instrumentation to measure the reasons why connections are being closed but I'm fairly positive unexpected read from socket is the error connCheck is hitting.

[rentziass]

Update on this: we deployed a patched version that removes the read from the underlying net.Conn (essentially #3138) and we confirmed that fixes the issue 🎉

[vladvildanov]

@rentziass Thank you for your valuable input! I would make sure we include this bug fix into our next 9.6.2 release

[rentziass]

Hey @vladvildanov 👋 Thanks for reviewing and merging the PR! Do we need those changes ported to the 9.6 branch? Code changed a bit in the meantime on the branch, do you need me to open another PR against that branch or do you want to do it?

[vladvildanov]

@rentziass Yes, this would be nice

[rentziass]

Backported in #3145, I'm gonna test it real quick to make sure this version is also working as expected.

[rentziass]

@vladvildanov just confirmed #3145 works with our cluster as well!

[rentziass]

@vladvildanov do you know roughly what the ETA of releasing v9.6.2 would be? Sorry for the spam, we're blocked on upgrading past 9.5.2 right now :/

[vladvildanov]

@rentziass I'll try to make it tomorrow

[rentziass]

Thank you ❤ and anything I can do to help, please let me know!

[vladvildanov]

@rentziass 9.6.2 just got released