At the Forge - Debugging Rails Applications

The past few months, I've covered a number of automated testing systems available to Ruby programmers in general and Rails developers in particular. Automated testing, especially when you use it before and while you develop (as opposed to afterward) is a terrific way to improve the quality of your design, as well as the robustness of your code. Whether you practice TDD (test-driven development), BDD (behavior-driven development) or something similar to the two, your software is likely to have fewer bugs and be more maintainable than its untested counterparts.

So, does that mean software written in this way has no bugs? Let's not be silly—of course it does. But, if you have been serious about testing, you are likely to have fewer bugs, and they may well be harder to detect and more subtle.

If the bugs are smarter (or craftier), your debugging and testing tools need to be smarter too. Fortunately, as the Ruby language and the Rails framework for Web development have become increasingly popular, a number of talented developers have stepped up to the plate, offering a variety of sophisticated tools that can help you identify and squash bugs as they occur.

This month, I describe a few of the tools that I use when developing Web applications using Ruby on Rails. If and when you get stuck working on a Rails application you are developing, I hope some of these techniques will help you identify and solve the problem more quickly than before.

I'm a big fan of logfiles. When something goes wrong on my computer or in a program I've written, my first instinct is to check the logs. When I am teaching a class in Rails development, and people ask why their program doesn't work, my first response always is to ask them what the logfile says. It can be an invaluable starting point for debugging problems.

Fortunately for me, the Rails core team also likes logfiles quite a bit. Each environment—and there are three by default, for development, testing and production—has its own logfile, named log/ENVIRONMENT.log, under the application's root directory.

Just what is put into the logfile depends on the settings you have made. By default, the development logs include a great deal more detail than the production logs, showing you (among other things) the actual SQL queries that are being sent to the database. Each log message has a level associated with it, much as you might have seen in other logging systems, such as Apache or log4j. A logged message is written to the logfile only if it is at least as important as the current environment's minimum logfile priority (in increasing order of priority: debug, info, warn, error and fatal). Thus, a fatal log message always will be written to the log, while a debug message will be written only if the current environment's log level is debug.

The logfile is useful in at least two ways. First, it allows you to see what is happening inside your program as it executes, particularly when something goes wrong. In the development environment, a fatal error will produce a stack trace in both the browser and in the logfile. But in the production environment, you probably don't want the world to see the internals of your code's flaws. For this reason, stack traces appear only in the production log, while the browser shows an error message. Tracing through a logfile is, as I stated earlier, my favorite way to figure out what is happening in a program.

In addition to the stack backtrace, the logs (and particularly the development logs) contain a wealth of other information, as you can see from this short example:

Processing ReviewController#view_one_review (for 74.212.146.115 
at 2009-11-10 09:25:55) [GET]
  Session ID: 9513bd79785b3d037804b45709a1f12c
  Parameters: {"id"=>"2567"}
Rendering template within layouts/one-review.rhtml
Rendering review/view_one_review
Completed in 1400ms (View: 16, DB: 973) | 200 OK
[http://example.com/book_reviews/view_one_review/2567]

The first line shows the date and time when the request was made, the controller and action that were invoked, and the URL (at the bottom of the log entry) that caused that controller and action to be invoked. It shows that the HTTP response code was (200, or “OK”) and how long it took to execute, giving you a rough sense of how efficient a particular method might be. And, you even get a breakdown of how long the database and view each took, allowing you to focus your optimization strategy on the truly needy methods in your system.

You also get the full list of parameters that were submitted to the controller action. This has been particularly useful to me on numerous occasions when I get calls from clients. Being able to look at the parameters that were submitted to the controller action allows me to test those precise parameters and trace their usage through the system.

Finally, you can see which view templates were rendered. Especially on a site with a complicated set of views, it's often helpful to know just what is being invoked and displayed.

In the development environment, you also will see things like this:

Parameter Load (1.9ms)   SELECT * FROM "parameters"
          WHERE ("parameters"."param_name" = E'Blocked IPs'
          AND "parameters"."param_group" = E'Restrictions') LIMIT 1
PaymentMethod Load (2.0ms)   SELECT * FROM "payment_methods"
          WHERE (disabled = false) ORDER BY payment_method_name
State Load (6.5ms)   SELECT * FROM "states" ORDER BY abbreviation

In other words, you can see when objects are being initialized from the database and what queries are being used in order to do this.

So far, I've shown how you can use the default output in Rails logfiles to find useful information about what your application is doing. But I often find it useful to write information to the logfile as well, indicating where I am in the code or that a particular task has been accomplished. For example, on a bookstore application that I worked on with a complicated pricing algorithm, I would log each calculation in that pricing algorithm to the logfile. This would allow us to “replay” the algorithms as users saw them and double-check our work in a variety of ways.

To log information to the Rails logs, simply use the logger object and send it a message corresponding to the log level you want to use. For example, if you want to know whether a product is in stock, you could say:

logger.warn "Checking to see if ISBN '#{isbn}' is in stock."
if Isbn.in_stock?(["isbn = ? ", isbn])
  logger.warn "\tYup, we have it!"
end

Such “chatty” logs might be slightly inefficient, but they make it easier to read (and follow) what is going on inside your program, on the occasions when you need to read the logs to debug problems. Remember, you are creating these logfiles knowing you will need to read them someday, and by making them as enjoyable, flowing and enlightening as possible, you will make that experience far more pleasant.

I tend to use the warn level for most things I write to the logs and use debug when I want something to appear only in the development logs. If I have to display a complex data structure, I often will display it using YAML, with the .to_yaml method. This makes it easier to understand structures, particularly when you're interested only in one or two of its attributes.

I'm also a heavy user of tail -f on logfiles, which allows me to see the logfile as it grows. Combined with grep, this makes it possible to search for the occurrence of particular methods, values or anything else that might appear in the logfile. For example, you can look for every mention of a Person object with:

tail -f log/development.log | grep Person

If I want to peek at a value across many different invocations, I sometimes will put a special marker, such as the method name, in my logger call, by putting the following in a controller method:

logger.warn "[interesting_method] The value is '#{foo}'."

Notice that I put single quotes around the value; this allows me to identify whitespace and empty strings more easily. I then can see whenever this code is invoked:

tail -f log/development.log | grep interesting_method

Although I most commonly look at the development log (while writing code) and the production log (on a running server), I also have found occasion to look at the testing log, which shows the results of running tests. (If you are testing with Cucumber, realize that it has its own environment and logfile.)