At the Forge

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.)

I have been using logfiles to assist me in debugging and development for years, starting long before I began to use Rails. But logfiles allow you to see only what has happened in the past, passively. One of the best tools in a Rails developer's toolbox is the console, an interactive command-line interface that allows you to query, execute and test commands and variable values. If you are familiar with Ruby's “irb” for interactive work, the console will be familiar to you.

The console often is the first place that I write any code. It puts you in a context similar to that of a controller, allowing you to talk to the database via ActiveRecord, creating (and modifying and destroying) objects and assigning them.

For example, I often play around with associations and named scopes within the console, testing that I easily can retrieve one object through another or retrieve a subset of objects using a method call. For example, if I have a Person object and a Vehicle object, I should be able to say Person.new.vehicles in the console and get the empty array. Or, I should be able to use a named scope to say Person.men, retrieving only the men from the database.

I also use the console a great deal to test objects for validity. The valid? method for ActiveRecord objects, coupled with the save! method that raises an exception when a save goes wrong, allows me to test objects to see whether ActiveRecord believes they're valid, and why. For example, if I say:

Person.new.save!

I should get a list (not formatted beautifully, I admit) of the validations that have failed—generally indicating which attributes need to be set in order to save the person successfully. True, you always could invoke the errors method on an object after a failed save, but I find this to be faster and more obvious, which is precisely why I'm in the console.

I often use the console to piece together the methods I am going to use or just to experiment with code that eventually will go into a class or module. If you modify a model definition while you're in the console, you need to reload models with:

reload!

so that the console will be synchronized with the current state of the source code.

By default, the console operates in the development environment, so that when you write:

./script/console

you are talking to the development database.

I should note that there are a number of Ruby gems designed to improve the irb experience. One of these is wirble, which colorizes and otherwise improves the irb interface. I have been using it for a while and find it hard to use irb without its various improvements.

A newer entry is looksee, which provides a new lp (lookup path) method that shows each of the methods an object responds to, categorized and sorted as a list of ancestors. Using lp has made it easier for me to know just which class or module definition I need to inspect to investigate a particular method.

If you want to use the console for a production environment, which I often do when debugging problems on a production server, you will need to state the name of the environment explicitly:

./script/console production

I should add that recent versions of Rails include a similar command, dbconsole, which allows you to talk directly to the relational database for the environment to which you're connected. I often use dbconsole instead of typing mysql or psql (depending on the system I'm using). However, it's important to remember that when you work in the Rails console, the objects are subject to validations and other integrity checks that are not present in your raw connection to the relational database. So for safety's sake, it's usually a good idea to do things through Ruby, rather than the database. (Although if your database supports transactions, you can get some element of safety by doing all modifications within a BEGIN-COMMIT block.)

The console, of course, is good for testing code, but you cannot run your entire Rails application inside the console. There are times, however, when you wish you could drop into the console just for a portion of your Rails application to poke around inside it. True, you could use logging statements to write the current state of affairs to the logfile, but there's nothing like interactively exploring an application from the inside to give you a better feeling about how it is working (or not).

The solution to this problem is the deceptively simple ruby-debug gem, which you can install (like all Ruby gems) by saying:

sudo gem install ruby-debug

You then need to include the gem. This typically is done in the development and/or test environment, but not in the production environment, for obvious reasons. Inside of config/environments/development.rb (or test.rb), you add:

require 'ruby-debug'

and you're set to go!

Under most circumstances, ruby-debug will do absolutely nothing. It won't affect your code, execution or anything else. But if you drop the method:

debugger

into your Rails application, the application will halt when it gets to that line and will give you a true debugger, looking something like GDB. You get a few lines of context around the current line, you can print current values (or any other expression) with the p command, and you can move forward in the program on a line-by-line basis with the n command. Your Web browser, which presumably triggers the debugger when it invokes a particular controller action, will hang while you are using the debugger, stepping through the code and inspecting the environment.

To explore things more fully, you can drop into irb at any time, getting another version of the Rails console. This is good when you want to do something more than just examine variable values—exploring the database, for example, or drilling down into the innards of the system.

Note that because of the nature of ruby-debug, it's really only practical for use with HTTP servers that you run in the foreground, such as WEBrick. But there's nothing stopping you from having two different application instances (one using Phusion and one using WEBrick) running in the same environment or working on the same database—just make sure to run them on different ports and be sure to keep track of multiple tabs that you might have open in your Web browser.

I've only begun to use ruby-debug seriously in the past few months, and I'm already wondering how I ever got along without it. If nothing else, exploring my application from the inside gives me many insights that I would never have had otherwise, and it gives me a chance to look at things actively, rather than just using logfiles.

Finally, you might want to try one or both of the commercial Rails services that have sprung up, and which provide monitoring and notifications for Rails applications. I should make it clear that both of these are hosted by for-profit corporations, and that although they are offering free versions of their products, their ultimate goal is presumably to make money.

New Relic RPM is a performance monitor that you install into your Rails application as a plugin. Every few minutes, the plugin reports your current application status back to New Relic's servers, where the data is then made available in an easy-to-understand format. New Relic's basic offering is free, and although it is much more limited than the commercial versions, I have found it to be highly useful in giving me a snapshot of the current system performance and bottlenecks. If and when your site brings in some money, it might be worthwhile to pay for one of New Relic's commercial products, which provide not only an indication of controller and server performance from the last 30 minutes, but also from the last few weeks, as well as more detailed analyses of memory, database and CPU use, among other things.

Hoptoad, a service run by Thoughtbot, is similar to New Relic RPM, in that it has a free version as well as a commercial one. Hoptoad is similar to many notification systems, and it sends you e-mail when an exception occurs in your application. However, it keeps track of the entire stack trace and request context, and it also keeps a log of it on Hoptoad's Web site, keeping similar errors together. You also can indicate when you have resolved a problem, using it as a primitive sort of bug-tracking application. (Although I find it annoying that you receive e-mail only the first time a particular error manifests itself, until you mark it as resolved.) Hoptoad has made inroads into many Rails projects on which I have worked, and I have found it to be more reliable and easier to use on my projects than simpler exception-notification systems.

Debugging Web applications has never been easy, but the Ruby on Rails community has managed to create a set of useful and powerful tools that can make a big difference to average Web developers. Whether you are a new developer or an experienced one, having these tools in your toolbox can make you more effective at finding bugs and at getting your application, bug-free, out the door for your customers.