Section 7: Debugging
Mongrel is designed to help developers get things done. While it also makes deploying Ruby Web applications easier, it is the debugging features that developers love the most. Most folks are not accustomed to having this level of debugging from their Web server, though, so this section will cover all the various things you can find out about your Rails application using Mongrel.
The debugging capabilities in Mongrel were born out of frustration and necessity. It’s frustrating tracking down certain types of defects in a Rails application, and when people have these problems they blame Mongrel. It’s necessary to have strong debugging in order to determine if the problem is caused by Mongrel or by other code.
Using these techniques makes it easier to find memory leaks, open file leaks, various thread issues, and problems with proxy configurations. The tools aren’t the greatest but they’ll help quite a bit in a pinch.
7.1. Available Tools
The primary debugging method in Mongrel is logging. By enabling different options or setting up special handlers you can get Mongrel to log helpful data to files found in the log/mongrel_debug directory. Since Mongrel is easily extensible, you can also use the current handlers as the basis for your own specialized debugging filters.
7.1.1. “Dash-Bee” Logging
The main logging people use is “Dash-Bee” or just -B for the mongrel_rails option that enables all of the available logging filters. It’s very easy:
mongrel_rails start -e production -B
Once you run your Rails application this way, you’ll get tons of information from the log/mongrel_debug directory. Notice that we started in production mode. This is done because in debuggin mode Mongrel is painfully slow, and also Rails development mode does quite a few nasty things to Ruby, which can skew your debugging output.
Right away Mongrel will start logging the following:
accesses Apache-style access logs statements get printed to the console for you to see what requests are coming in.
objects.log Used for debugging memory leaks. For each request a listing of every class currently active in object space, the number of objects of that class, the delta when compared with the last run, and a bit of information on the average lengths of objects that answer to the length method.
files.log Used for finding file leaks, this log contains a list of each currently open file and how many times it’s been opened without a close. File leaks are very crippling to Mongrel since Ruby 1.8.x can only handle about 1,024 depending on the system.
rails.log Many times what you think Rails is receiving is different from what your HTTP client is sending. This log file will tell you exactly what parameters Rails is receiving for each request.
threads.log Library authors love messing with the internals of Threads (specifically the Thread.current[ ] hash). This can cause unexpected behavior and memory leaks. Mongrel will dump the active threads and their Thread.current contents.
Each of these log files will be written to the mongrel_debug directory for each request. There isn’t any locking or coordination done on this logging so you should avoid really thrashing Mongrel in -B mode to get better results.
7.1.2. USR1 Logging
While -B can help you do deeper debugging “back at the lab,” it is not viable for many production situations since it’s slow and does voodoo hackery on Ruby’s internals. To help with two common problems while in production mode, Mongrel has a lighter type of debug logging called USR1 Logging. This mode is a toggled mode that simply flips a global variable to tell Mongrel to log more information when there’s an exception, and to report on a few more key elements.
First, in USR1 mode Mongrel will dump the full request of any client that violates the HTTP specification. You can then use this to see if you should block this client, fix the client, or request that Mongrel’s parser get an update.
Second, it logs at 10-second intervals the number of requests waiting for different Rails actions. This helps you spot the Rails actions and controllers that are blocking your Mongrel processes from continuing. It is a very light logging that will only go to your mongrel.log file (or console if not in daemon mode).
Using USR1 logging is very simple:
killall -USR1 mongrel_rails
On POSIX systems this will tell all your Mongrel processes to start doing USR1 logging. It doesn’t do a restart, stop any active connections, or anything that should impact your running application. It’s also not a performance hit (maybe 1% or so).
Once you’ve gathered some information you can use, then you simply run the killall command again and Mongrel will toggle the logging off.
Zed Sez
Have you ever worked with that one programmer who insists that his code is absolute perfection handed from Gaiai in little baskets woven from gold? You know the guy. He’s the one that’s constantly using big fancy words like “efferent coupling” and “semantic inference,” and claims Haskell/Scheme/Lisp/ML is the greatest language ever.
You probably also have experienced when Super-Software-Architect-Master-Coder writes crap-buggy code yet defends it to his death. He’ll insist that everyone else change to make his junk work. Quite often these so-called “master coders” are actually fairly incompetent and hide behind extensive education to cover their constant failures. I’ve worked with several who would rather quit than admit that they were wrong. Very unprofessional.
These people’s problem is they suffer from Potpourri Turd Syndrome—a belief that their you-know-what don’t stink and smells like fine dew on freshly cut grass. Whenever there’s a bug, they go running like kids in a candy store to other people’s code trying to find fault and just assume that it’s nothing they wrote.
The developers that I consider good always assume that what they write is the first suspect when a bug comes through the door. They will spend quite a bit of time building evidence to rule out possible causes, try to find causes of defects, and have no problem admitting when their designs are flawed.
When you run into a problem with your application, always assume it’s your fault first. Mongrel’s not perfect, but its code is minuscule compared to the size of Rails and most likely even your own application code. Mongrel also powers many large and medium deployments without any problems. If there’s an error, the evidence already says it’s in your code, so bite the bullet and start investigating it as if it’s your problem.
7.1.3. Customized Log Configuration
A more advanced usage of the logging capabilities in Mongrel is to use a mongrel.conf file and the -S option to configure just one of the debugging handlers. This lets you log only the part of the request you need to determine a problem while letting Mongrel run a bit quicker. All you have to do is create a mongrel.conf file with the appropriate Configurator#debug function call.
As an example, we’ll configure just access logging and rails.log parameter logging:
debug "/", what = [:access, :rails]
Place this line in a mongrel.conf and then tell Mongrel to run this file with the -S option:
mongrel_rails start -e production -S mongrel.conf
You could configure your own custom handlers in a special mongrel_debug.conf that you run only in desperation to get special information.
7.2. Common Scenarios
There are quite a few places where your code can go wrong, and since you wrote it, it’s your problem, but here are the most common problems that Rails applications run into. If these don’t help you solve your problem, remember to check out the Mongrel mailing list and the FAQ on the Mongrel Web site (http://rubyforge.org/mailman/listinfo/mongrel-users and http://mongrel.rubyforge.org/faq.html).
Leaking Files Leaking files in Rails is common for people who come from other languages where open files will be closed by the GC. Ruby’s GC isn’t quite that smart, so many new Rails programmers leak files by accident. Using the files.log debugging will show you right away what you’re doing. Best way to avoid it is to always open your files and use them in a block: open(’thefile.txt’) {|f| f.read }
Leaking Objects Leaking in a language like Ruby basically means that you’re storing objects in places where the Garbage Collector (GC) can’t get to them or can’t release them. The object.log will help you spot objects that are getting leaked if you simply look for any class whose delta goes up but never down. You can avoid leaks of this kind by utilizing WeakRef in any internal caching you do, and by not storing things in class variables (@@likethis).
Nobody Likes Mongrel Or, everything’s configured right, but requests just aren’t getting to Mongrel. The problem is difficult to debug without actually looking at the network traffic, but looking at the rails.log will tell you if requests are coming in and being formed correctly. If that doesn’t work then you’ll need to use a packet sniffer to really find out what’s going on.
Jammed Requests This is also known as “stopped mongrel” or “stuck mongrel” and happens when you have a Rails action that seems to never finished. Common causes are having multiple Mongrel processes all trying to use common resources without proper locking. Turning on USR1 logging temporarily in production will help you figure out which action is causing you problems.
EMFILE If you open too many files for either Ruby to handle or for your system’s restrictions then you’ll get a “too many open files” exception in your Rails codes or even at other random locations. Mongrel will log these in the mongrel.log as attempts to kill Threads that are “too old,” but really the problem is you have a Rails action that’s causing the damage. What you want to do is turn on USR1 logging and -B logging to get the files.log. Then look at which request opens the most files and find a way to tone it down.
7.3. Other Tools
When trying to find out what is going on with your server, many times you have to use an external tool. There are tools to help you debug from the client’s perspective, from the server’s perspective, and finally from the network’s perspective.
7.3.1. Client Debugging
When you are not sure if the problem is in the client or the server, simply using one of these tools can really help you rule out the client.
FireBug A very nice tool that lets you view nearly everything about the requests in FireFox.
curl A good command-line tool that you can use to snap headers and data from a server and try out quick parameters to see if what you’re getting is really what a browser should see. Try -I to see the returned headers (a nifty way to verify which Web server is getting hit, Mongrel or your front-facing one).
RFuzz An HTTP client with fuzzing[14] and client testing capabilities that Zed built to help test Mongrel (and also to see just what kinds of crap well-known HTTP servers and Web sites would accept. You’d be amazed). It is an excellent tool for thrashing your own application to find holes, and it happens to be a tight little HTTP client should you want one. It is as compliant an HTTP 1.1 client as Zed could build.
httperf As well as being able to do performance testing, httperf can help you spot stability problems while under heavy loads, and simulate user sessions.
7.3.2. Server Debugging
If you know the problem is with the server, you may still not know what component is responsible. It could be Mongrel, the fronting Web server, load balancers, the operating system, or a bad network configuration. These tools help you test servers in various ways.
Lsof “list of open files” tells you which processes have which files, sockets, domain sockets, etc. open on your server. It will also tell you what state each socket is in and which process owns it. It’s kind of slow and only really works right when run as root, but it’s a great way to find out who’s leaving files open and what files those are. The main benefit of lsof over something like netstat is that lsof works the same everywhere.
netstat Although usually very specific to each particular OS and even different OS versions, netstat will dump tons of different information about your system’s network configuration, including routing, packet transfer statistics, open ports, and who’s currently connected to which processes.
strace You gotta be desperate to turn this on, but if you see a process that’s hung or eating all of your CPU, then running strace (also known as truss on some systems) against it will print out the system calls the program is making. Many times this is all you need to figure out what’s causing the problem.
7.3.3. Network Debugging
When you have no evidence that the client is causing the problem, and you are convinced the server is configured correctly, then you either blame green Pygmy elves or you break out various network debugging tools.
traceroute It’s an old one but good one. Don’t waste hours or weeks trying to find out why a server is slow before you run this tool and make sure the pipes are all running well.
mtr A nicer little graphical version of traceroute is “Matt’s Traceroute”.[15] Works as a GUI tool and a curses interface. It also will calculate better statistics to show you where links in the routing chain are most likely slow or dropping packets.
tcpdump If you’re not sure about the traffic going to your various servers then you can have tcpdump print out information about packets being transmitted on the network. This is a quick way to spot problems with routing, connections, etc. since tcpdump only logs what it sees.
Wireshark (Ethereal) The absolute best network analysis tool out there. It’s changed names, but Wireshark is an incredibly good graphical tool for analyzing network traffic. Think of it as a super fantastic tcpdump. You can capture packet traces, save them to files, use filters to reduce the information, follow TCP streams to see full conversations between peers, and decode entire protocols.
7.4. Reporting Mongrel Bugs
Sometimes Mongrel has defects that you would like to report. This is difficult, though, because many problems aren’t only Mongrel’s, but usually with Mongrel and some Web framework being hosted. Add to this the potential that your code may be broken and debugging gets tougher. What you need to do when submitting a potential defect to Mongrel is to follow this process as best you can:
- Make sure the defect isn’t already reported on the mailing list or the bug tracker.
- Reduce the bug to the simplest code and procedure that demonstrates it. Many times just doing this will help you find any problems and fix them yourself.
- If after reducing the bug you find it’s actually a Mongrel defect, post a report to the http://www.rubyforge.org/projects/mongrel/ bug Tracker.
- Be sure to include the versions of all the software you use, your reduced code, and the test procedure.
- Wait for it to be fixed. Usually defects are fixed in one version and quite quickly.
- If you can submit a patch that fixes it, then that’s great. Make sure the patch is against the release you’re using so we can validate it.
Zed Sez
I’m not a porn star. I know, I look like one, but I’m not. Yet for some reason people feel they can shove giant patches at me without warning me and expect me to take it. I call this “code fisting.” It’s where you make a giant patch but don’t write any tests, don’t ask me if it’s worth doing, and expect it to be applied now! Don’t be a code-fister. I work on this stuff for fun, and really like helping people, but if you’re going to give me a patch, be gentle. Tell me about it, communicate, send me the changes in small chunks, and make sure it’s tested. I call this method of communicating change requests “code lube.”
The worst thing you can do, though, is quote sections of the HTTP 1.1 RFC at me like you’re a fire-and-brimstone minister yelling scripture out of the Bible at your flock. I don’t think any Web server actually conforms to the HTTP 1.1 RFC because it’s vague and complex. Many requirements in the RFC only apply in certain contexts and sometimes they contradict other sections. Rather than being a rules lawyer and throwing a paragraph of the RFC out of context at the bug tracker, go off and implement the requested feature yourself. Code is the currency of respect in the open-source world; write some if you want respect.