#54 Debugging Ruby (revised)

Below is a page from an application that lists tasks. There are two lists, one each for tasks that are due today and tomorrow. This application has a bug, however: the “Meet Yoda” task shows up under today’s (April 15th) tasks, even though this task isn’t due until April 16th at 5am.

Why is this task showing up under today’s list when it’s not due until tomorrow morning? In this episode we’ll find out why by using the Ruby debugger then fix this problem.

The Code That’s at Fault

Let’s dive into the code and see how this page works. The code for this action is in the TasksController and it looks like this:

class TasksController < ApplicationController
  def index
    @today_tasks = Task.due_on(Date.today)
    @tomorrow_tasks = Task.due_on(Date.tomorrow)
  end
end

In this action we fetch the tasks for today and tomorrow by using a custom class method called due_on on the Task model which we pass a date. Let’s take a look at that model.

class Task < ActiveRecord::Base
  attr_accessible :due_at, :name

  def self.due_on(date)
    range = date.to_time...(date+1).to_time
    where(due_at: range)
  end
end

In due_on we create a range. This range has a start value of the date that’s passed in and an end value set to the passed in date plus one day, both converted to times with to_time. We then search for tasks that have a due_at value within this range. For some reason this code is finding tasks that fall outside the day that’s passed in to due_on so we’ll use a Ruby debugger to determine what’s causing this error.

Using The Ruby Debugger

First we’ll need to add a debugger to the gemfile. At the bottom of a Rails 3 application’s gemfile there’s a commented-out gem called ruby-debug19. This gem doesn’t work well under Ruby 1.9.3, which is what we’re running our Rails application on, so we can’t use it here. Fortunately there’s a fork of this gem called debugger which does work so we’ll use that instead. We’ll use the group option with this gem so that it’s only installed in the development and test environments. As always when adding a gem to a Rails application we’ll need to run bundle to install it and restart the Rails server if it’s running.

# To use debugger
# gem 'ruby-debug19', :require => 'ruby-debug'
gem 'debugger'. group: [:development, :test]

Now we can add a breakpoint anywhere in our code by making a call to debugger. We’ll add one at the top of the TaskController’s index action.

class TasksController < ApplicationController
  def index
    debugger
    @today_tasks = Task.due_on(Date.today)
    @tomorrow_tasks = Task.due_on(Date.tomorrow)
  end
end

When we reload our tasks page now the browser will appear to hang. This is because our Rails application has been interrupted by the debugger. We can see this if we look in the terminal where we started the server.

$ rails s
=> Booting WEBrick
=> Rails 3.2.3 application starting in development on http://0.0.0.0:3000
=> Call with -d to detach
=> Ctrl-C to shutdown server
[2012-04-15 02:41:15] INFO  WEBrick 1.3.1
[2012-04-15 02:41:15] INFO  ruby 1.9.3 (2012-02-16) [x86_64-linux]
[2012-04-15 02:41:15] INFO  WEBrick::HTTPServer#start: pid=6160 port=3000
/Users/eifion/todo/app/controllers/tasks_controller.rb:4
@today_tasks = Task.due_on(Date.today)
(rdb:1)

The last line here is the debugger prompt. If we’re unsure what to do here we can type help to get a list of the commands it supports.

(rdb:1) help
ruby-debug help v1.1.1
Type 'help <command-name>' for help on a specific command

Available commands:
backtrace  delete   enable  help  list    ps       save    step       var  
break      disable  eval    info  method  putl     set     thread     where
catch      display  exit    irb   next    quit     show    trace    
condition  down     finish  jump  p       reload   skip    undisplay
continue   edit     frame   kill  pp      restart  source  up       

To get more information about that command we can type help and pass in its name. We can view the code around the breakpoint by running list but as most commands have an abbreviated version we can use l instead.

(rdb:1) l
[-1, 8] in /home/eifion/todo/app/controllers/tasks_controller.rb
   1  class TasksController < ApplicationController
   2    def index
   3      debugger
=> 4      @today_tasks = Task.due_on(Date.today)
   5      @tomorrow_tasks = Task.due_on(Date.tomorrow)
   6    end
   7  end

The arrow points to the line of code that will be executed next. If we run next that line of code will be processed and the debugger will stop at the next line. We can inspect variables with the pp command and we’ll do this now to see what the value of @today_tasks is.

