Investigate and solve Redis::CannotConnectError

[jrochkind]

We are getting regular "bursts" of Redis::CannotConnectError reported by HoneyBadger.

Here is one: https://app.honeybadger.io/projects/58989/faults/126038285

They show up in "bursts" of multiple reports from HB, which is a bit weird in that we'd expect HB to "group" them but I guess they appear as different groups? Haven't gotten to the bottom of that.

Some investigation of previous burst...

• 3 reports at 2am, each report is only 1-5 isntances, so it wasn't a lot

  • These are on our Rails.cache ephemeral redis, not our persistent Redis used for ActiveJob.
  • But, I hadn't realized before, we actually had THOUSANDS of these occuring on May 3rd between 6:50 am and at 7:45am... since it's just cache, it's not necessarily a visible problem to users, but interesting. And maybe some times before that.

• Connect timeout.

  • Could be from CPU exhaustion? But the cache redis is currently only using 1% of CPU… it doesn't look like historical data is available from stackhero
  • If it’s actual network troubles that is annoying. From error message it looks like we have 1s set for connection timeout, which ought to be plenty and is already too long.

• all the resource usage looks fine — at this point in time, haven’t found historical.

• Nothing seen in the very limited logs available in stackhero

• There is a rails-managed connection pool in use for cache, but ConnectionTimeout error has stacktrace in netwroking stack, suggesting this is actual network to redis issue, not connection pool running out of max connections.

• Updating to latest redis might not hurt, it’s in our Ready, when we get to it, we can go from a 7.x to latest 8.x.

[jrochkind]

OK, found out we can ask for "SLOWLOG" from redis live.

scihist-digicoll(prod):006> Rails.cache.redis.with { |conn| conn.slowlog('get', 10) }
=>
[[4, 1777808067, 42835934, ["get", "scihist:more_like_this:mp48sc852:4"], "172.20.0.4:40760", ""],
 [3, 1777807935, 378111, ["get", "scihist:more_like_this:44558d374:4"], "172.20.0.4:56178", ""],
 [2, 1777807885, 268793, ["get", "scihist:more_like_this:hqxtd3m:4"], "172.20.0.4:60784", ""],
 [1, 1777807872, 13894, ["get", "scihist:more_like_this:uzh0kyb:4"], "172.20.0.4:60784", ""],
 [0, 1753691606, 11642, ["get", "more_like_this/tihs2kr"], "172.20.0.4:42184", ""]]

That's ID, unix timestamp, duration in micro-seconds (millions of a second]. So only one truly pathological one, the first one is 42 seconds which is crazy. Second slowest is 378ms which is still far too slow, but for an occasional edge case?

So not sure there's anything for us here, just one super pathological one and one alone probably doens't explain much.

[jrochkind]

I think this probably IS bot traffic -- we let bots into item detail page, and that uses redis to access a cached version of "more like this", which was meant to keep it from overloading solr -- I think it may be overloading redis just cache though!

Just a hypothesis, have not confirmed with logs or other debugging.

If so, one solution would be using an in-memory RAM cache, perhaps in front of the redis cache, to try to keep traffic from redis cache too?? (in memory RAM cache would get cleared on every deploy, so would only be semi-persisetent).