Using Honeycomb to Investigate a Redis Connection Leak
Tags: redis, debugging, observability, honeycomb
Published: 2020-11-05 18:06:36

This is a guest post by <a href="https://github.com/ajvondrak">Alex Vondrak</a>, Senior Platform Engineer at <a href="https://www.truex.com/">true[X]</a>.

{% user ajvondrak %}

---

This is the story of how I used Honeycomb to troubleshoot <a href="https://github.com/redis/redis-rb/issues/924" target="_blank" rel="noopener noreferrer">redis/redis-rb#924</a> and discovered a surprising workaround.

## The Problem

Emergent failures aren't fun. I've long since learned to dread those subtle issues that occur at the intersection of old code bases, eclectic dependencies, unreliable networking, third party libraries &amp; services, the whims of production traffic, and so on.

That's why, when <a href="https://redislabs.com/" target="_blank" rel="noopener noreferrer">RedisLabs</a> emailed us early in December 2019 about our clients spiking up to ~70,000 connections on a new Redis database, I really didn't want to deal with it. Our application was deployed across ~10 machines with 8 processes apiece - so you'd think _maybe_ around 100 connections tops, if everything was going smoothly. Yet there the stale connections were.

Of course, I already knew where the problem came from. The new database was for a workaround we'd just deployed. It was a bit of over-engineering for a very specific use case, and it relied on blocking operations to force parallel HTTP requests into some serial order. The logic is replicated in <a href="https://gist.github.com/ajvondrak/958962a0600cf847465a059210f266e7" target="_blank" rel="noopener noreferrer">this GitHub gist</a>.

The important thing to note is that we relied on <a href="https://redis.io/commands/blpop" target="_blank" rel="noopener noreferrer">`BLPOP`</a> to populate most of our responses. This Redis command blocks the client for a given number of seconds, waiting for data to appear on a list for it to pop off. If no data arrives in the given timeout, it returns nil.
<table style="height: 119px; border-style: solid; width: 815px;" border="1" width="815" cellspacing="1" cellpadding="5px">
<tbody>
<tr style="height: 24px;">
<td style="width: 173px; height: 24px;"><b>Elapsed Time (sec)</b></td>
<td style="width: 166px; height: 24px;"><b>Client 1</b></td>
<td style="width: 181px; height: 24px;"><b>Client 2</b></td>
<td style="width: 158px; height: 24px;"><b>Client 3</b></td>
</tr>
<tr style="height: 24px;">
<td style="width: 173px; height: 24px;"><b>0</b></td>
<td style="width: 166px; height: 24px;"></td>
<td style="width: 181px; height: 24px;"><code>BLPOP list 2</code></td>
<td style="width: 158px; height: 24px;"><code>BLPOP list 4</code></td>
</tr>
<tr style="height: 24px;">
<td style="width: 173px; height: 24px;"><b>1</b></td>
<td style="width: 166px; height: 24px;"></td>
<td style="width: 181px; height: 24px;">(waiting)</td>
<td style="width: 158px; height: 24px;">(waiting)</td>
</tr>
<tr style="height: 24px;">
<td style="width: 173px; height: 24px;"><b>2</b></td>
<td style="width: 166px; height: 24px;"><code>RPUSH list x y z</code></td>
<td style="width: 181px; height: 24px;"><code>nil</code> (timed out)</td>
<td style="width: 158px; height: 24px;">(waiting)</td>
</tr>
<tr style="height: 24px;">
<td style="width: 173px; height: 24px;"><b>3</b></td>
<td style="width: 166px; height: 24px;"></td>
<td style="width: 181px; height: 24px;"></td>
<td style="width: 158px; height: 24px;"><code>x</code> (didn’t time out)</td>
</tr>
</tbody>
</table>
We were under stringent timeouts ourselves, so we'd just wait 1 second for this data. Our customers would timeout long before Redis did anyway.

To add to the stress, this legacy code base was using relatively old/unmaintained software: <a href="https://github.com/postrank-labs/goliath" target="_blank" rel="noopener noreferrer">Goliath</a>, <a href="https://github.com/igrigorik/em-synchrony" target="_blank" rel="noopener noreferrer">em-synchrony</a>, the <a href="https://github.com/redis/redis-rb/issues/915" target="_blank" rel="noopener noreferrer">recently-deprecated</a> Redis synchrony driver, and other such things built atop the often-confusing <a href="https://github.com/eventmachine/eventmachine" target="_blank" rel="noopener noreferrer">EventMachine</a>. Suffice to say, we've had our issues in the past.

RedisLabs instituted a connection cap to stop paging their ops people. With the intervening holidays (and just slow customer ramp-up on the new feature), it wouldn't be until February 2020 that we realized no requests were succeeding because RedisLabs constantly sat at max capacity - no one was able to connect.

## Searching in the Dark

What could I do? The Ruby code was as straightforward as it could be. I used the <a href="https://github.com/redis/redis-rb" target="_blank" rel="noopener noreferrer">redis gem</a> to initialize a single `Redis` instance shared across each process. Nothing but a simple call to the `Redis#blpop` method:

```ruby
redis.blpop(key, timeout: 1)
```