(rdb:1) next
/home/eifion/todo/app/controllers/tasks_controller.rb:5
@tomorrow_tasks = Task.due_on(Date.tomorrow)
(rdb:1) pp @today_tasks
[#<Task id: 1, name: "Buy some droids", due_at: "2012-04-15 11:50:00", created_at: "2012-04-15 08:59:06", updated_at: "2012-04-15 08:59:06">, #<Task id: 2, name: "Meet Obi-Wan", due_at: "2012-04-15 14:20:00", created_at: "2012-04-15 08:59:06", updated_at: "2012-04-15 08:59:06">, #<Task id: 3, name: "Find a ship", due_at: "2012-04-15 16:55:00", created_at: "2012-04-15 08:59:06", updated_at: "2012-04-15 08:59:06">, #<Task id: 4, name: "Save the princess", due_at: "2012-04-15 19:30:00", created_at: "2012-04-15 08:59:06", updated_at: "2012-04-15 08:59:06">, #<Task id: 5, name: "Destroy the the Death Star", due_at: "2012-04-15 21:45:00", created_at: "2012-04-15 08:59:06", updated_at: "2012-04-15 08:59:06">, #<Task id: 6, name: "Meet Yoda", due_at: "2012-04-16 05:00:00", created_at: "2012-04-15 08:59:06", updated_at: "2012-04-15 08:59:06">]

We can run any Ruby code we want here so we’ll use map to get a list of the times the tasks are due at.

(rdb:1) pp @today_tasks.map(&:due_at)
[Sun, 15 Apr 2012 11:50:00 UTC +00:00,
 Sun, 15 Apr 2012 14:20:00 UTC +00:00,
 Sun, 15 Apr 2012 16:55:00 UTC +00:00,
 Sun, 15 Apr 2012 19:30:00 UTC +00:00,
 Sun, 15 Apr 2012 21:45:00 UTC +00:00,
 Mon, 16 Apr 2012 05:00:00 UTC +00:00]

The April 16th task is showing up in the list so we’re able to reproduce our error. Let’s try to determine why. We can step into methods with the step command so we’ll do that now then run list again to see where we are.

(rdb:1) step
/usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.3/lib/active_support/core_ext/date/calculations.rb:36
::Date.current.tomorrow
(rdb:1) list
[31, 40] in /usr/local/lib/ruby/gems/1.9.1/gems/activesupport-3.2.3/lib/active_support/core_ext/date/calculations.rb
   31        ::Date.current.yesterday
   32      end
   33  
   34      # Returns a new Date representing the date 1 day after today (i.e. tomorrow's date).
   35      def tomorrow
=> 36        ::Date.current.tomorrow
   37      end
   38  
   39      # Returns Time.zone.today when <tt>Time.zone</tt> or <tt>config.time_zone</tt> are set, otherwise just returns Date.today.
   40      def current

It looks like we’re in the Date class’s tomorrow method. This is great as it means that we can walk through and look at Ruby code that isn’t our own. We’ll skip over this and run next and list again. This takes us in to the due_on method in the Task model.

(rdb:1) next
/home/eifion/todo/app/models/task.rb:5
range = date.to_time...(date+1).to_time
(rdb:1) list
[0, 9] in /home/eifion/todo/app/models/task.rb
   1  class Task < ActiveRecord::Base
   2    attr_accessible :due_at, :name
   3  
   4    def self.due_on(date)
=> 5      range = date.to_time...(date+1).to_time
   6      where(due_at: range)
   7    end
   8  end

The debugger is now at the line of code that sets the range and this is probably the source of our problem. Let’s take a look at the range variable.

(rdb:1) next
/home/eifion/todo/app/models/task.rb:6
where(due_at: range)
(rdb:1) pp range
2012-04-16 00:00:00 -0700...2012-04-17 00:00:00 -0700

This is the range for tomorrow’s tasks and the start and end date do look to be correct so why isn’t our code working correctly? We can run irb to switch to a Ruby shell in the debugger and this way we can debug code directly and inspect any variable that we want to. We’ll use this to look at the SQL that’s used when we search for Tasks by their due_at time.

(rdb:1) irb
irb(Task):001:0> puts where(due_at: range).to_sql
SELECT "tasks".* FROM "tasks"  WHERE ("tasks"."due_at" >= '2012-04-16 07:00:00.000000' AND "tasks"."due_at" < '2012-04-17 07:00:00.000000')

The SQL that runs finds the tasks that are due from 7am on the date passed in to 7am the day after, which is why our early morning “Meet Yoda” task is appearing on the wrong day. This offset is due to a time zone issue. The server that our app is running on is in the USA and is set to Pacific Standard Time which is seven hours behind UTC. When Rails converts a time to an SQL query it converts it to UTC time and midnight in PST is 7am in UTC. We can call date.to_time_in_current_zone to return the time in the zone that Rails is set at and handle the conversion properly.

irb(Task):004:0> date.to_time
=> 2012-04-16 00:00:00 -0700
irb(Task):005:0> date.to_time_in_current_zone
=> Mon, 16 Apr 2012 00:00:00 UTC +00:00

There are other methods that Rails adds to date that will make it more convenient to generate the range variable. Instead of converting the time into the correct zone we can do this:

irb(Task):006:0> range = date.beginning_of_day..date.end_of_day
=> Mon, 16 Apr 2012 00:00:00 UTC +00:00..Mon, 16 Apr 2012 23:59:59 UTC +00:00

This converts both times to UTC and so the SQL query will now have the correct times in it when it’s created. The line of code above will set the value of the range variable in our code so when we exit out of irb here that value will be used and not the one that was set in the code earlier. We quit out of irb by running exit and then we can exit out of the debugger and have it carry on processing the request by running continue. When we do this the response in the browser is interesting. The “Meet Yoda” task is now in both lists.

This is because the list for today was generated before we altered the range in the debugger and so still has the bug in it. We fixed the range before the list for tomorrow was rendered so this is showing the correct items. Now we can go and fix the code in the Task model.

def self.due_on(date)
  range = date.beginning_of_day..date.end_of_day
  where(due_at: range)
end

We’ll remove the call to debugger in the index action too. When we reload the page now both lists are correct.

When you run into an error in your Rails application now, instead of adding puts statements everywhere you should consider using the debugger instead. For an alternative to debugger take a look at the pry_debug plugin. Pry was covered in episode 280.