A fun bug we found in our MMO

Our server went down for no apparent reason. Turns out that it ran out of memory. Luckily we had a core dump and thus a useful stack trace with relevant parameters intact.

This showed that it tried to allocate 500MB of message buffer space in one call. But why? The short answer is that it interpreted it as a safe message type because it arrived on a socket that isn't accessible from the outside world, and the length field of the struct was a tad larger than any length field should be. :)

But how did that message even get there on that socket when it should have only been safe messages? The incoming message had entirely the wrong format, resembling an HTTP get request. We make some HTTP requests from the other server, but to external sites, not to the other internal server. How could it get mixed up?

The first thought was that perhaps the pooled TCP socket class had a bug, where data for one of the batch of sockets gets sent to another accidentally. A quick inspection of the code revealed that we weren't using the pooled sockets for this application, though. What was left to go wrong? Just the socket creation and the remote hostname to address lookup function.

Looking at the latter, we spotted the bug immediately; the lookup function, several years old and predating almost everybody on the team, was filling a static data member and returning a pointer to that. This worked fine while all our networking was in one thread, but more recently extra networking threads have been added for slow, synchronous tasks, such as the HTTP request we saw here, arriving on the other server. With several threads overwriting that structure, and player concurrency rising, it was only a matter of time before a function in one thread got back the address that a function in another thread had asked for. In this case an external HTTP query asked for the IP address of an external website and got back an internal IP address and port, which wasn't too happy to receive that HTTP GET request!

Lessons learned:

• core dumps are ace: extensive logging is essential and hand-rolled stack trace functionality is great but you can't beat being able to open up gdb and see the problem as it stands. Without that we would have just had a random out of memory condition crashing a server and no real way of seeing what part of the code caused it, never mind guessing what the input data was.
• Validate your data input! We weren't doing so because it's an internal channel and because we ran up against the arbitrary limit before, but really we should have just upped the limit and added logging when it was exceeded. A search for errors would have then found this issue.
• concurrency is hard: old code needs to be inspected for thread-safety. new code needs to be written with concurrency in mind, not just as a single-threaded program with some background threads and a few locks, as the more shared data you have the more likely that you'll hit upon a bug. better to be safe than sorry with multi-threaded code, using copies of data and high level data exchange mechanisms where possible: micro-optimise later, if and only if you're still maxing out those 4 cores! I'll speak more on this sort of thing in future posts.
• distributed systems are hard: a bug in program 1 might only manifest as a result of a bug in program 2. Or on the other hand an apparent bug in program 1 might just be a valid response to the actual bug which is in program 2. Web developers are very familiar with this phenomenon since browser behaviour depends not only on the browser, but on the HTML code on the server, and indeed the headers served up by the web server. Luckily web transactions carry very little state and are easily logged so such problems, though frustrating, are relatively easy to reproduce and hopefully therefore to fix. With highly-stateful simulations like MMO games you'll often never be able to see what program 2 was doing when it sent the input that broke program 1. This makes it all the more important to get the code right first time.