Development Blog: Viget Labs

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.