#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
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
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
(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
(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
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
list again. This takes us in to the
due_on method in the
(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
(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
(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
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.