Was the problem in my application? Redis? EventMachine? I spent weeks trying to read each library's code line-by-line, wishing I could just squint hard enough to understand where it could go wrong. I went through several Hail Mary attempts:

1. I tried sending a <a href="https://redis.io/commands/quit" target="_blank" rel="noopener noreferrer">`QUIT`</a> command after every request. Nothing.
2. I investigated setting a <a href="https://redis.io/topics/clients#client-timeouts" target="_blank" rel="noopener noreferrer">client timeout</a>, but that's <a href="https://support.redislabs.com/hc/en-us/articles/203290717-How-do-I-configure-the-timeout-for-my-Redis-connections-" target="_blank" rel="noopener noreferrer">not configurable on RedisLabs</a>.
3. I tried to monkey-patch underlying EventMachine connections to set <a href="https://www.rubydoc.info/github/eventmachine/eventmachine/EventMachine/Connection#comm_inactivity_timeout-instance_method" target="_blank" rel="noopener noreferrer">inactivity timeouts</a>. No dice.
</ol>

The only remaining suggestion was to write a script that periodically fed the <a href="https://redis.io/commands/client-list" target="_blank" rel="noopener noreferrer">`CLIENT LIST`</a> into <a href="https://redis.io/commands/client-kill" target="_blank" rel="noopener noreferrer">`CLIENT KILL`</a>. That was my reality check: _surely_ that couldn't be an appropriate fix. What was I missing?

## Enter Honeycomb

At the time, we had signed up for Honeycomb, but hadn't really instrumented any of our old systems. I whinged about how much I didn't want to spend time on this decrepit code - exactly because of problems like this. So of course I didn't want to instrument it! But I was getting nowhere with this bug. I didn't know what triggered it, short of production traffic. What's more, it was likely a bug in some library, not my application.

But hey, this is Ruby: I could just monkey-patch the libraries. It wouldn't be my first time. I even wrote the <a href="https://github.com/honeycombio/beeline-ruby/pull/42" target="_blank" rel="noopener noreferrer">Redis integration for the Ruby beeline</a> (full disclosure), and that works by monkey-patching the redis gem.

So I spun up a canary instance pointing to some frenzied branch of my code where I iteratively added stuff like this:

```ruby
Redis::Client.prepend(Module.new do
  def connect
    Honeycomb.start_span(name: 'Redis::Client#connect') do
      super
    end
  end

  def disconnect
    Honeycomb.start_span(name: 'Redis::Client#disconnect') do
      super
    end
  end

  def reconnect
    Honeycomb.start_span(name: 'Redis::Client#reconnect') do
      super
    end
  end
end)
```

It was ugly, but it did the trick. I could finally see the code in action.

<a href="https://www.honeycomb.io/wp-content/uploads/2020/07/redis-connection-leak.png"><img class="aligncenter size-full wp-image-7132" src="https://www.honeycomb.io/wp-content/uploads/2020/07/redis-connection-leak.png" alt="trace view showing Redis reconnection attempts" width="1600" height="748" /></a>

It still took some flipping back &amp; forth between the trace and the Redis code, but I finally noticed a pattern:

- The `BLPOP` command was being wrapped in a client-side read timeout that _added_ 5 seconds on top of the 1 second I was trying to block for. I didn't expect or even need that.
- By using that read timeout code, connection errors would also be retried endlessly.
- Due to the read timeout, each connection error took the full 6 seconds to surface.
- Each retry would disconnect &amp; reconnect the client.

One reason the connection errors were likely happening was because of the RedisLabs connection cap. They may still have been happening for mysterious reasons, as in <a href="https://github.com/redis/redis-rb/issues/598" target="_blank" rel="noopener noreferrer">redis/redis-rb#598</a>. Regardless, I could observe this endless retry loop triggering a disconnect & reconnect - several of them per request. So I thought: if those connections aren't actually being closed, that could be the source of my idle connections.

After weeks of endless squinting, guessing, and checking, within a <b>day </b>of using Honeycomb<b>,</b> I had an idea actually backed up by data. Carefully inspecting the redis gem's code, I circumvented their read timeout & retry logic with:

```diff
-redis.blpop(key, timeout: 1)
+redis.call([:blpop, key, 1])
```

Once it was deployed to the whole cluster, our connection count plummeted, and the feature finally worked as intended.

## Takeaways

- Think about what you're actually trying to do. I could've written a `CLIENT KILL` cron job, but that's trying to _reap_ idle connections, not stop them from being generated in the first place. When you don't have enough information about the problem you're trying to solve, the answer probably isn't to fix some other symptom.
- When the only thing you can do to reproduce an error is to launch production traffic at it, live tracing is the only way to see exactly the details you need.
- The code bases you hate the most are usually the ones that need the most instrumentation. But a little instrumentation still goes a long way.
- Know when to stop. I don't know why this bug happened just the way it did. But I figured out enough to fix the problem for our customers. It's a reasonably precise workaround, and further investigation can go from there.


--- 

Download the <a href="https://www.honeycomb.io/resources/guide-observability-for-developers/" target="_blank" rel="noopener noreferrer">Observability for Developers white paper</a> to learn more about how observability can help you debug emergent failure modes in production.

Experience what Honeycomb can do for your business. Check out [our short demo] (https://www.honeycomb.io/get-a-demo).