Hey, Don’t Dump. Debug!

I often ask other developers for advice. At times, the counsel reinforces my approach; at other times, the guidance challenges my thinking, leading me to refine my code or even pursue a wholly different solution.

Out of curiosity, I also ask other coders about debugging techniques, and more often than not, I am surprised by the answer. Believe it or not, the vast majority relies on liberal “print” statements sprinkled throughout code. Of course, “print” takes many forms—dump pertinent data structures, emit trace statements to standard error, and log interim results in a separate file—and there are cases where these methods are mandated. Still, it puzzles me why more skilled developers do not use a debugger. Extensions to PHP allow for interactive forensics; Perl running within mod_perl supports debugging; and Ruby on Rails’s Mongrel provides the --debugger option to interrupt execution and drop to a debug console.

In my Rails work, I use the debugger extensively. The debugger combines the power of the Rails console and the Interactive Ruby Debugger, irb, and peers into running code responding to incoming requests. Better yet, I can yield to the debugger console anywhere—in a controller, a view, a plug-in or helper. Within the debugger, I can inspect the stack, variables, the params hash, and more.

Installing the Debugger

The debugger, ruby-debug, is provided as a Ruby gem and installs just as easily as any other extension.

$ sudo gem install ruby-debug

Once installed, you can invoke the debugger anywhere in your code with a call to debugger.

class ExampleController < ApplicationController
  def index
    # ...
    debugger
    # ...
   end
end

By default, Rails's script/server ignores calls to the debugger (and instead emits a message such as Debugger requested, but was not available). To enable the debugger and temporarily halt execution at each call, launch Mongrel with the option --debugger.

$ ruby ./script/server --debugger
=> Booting Mongrel
=> Rails 2.3.2 application starting on http://0.0.0.0:3001
=> Debugger enabled
=> Call with -d to detach
=> Ctrl-C to shutdown server

Once the debugger is enabled, each call to debugger generates a command prompt. The prompt is prefaced by the file name and line number where the call occurred and the next line of code to execute.

/Users/supergiantrobot/Projects/dc/trunk/app/controllers/search_controller.rb:32
@results = Part.uniqify( @results ) if logged_in?
(rdb:3)

(The 3 in the prompt is the thread number, which you can safely ignore if you're not juggling multiple threads.) At the prompt, you can type a number of commands to help ferret out your mistake. When in doubt, simply type help for a list of available commands or help command for hints about a specific command.

Commands to Query State

Like gdb (the Linux debugger for many languages) and Firebug (the Firefox debugger for JavaScript), rdb provides instructions to march through code and examine state. Here's an example using some of the most common commands.

The sample code prints the catalog of revisions made to records in the database. The controller is standard; the view is written in HAML, but could just as well be any other format. A call to debugger has been added at the start of the index action.

class RevisionController < ApplicationController
  before_filter :login_required

  def index
  	debugger

    @revisions = Revision.paginate :page => params[:page],
      :order => 'created_at DESC'
  end
end

%table
  - @revisions.each do |revision|
    %tr
      %td
        = revision.author.capitalize
      %td
        = revision.field
      %td
        = revision.value

The first command is list (which can be abbreviated to simple l, or lowercase L). It prints the ten lines of code surrounding the breakpoint to provide context.

.../app/controllers/revision_controller.rb:7
@revisions = Revision.paginate :page => params[:page],
(rdb:20) list
[2, 11] in .../app/controllers/revision_controller.rb
   2    before_filter :login_required
   3
   4    def index
   5      debugger
   6
=> 7      @revisions = Revision.paginate :page => params[:page],
   8        :order => 'created_at DESC'
   9    end
   10  end

The arrow (=>) reflects the program counter, or the statement about to execute. If you type list again, it shows the next ten lines of code.

The next command is print or p. It reveals the value of its argument, and formats the output as inspect would.

(rdb:20) p params
{"action"=>"index", "controller"=>"revision"}
(rdb:20) params
{"action"=>"index", "controller"=>"revision"}

Inspecting a variable is so common, there's a shortcut: omit print and simply type the name of the variable. That's the latter command above.

The backtrace command displays the call stack. The current frame—that is, the frame where you called debugger&mdashl;is numbered 0. Commands such print and list always apply to the current frame.

Preceding call frames are numbered 1, 2, and so on. Use the frame n command, where n is a frame number, to move to a specific frame. Again, an arrow (-->indicates your current frame.

(rdb:20) backtrace
--> #0 RevisionController.index
       at line .../app/controllers/revision_controller.rb:7
    #1 Kernel.send(e#NilClass)
       at line .../actionpack-2.3.2/lib/action_controller/base.rb:1322
    ...
    #44 Mongrel::HttpServer.run
       at line .../mongrel-1.1.5/lib/mongrel.rb:285
(rdb:20) frame 44
(rdb:20) list
[280, 289] in /opt/local/lib/ruby/gems/1.8/gems/mongrel-1.1.5/lib/mongrel.rb
   280                if worker_list.length >= @num_processors
   281                  STDERR.puts "Server overloaded with #{worker_list.length} processors (#@num_processors max). Dropping connection."
   282                  client.close rescue nil
   283                  reap_dead_workers("max processors")
   284                else
=> 285                  thread = Thread.new(client) {|c| process_client(c) }
   286                  thread[:started_on] = Time.now
   287                  @workers.add(thread)
   288
   289                  sleep @throttle if @throttle > 0
(rdb:20) backtrace
   #0 RevisionController.index
       at line /Users/supergiantrobot/Projects/dc/trunk/app/controllers/revision_controller.rb:7

...
--> #44 Mongrel::HttpServer.run
       at line .../mongrel-1.1.5/lib/mongrel.rb:285

By the way, if you want to know what instance variables are defined in the current frame, type instance_variables.

(rdb:20) frame 0
#0 RevisionController.index
       at line .../app/controllers/revision_controller.rb:7
(rdb:20) instance_variables
["@_params", "@request_origin", "@_request", "@search_options", "@performed_render", "@_headers", "@template", "@action_name", "@_response", "@url", "@performed_redirect", "@before_filter_chain_aborted", "@target", "@_session"]

You can also use the var command to query global variables, local variables, and constants and instance variables in any object.

(rdb:20) var global
$! = nil
...
$tcp_defer_accept_opts = nil
$~ = nil
(rdb:20) var local
  __dbg_verbose_save => false
  const_name => :Revision
  e => nil
  parent_qualified_name => nil
  qualified_name => nil
(rdb:20) var instance Inventory
@after_create_callbacks = [#<ActiveSupport::Callbacks::Callback:0x262f35c
@identifier=nil, @kind=:after...
...
@observer_peers = [#<StockObserver:0x25f4090>]
@parent_name = nil

Next: Commands to Control Execution