Using ruby-debug to Find Those Hard-To-Reach Places (bugs)

Matt Swasey, Former Viget

Article Category: #Code

Posted on

I've been writing Rails applications for a little over two years now, but only recently has ruby-debug been added to my tool belt. Since then, I've been using it almost every week and have found it super useful.

If you take five minutes to learn the six commands I'll provide for you here, I promise you won't regret it.

The Scenario

I was working with binarylogic's fantastic searchlogic gem in a project recently. I couldn't figure out why mysql "ORDER" parameters were not being produced by searchlogic's search method when chained off of a named scope. For example:

 class Order < ActiveRecord::Base named_scope :active, :conditions => {:state => "active"}, :order => "delivery_date DESC" end 

Using just this named scope, the DB log would reflect this:

 SELECT * FROM "orders" WHERE ("orders"."state" = 'active') ORDER BY delivery_date DESC 

That looks like we would expect. However, when executing a command like this:

 Order.active.search(:state_is => "onhold").ascend_by_delivery_date 

Noting the DB logs, we see this:

 SELECT * FROM "orders" WHERE ((orders.state = 'onhold') AND ("orders"."state" = 'active')) ORDER BY delivery_date DESC 

Notice that our two states are joined with an AND (that's cool), but check out the "ORDER BY" clause. It still reflects a descending order for delivery_date – not what we wanted at all.

So how do we figure out what's going on here? We could write some tests, but I'm afraid that those tests might just confirm what we already know. There is a bug somewhere, but where?

Setup

There are many ways to go about this. The one I came up with could be clever or could just be a hack. I like to create a rake task that invokes the debugger right before the problem line of code, so I created lib/tasks/debug.rake and added this to it:

 namespace :debug do require 'ruby-debug' desc "debug named_scope order issues" task :named_scope_issues => :environment do debugger Order.active.search(:state_is => "onhold").ascend_by_delivery_date end end 

Then in terminal:

 $ rake debug:named_scope_issues 

This will dump us into a debug session.

ruby-debug

What you will see will look similar to this:

 rake debug:named_scope_issues (in /Users/mig/Desktop/store) /Users/mig/Desktop/store/lib/tasks/debug.rake:7 Order.active.search(:state_is => "onhold").ascend_by_delivery_date (rdb:1) where --> #0 at line /Users/mig/Desktop/store/lib/tasks/debug.rake:7 Warning: saved frames may be incomplete; compare with caller(0). (rdb:1) 

From here we have a ton of commands at our disposal, the most important I've found are: help, step, next, list, and var local

help

Help will give you a run-down on all the other commands available to you, easy enough.

 (rdb:1) help ruby-debug help v0.10.3 Type 'help ' for help on a specific command Available commands: backtrace delete enable help next quit show trace break disable eval info p reload source undisplay catch display exit irb pp restart step up condition down finish list ps save thread var continue edit frame method putl set tmate where (rdb:1) 

step & next

step is where you can get down into the nitty gritty goings-on of the code, it will 'step' into the first method it encounters on its current line.

next is like step, only it will evaluate the current line of code without stepping into the methods within, and simply drop down the next line of code in the current method.

list

list will print the current line of code the debugger is waiting to evaluate, along with the preceding and following five lines.

Here we are buried within some named_scope logic:

 (rdb:1) list [169, 178] in /Users/mig/Desktop/store/vendor/rails/activerecord/lib/active_record/named_scope.rb 169 private 170 def method_missing(method, *args, &block) 171 if scopes.include?(method) 172 scopes[method].call(self, *args) 173 else => 174 with_scope({:find => proxy_options, :create => proxy_options[:conditions].is_a?(Hash) ? proxy_options[:conditions] : {}}, :reverse_merge) do 175 method = :new if method == :build 176 if current_scoped_methods_when_defined && !scoped_methods.include?(current_scoped_methods_when_defined) 177 with_scope current_scoped_methods_when_defined do 178 proxy_scope.send(method, *args, &block) (rdb:1) 

The => mark indicates the current line (174)

var local

var local is perhaps the most useful of all the debugger commands for me, it will give a value dump of all the local variables. I keep an eye on this every few lines to detect when variable values have changed.

For example, if we called 'var local' on the previous line, we would get this:

 (rdb:1) var local args => [{:state_is=>"onhold"}] block => nil method => :search (rdb:1) 

Ahh, we can see that we've passed the evaluation of the 'active' scope, and are now evaluating the scope that search() is creating.

Conclusion

You might be thinking that this is a pretty tedious process, and it often is, but for the bugs buried deep within code it's sometimes a good way to go.

I won't take you though the entire debug session here, as it would take a couple screens, and people would probably lose interest. I will say however, that the bug was not in searchlogic's code, but in Rails itself.

Here is a simple example to demonstrate:

 class Order < ActiveRecord::Base named_scope :by_delivery, :order => "delivery_date DESC" named_scope :by_creation, :order => "created_at ASC" end 

Calling:

 Order.by_delivery.by_creation 

Would produce:

 SELECT * FROM "orders" ORDER BY delivery_date DESC 

Hmm...

In the end, the issue was a bug in Rails itself, but this process allowed me to gain a better understanding of how the tools and libraries I use interact with one another. Try giving ruby-debug a whirl in your next project.

Here is a link to the Rails Lighthouse ticket describing this bug.

Related Articles