Simple Unobtrusive Ruby/Rails Debugging

Introduction

When your Rails application goes awry, perhaps the easiest way of tracking down the cause is to add a line to the source that raises an exception with a message that inspects the contents of a variable, for example, raise @user.inspect. You then read the exception details, either in a browser or in the logs. When you've finished, however, you have to remove the said line.

In this little piece, I'll present a way of doing the above without altering any of the application's source code. I'm not sure if this method is any quicker, but it is about as easy and it saves you from having to remove the line later on. Plus, it lets you inspect a number of variables (or expressions) at one time, resumes execution, and gives you the option to redirect output to a file.

Alternatively, the utility can dump all variables, or it can execute a file of arbitrary Ruby code. Both within the scope of a specified line of a source code file. The utility's only disadvantage is that it slows up execution by many orders of magnitude.

It is a stand-alone Ruby module of less than two pages of code in just one file, examiner.rb - http://objectivewebsites.co.uk/ruby/examiner.rb. It has no dependencies and has no side-effects - unless you introduce them yourself! It is too simple to package up, and, as a file in your current directory, you may edit it to suit a particular purpose, or to change its output format.

To bring this utility into action, you can simply require it with the -r switch, (i.e. -rexaminer) from the command line when launching a new Ruby program. Everything else remains intact.

Example

Let's consider a case where a user logs into a Rails application. Suppose we want to see three values, first a local variable called status, second a user's record and third the associated session store, all within the context of a sessions controller's source at a line numbered 42. To begin, we could start the server with:

$ EXAMINE='sessions_controller 42 status session[:user_id] @user' ruby -rexaminer script/server

A preliminary message will suddenly appear that shows details of what the utility will do. Then we log in to the application (in another window) as a known user. And, sometime afterwards, another message will appear (on the server's terminal - among other fluff) that might look something like this:

SessionsController.create ./app/controllers/sessions_controller.rb

42: flash[:notice] = status

  status = "Login accepted"

  session[:user_id] = 17

  @user = #<User:0xb709c2b8 @attributes={"name"=>"drop", "id"="17", ..., "created_at"=>"2010-09-28 13:15:08"}>

The first item gives the current class and method, alongside the path to the actual source code. The next gives the line number and the source code at the given point. The remaining lines are the supplied expressions with the resulting value rendered through the inspect method.

Usage Guide

The utility can be started, together with a Ruby program, from the command line with the following:

$ {environment variable(s)} ruby -rexaminer {ruby program [args]}

This assumes that you have the file called examiner.rb, (available below), in a directory in the $LOAD_PATH. The current directory will do, or if this file is somewhere else entirely, then use the -I switch on the ruby command to specify that directory.

The utility accepts just three environment variables, EXAMINE, EXAMINE_LOG and EXAMINE_ON.

The environment variable EXAMINE (mandatory) contains space-separated values. The first two values are mandatory, the rest are optional. These values are:

1. A regular expression that uniquely matches the path of a Ruby source code file. Putting in the file name should be sufficient, e.g. user.rb.
2. A line number of executable code within the above file, not a blank line, nor a comment, nor an end statement, nor at a class or method definition. Note that the evaluation takes place before the line is actually run, and that line numbering starts at one, not at zero. To list a (source code) file with line numbers you can use $ cat -n {filename} from the command line.
3. If this field is left blank (omitted) it will produce a dump of all local and instance variables. If it has a single value that points to an existing file it will execute the Ruby code contained in that file. If this field doesn't point to a file, then it should contain one or more variables, (or expressions, e.g. product.cost*1.175), which are separated by spaces - so therefore must not themselves contain spaces. The important point here is that this code execution is carried out within the scope of the location stated in 1 & 2.

The environment variable EXAMINE_LOG (optional) is simply a file name to which output is written, otherwise output is to the screen that launches the program (STDOUT).

The environment variable EXAMINE_ON (optional) is a flag which keeps the utility turned on after it has written its output. It normally switches itself off for efficiency. If not null, the value of this environment variable is used to delimit the output. In short, leave it out if in doubt.

Make it Faster

When this utility is invoked with the -rexaminer switch, it takes effect immediately, and if this is combined with lengthy processing before the desired line is reached, a protracted delay will ensue. This can be mitigated by turning it on at a later stage of the initialisation process.

In Rails, this can be achieved - in two commands - by converting the utility into a makeshift plugin. First create a new directory (its name doesn't matter) under vendor/plugins. Second, copy the file, examiner.rb (http://objectivewebsites.co.uk/ruby/examiner.rb), into the new directory with a new file name, init.rb. Then you leave out the -rexaminer switch on invocation, but you still include the environment variables. This will make it less slow. If you do this, you must delete the init.b file once you are done.

If you use this utility while writing tests you could speed things up dramatically by adding a line like require 'examiner' near the top of the test script you're working on. You could also define the environment variables just before this line, and then you won't need to add any parameters to the command that kicks the tests off.

How it Works

This utility borrows from the standard library modules, Tracer and Profile, (which provide details on the steps of a program's execution), and it makes use of the Kernel#set_trace_func method. This method takes a code block that is executed after every significant event that occurs while a Ruby program runs. (This is why the utility dawdles).

The code block passes back six values. The first denotes the event type (see below). The second is the path of the source file. The third is the line number within the file. The fourth gives the current method's name. The fifth is the variable bindings. And the sixth is the current class.

The event type has several values, These are as follows. The values class & end mark the beginning and end of a class definition. The values call/c-call & return/c-return mark the beginning and end of a method call, depending on whether the method is written in Ruby or C. The value line marks some code execution within a line. The value raise marks the raising of an exception.

Source Code

Here's main source code file, examiner.rb - http://objectivewebsites.co.uk/ruby/examiner.rb, which is all you need. Also, there is an example file, reflect.rb - http://objectivewebsites.co.uk/ruby/reflect.rb, that uses Ruby's introspective capabilities to show lots of information at a particular stage of a running program (notably, it gives details on all of the available methods calls). It causes no harm and can be used in the way indicated (in section 3) above. For example (assuming examiner.rb and reflect.rb are in your current directory):

$ EXAMINE='sessions_controller 42 reflect.rb' ruby -rexaminer script/server

Possible Enhancements

To provide more than one breakpoint by using a configuration file rather than using environment variables. To specify a breakpoint with a class and method name rather than a file name filter and a line number. To allow the log file to be opened with an append rather than a write which obliterates the previous data. To save time, provide a finer way of controlling when it is switched on and off. At present it is switched on as soon as it is required - in the last line of the examiner.rb file.