It can be hard to fix a bug even when it happens deterministically; replicating the circumstances that trigger it is often the hardest step. When a bug is non-deterministic this becomes harder: we need to execute the code that reproduces it many times in order to observe the behaviour, which adds significant time to our feedback loop. Harder still is when the cause of the bug happens prior to its manifestation —when data is corrupted but we don’t immediately notice it. Our usual tools focus on capturing the state of the system at the time a crash happens, which doesn’t tell us why the corruption happened in the first place, just that it happened.
This is the tale of a memory corruption bug we found in the redis-client library and what helped us get there.
Chapter 1: Bounce
Our story starts with David, an engineering manager on our Scalability team. One idle Tuesday, David saw a build of his had failed due to what appeared to be a number of flaky tests. He started a thread in Slack to alert others and included a screenshot from the Test Engine dashboard.
As a continuous integration company, we are intimately familiar with flaky tests —they are an inevitable part of any large codebase. Within 15 minutes, the team pulled the Andon Cord; these tests were so flaky they were preventing us deploying code to production. As David summarised it, “[the] priority is getting main unblocked”, so we worked to exclude the tests from our suite temporarily.
With the urgency reduced, David and the many other developers blocked by this hiccup were free to go back to their original tasks. David, though, decided to take a slightly deeper look by inspecting the reliability of these tests using Buildkite’s Test Engine reliability score, to see if he could correlate when they suddenly became unstable.
It seems the three worst flakeys went from ~100% reliable to… not around [2-4 days prior]. I’ve had a look through merged PRs to see if I can spot what might have contributed to that change, but can’t see anything obvious… Only thing that jumps out is the redis upgrade?
That Redis upgrade was done on the prior Friday afternoon by a staff engineer, and part time blog post narrator, Patrick Robinson. Patrick loves few things more than talking about himself in the third person; one of those things is getting deep into gnarly bugs.
Here’s our first clue: the Redis gem upgrade had gone smoothly with no hint of any production issues. At this point, though, a second hypothesis appeared: the tests were flaky because they depended on a certain sequence of events. See, the flaky tests were part of our feature test suite; they utilised not just RSpec but also a Selenium headless browser and a test environment comprising of a web/API server, database and Redis server. In these situations, race conditions between the different components are a common cause of flaky tests. Unfortunately, this would lead our investigators off track.
So the suggestion was to slap a sleep in between the test setup and assertions to see if it made the problem go away. This wasn’t a solution, but a way of establishing if the flakiness was the result of a WebSocket message taking slightly too long to arrive.
Chapter 2: Fade to Black
The following Monday, more tests were failing sporadically in the same file as those that had been skipped. Patrick worked with another of our staff engineers who could, unlike Patrick, write actual frontend code. Together they managed to build a reliable reproduction of the bug, although it took up to 30 minutes to produce a failure. After eliminating the possibility of a race condition where messages were delivered after the test suite had run, the team narrowed in on the interactions between ActionCable and Redis.
By adding additional logging, they found the subscribe command was being delivered to ActionCable but wasn’t being received by Redis. Other developers also reported WebSockets often failing in development, indicating it was not only the test environment that was impacted.
At the end of the third day of debugging, seemingly getting nowhere, Patrick got a very unusual error message, which he posted to Slack with the departing words “I think it’s time to give up for the night…”:
ruby(29632,0x2a9f1f000) malloc: Double free of object 0x2a9bb6740
ruby(29632,0x2a9f1f000) malloc: *** set a breakpoint in malloc_error_break to debugThis kind of exception is quite unusual and hints at how deep this bug goes. But the team hadn’t quite gathered enough information to recognise how or even if it related to the failure. Like an installment of the blockbuster movie series Knives Out, even with all the information, it still didn’t make sense.
And yet, with all the pieces on the table, this crime still truly appears impossible. ~ Benoit Blanc
Chapter 3: Everlong
Hello
I’ve waited here for you
Everlong
Successful debugging requires a good dose of skill and a pinch of luck. Late on the following Thursday afternoon, a message was posted in our engineering Slack channel that a build had triggered a segmentation fault. Attached to the build was a core dump.
The core dump was attached because one of our developers was previously trying to debug a crash in the test suite, and had written a plugin to look for the presence of a core dump and, if one was found, upload it to the relevant build as an artifact.
That means it’s time to introduce our third character, Rian, who during his tenure at Buildkite developed a reputation for finding and fixing incredibly obscure bugs (along with the infamous Doom pipeline). The stories are so great that despite Rian’s departure we tell them to new hires, who retell them to others and so on and so forth.
The core dump enabled Rian to inspect the state of the process at the time it crashed, akin to a black box in an aircraft crash investigation. The crash message itself indicated it happened inside the hiredis code, which is a C extension bundled into the redis-client gem. From this, he ascertained that the exception was triggered by a call to the C function memmove. While the source and destination addresses for this call looked sane, the size field was set to 0x00a0ffffffffffb6 , which is about 45 petabytes. Based on this and the fact we’d been seeing other unexpected behaviour since upgrading the Redis gem, it was logical to conclude a memory corruption bug was present in the newest version.
By another stroke of luck, Rian had attended a conference talk earlier in the year called Finding and fixing memory safety bugs in C with ASAN.
With this information, Rian set to work getting the reproducible code running in a version of Ruby compiled with ASAN. It only took a couple of hours to get this running, and within 30 minutes ASAN reported a heap use-after-free. In order to provide concurrent execution, hiredis has two threads for each connection, one for reading and one for writing. The use-after-free was happening because in some scenarios the reader thread would free the writer buffer.
Epilogue: In the End
Once we knew that there was memory corruption and, more importantly, where it was coming from, fixing it was relatively straightforward. Rian disabled using the C extension for Redis connections in test, development and production, and developed a reproducible test case that was reported upstream.
What enabled us to find it in the first place is the interesting part. A combination of deliberate application of our skills in building the necessary tooling, teamwork, and just the right amount of luck. Our tools, such as Test Engine and our coredump-artifact plugin, enabled us to identify the nature of the bug and, combined with using ASAN, where it manifested. Memory corruption bugs such as these can often take months to fix, because having a core dump generated by a segfault only tells you that memory was corrupted at some point in the past, but gives you few clues as to how it became corrupt.
No production data was harmed in the making of this story.