Everyone loves a good bug hunt story so I'll share one of the hardest
technical problems I've ever solved, and certainly the one that makes the best story. Strap in; this is a long one.
The year was 2015 and the Christmas break was fast approaching. Unfortunately, while the rest of the office thinned out, another engineer and I were stuck debugging an increasingly urgent production issue. What had started weeks prior as some random intermittent failures in a few of our microservices had slowly escalated into a crisis where more and more services were experiencing failures. We didn't have great monitoring back then to trace any given request through the system's various microservices and figure out where the bottlenecks were - all we knew was that lots of requests were getting backed up somewhere.
We soon found Nagios metrics indicating that one particular critical service on a few boxes had been seeing steadily increasing CPU usage over the past days and weeks. It had reached a point where the service, which is normally heavily IO-bound, was actually now CPU constrained. Our suspicions therefore quickly centered on this service. Failures here could very well lead to the cascading failures we were seeing across our system. A small but increasing percentage of requests to this service were timing out. This made upstream services time out, which in some cases made their upstream services time out.
Once we had sorted through the chaos of cascading failures, we were pretty sure that this one critical service was the root cause of all of the trouble, so we restarted it, one slave at a time so as not to cause downtime for the whole product. Each instance came back up 100% healthy, with completely normal CPU usage. Odd. But sure enough, within a day, CPU usage was spiraling out of control again.
We knew the problem would just come back again if we kept restarting it, so we enabled JMX on the JVMs and attached VisualVM to take some thread dumps and run the profiler. After plenty of head-scratching at the stack traces and close examination of the code, we finally figured out what was going on...
One of our developers had helpfully provided an implementation of java.io.OutputStream for writing data back from the server to the client. The one thing you should know about OutputStream is that it's a blocking interface - if you write data to it, the data is written, and if there's a failure then it should throw an exception right then and there, before the method returns, so that the caller knows there was a failure. The one problem with this is that our Java services were based on Netty, which is based on java.nio, which is asynchronous. When you write to a Netty channel, you don't get feedback right away on whether the data was successfully written to the underlying socket. Instead, you get a java.util.concurrent.Future which will eventually tell you whether the write succeeded. It should be obvious that there's a major impedance mismatch between trying to implement a blocking I/O interface using nonblocking I/O primitives. Our developer had decided to handle this by kicking off the I/O and then simply completely discarding the Future that the write call returned!
What would happen is that sometimes a client would disconnect while we were in the process of returning a response, but the application would never find out because it never checked the status of those discarded Futures. So the application would happily keep streaming data through this OutputStream back to the client. Every time the buffer was flushed, the data would make its way through the Netty pipeline all the way to the bottom, where the write would fail. This generated a rather large stack trace. This stack trace was written to disk - and because it was written directly to standard error rather than via the normal logging infrastructure, we never saw it. But it was being written nonetheless, and every flush of the buffer would cause a new stack trace to be generated and written out. It turns out that this is a rather expensive thing for the JVM to do in a tight loop for dozens or hundreds of concurrent connections.
Our solution was to do the obvious thing that should have been done in the first place and check the results of the damn futures! Every API in the service was depending on there being a blocking OutputStream to write data to, and we didn't particularly want to do a major refactor over to async I/O and push out such a high-risk change right before the Christmas break. So we made a seemingly-harmless change, very minor, which should have fixed the issue and cleared us for a well-deserved vacation. Where before the code was letting the Future fall out of scope unused, now we made it block on its result, so that it could throw an exception to stop the application if there was a failure.
When we deployed this fix and restarted the servers, the CPU usage remained normal. We breathed a sigh of relief. Then, a few hours later, things got interesting.
On one of my monitors I happened to be tailing the logs on one of the servers and noticed, all of a sudden, a cascade of these messages flowing down my terminal:
WARN c.s.j.rep.utilint.ServiceDispatcher - Server accept exception: class java.io.IOException : Too many open files
Sure enough, netstat showed thousands upon thousands of open TCP connections, enough to exhaust all of the file handles that the Linux kernel was willing to allocate to the JVM.
netstat reported that these connections were almost all stuck in a CLOSE_WAIT state. What the hell did that mean? I had taken a couple of networking courses in college, one lab course from a tech's perspective and another programming course from an engineer's perspective, so I was pretty handy with the tools and the general theory. I went home to get a textbook and found the TCP state diagram:
http://www.ssfnet.org/Exchange/tcp/Graphics/tcpStateDiagram1...
We took some packet dumps with tcpdump to make sure that the client wasn't misbehaving. It wasn't. After noodling over the packet dumps, the state diagram, and RFC 793 for a bit, it became clear that the client was sending a FIN segment, but our application was never acknowledging that by calling close on the socket. The TCP stack would hold the connection open until it reached a timeout, at which time it would close the socket for the application. But the application quickly supplied more stuck sockets to replace the ones killed by the networking stack.
Christmas Eve arrived and I needed to get on a flight back to the East Coast to visit family. We decided that over the break we'd conduct rolling restarts of the servers to clear out stuck sockets before they reached the maximum, and pick the problem up after the new year.
After the holiday, we were able to locally reproduce the issue by introducing a lengthy sleep stage inside our Netty pipeline. We went through the Netty library's source code line by line to see exactly what was happening. As we picked through the code one of us stumbled upon the following Javadoc comment:
https://github.com/netty/netty/blob/6e840d8e62e98590e129ab6f...
Thank Christ for the Java community's pathological love of absurdly prolix Javadoc. That footnote broke the case wide open. If you don't see the issue yet, I'll lay it out... in the next comment - HN won't let me post the whole thing in one comment.
