The Case of the Wrong User

At Twitter I worked on the team that ran ads.twitter.com, the advertiser dashboard where people managed their campaigns. This involved selecting tweets to use as ads, setting budgets and timelines, and viewing analytics about how they were performing. One afternoon in April 2011 we got a note from an advertiser–HBO, I think–that they signed in and found themselves looking at another advertiser’s campaigns. That sounded implausible, but they included screenshots that were quite convincing. In the top corner it showed them signed in as a different user. On the dashboard was a table of stuff they were absolutely not supposed to see.

I should start by noting that for this bug and investigation, I did nothing. At the time I was working on ads in users’ timelines and happened to sit next to the people building the advertiser dashboards. I had less than a year of professional experience and no helpful insights to offer. All I did was listen to and be grateful that nobody was asking me to fix it. This is all to say that when I say “we” below, I am being quite generous to myself–Andrew, Avi, Ben, Colin, Greg, and Lennon did all the work. It’s one of my favorite bug memories though because the source of the bug was so unfamiliar to me.

To return to the facts: this is a terrifying bug. Causing site downtime: bad; losing money: also bad; corrupting data: very bad; but showing one user’s data to another, especially when the data is private, concerns money, etc. is arguably the worst. First, we put the site into maintenance mode so nobody could sign in. Then we added piles of logging everywhere, and in particular to the place where we fetched the user in the sign in path. If we fetched a user that didn’t match the request (for example, if it came back with a different user name than the sign in request), we logged it and threw an exception. This gave the user an error and forced them to sign in again, which is much better than signing in as somebody else.

Shortly after shipping these changes we got a hit in the logs: a user signed in, we looked up the user, and got a different user back. Boom!

At this point I should explain where the users were coming from. Twitter ran a large Ruby monolith, which we unaffectionately called the monorail. It had all the important business logic and data access, but not the advertiser dashboard. Our service was a new, separate Rails application striking out on its own, but like a child, still dependent on the monorail for many important things like users and tweets. For this reason, the monorail exposed an Avro service called the composition daemon which allowed services like ours to do user lookup.

We took our logs to the folks running the composition daemon and asked (professionally) “what the hell is going on?” The user service has one job: you need to give us the users that we ask for. These logs show that you are clearly not doing that. We asked for user A, you gave us user B! So an engineer working on the composition daemon added logging to their side: for every request, they logged which user was requested and what user they returned. They deployed and we waited like fishermen for a bite.

The next day: BLAMMO!

• We asked for user A.
• They received a request for user A.
• They returned user A.
• We received user B.

This is the point at which I would have thrown up my hands. Choosing a career in software was a mistake. Thankfully, we had more experienced engineers on the team. One of them hypothesized that there must be some bug in the networking code. This seemed like a stretch to me, akin to blaming the compiler. The turning point was the moment we saw who wrote the Ruby implementation of the Avro client we were using: Twitter did. The gem was at version 0.0.1. Suddenly it seemed entirely plausible that we were doing something wrong in this home-grown, little-used library.

Our internal Avro client library was a wrapper around the underlying Avro gem that added support for timeouts, retries, and other common RPC concerns. The problem was that we handled some timeout exceptions the composition daemon might return like Errno::ECONNRESET, but not the Timeout::Error produced by caller-side timeouts. When a Timeout::Error was raised, it would propagate up the stack and the user would get an error. But crucially we would not disconnect the underlying Avro client. The TCP socket had a different timeout and was still active. When the composition daemon eventually returned a response, it would end up in the socket’s receive buffer and sit there undisturbed, ready to be read at a later time.

So an advertiser would sign in. We would request user A. The request took too long and our application hung up. The advertiser would see an error, try again, and would probably succeed. But in the background, the user request was still alive. When we finally received a response, the user A object would be written to the receive buffer. At some point in the future that specific application instance–we had dozens–would make a request for user B. As soon as it was sent, we would see that we had a response waiting. We would read it, get the wrong user, and store it as the signed-in user. The fix was a one-liner: properly abort the request on timeout and disconnect the client.

After we merged it, we never saw the mismatched user logs again. We got lucky that this bug happened when Twitter had so few advertisers. I got lucky because I didn’t have to fix what felt like an impossible bug, but got to learn about it for free.

Thanks to Lennon Day-Reynolds who reviewed this write-up.