Debug Rails issues effectively with tapping_device
Hello everyone, 👋 I’m the author of the tapping_device gem, a debugging tool I created a while ago. I'm also a Rails contributor that helps people solve their issues from time to time. Today I want to use a real-world example to demonstrate how did the tapping_device gem help me find the cause of a Rails issue in an hour ;-)
Basic Intro of tapping_device
tapping_device is built on top of Ruby’s TracePoint. It has several helpers that provide a high-level point of view of how your program runs. For example:
-
tap_on!(target)- you can use it to track all method calls performed on the target -
tap_sql!(target)- this is a Rails-specific helper. You can use it to track on method calls that generate SQL queries -
tap_passed!(target)- you can use it to track what method takes target as its argument
For more info, here’s a post contains some useful examples that you can use in your Rails apps.
The Issue (#38041)
The issue is about a behavioral change on DateTime calculation:
# Rails 5.2.4.1: OK
“2019-12-19 10:00”.to_datetime - BigDecimal(1).hour
=> Thu, 19 Dec 2019 09:00:00 +0000
# OK
# Rails 6.0.2.1: WRONG
“2019-12-19 10:00”.to_datetime - BigDecimal(1).hour
=> Thu, 19 Dec 2019 08:59:59 +0000
It’s clear that something has been changed between version 5.2.4 and 6.0.2. But we don’t know where's the change nor when it’s been made.
How I’d do, in the past
- Check if
“2019-12-19 10:00”.to_datetimereturns the same result in both versions - Check if
BigDecimal(1).hourreturns the same result in both versions - Digging into what happens when calling
DateTime#-in both versions - (Jumping between files and adding breakpoints or
puts)
What I did instead, with tapping_device
- I wrote a script that prints out how the objects are used by tracking their method calls. The first thing I’d check is that what’s returned in each method call so I can locate what’s been changed. And it’s also important to see where the calls were performed.
require "active_support/all"
require "tapping_device"
puts("Rails: #{ActiveSupport.version}")
time = "2019-12-19 10:00".to_datetime
one_h = BigDecimal(1).hour
device_for_time = TappingDevice.new
device_for_one_h = TappingDevice.new
device_for_time.tap_on!(time)
device_for_one_h.tap_on!(one_h)
time - one_h
puts("Calls on time\n")
device_for_time.calls.each do |payload|
puts(payload.method_name_and_location + " => #{payload.return_value}")
end
puts("==============================")
puts("Calls on one_h\n")
device_for_one_h.calls.each do |payload|
puts(payload.method_name_and_location + " => #{payload.return_value}")
end
- Then I ran the same script on both versions. Here are the outputs:
Output - Rails 5.2
Rails: 5.2.4
Calls on time
Method: :acts_like?, line: /Users/st0012/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4/lib/active_support/duration.rb:404 => true
Method: :+, line: /Users/st0012/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4/lib/active_support/core_ext/date_time/calculations.rb:113 => 2019-12-19T09:00:00+00:00
Method: :since, line: /Users/st0012/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4/lib/active_support/duration.rb:410 => 2019-12-19T09:00:00+00:00
Method: :plus_with_duration, line: /Users/st0012/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4/lib/active_support/core_ext/date/calculations.rb:102 => 2019-12-19T09:00:00+00:00
Method: :-, line: time_test.rb:15 => 2019-12-19T09:00:00+00:00
==============================
Calls on one_h
Method: :is_a?, line: /Users/st0012/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4/lib/active_support/duration.rb:145 => true
Method: :-@, line: /Users/st0012/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4/lib/active_support/core_ext/date/calculations.rb:102 => -3600.0
Output - Rails 6
Rails: 6.0.2
Calls on time
Method: :acts_like?, line: /Users/st0012/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2/lib/active_support/duration.rb:405 => true
Method: :+, line: /Users/st0012/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2/lib/active_support/core_ext/date_time/calculations.rb:113 => 2019-12-19T08:59:59+00:00
Method: :since, line: /Users/st0012/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2/lib/active_support/duration.rb:411 => 2019-12-19T08:59:59+00:00
Method: :plus_with_duration, line: /Users/st0012/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2/lib/active_support/core_ext/date/calculations.rb:102 => 2019-12-19T08:59:59+00:00
Method: :-, line: time_test.rb:15 => 2019-12-19T08:59:59+00:00
==============================
Calls on one_h
Method: :is_a?, line: /Users/st0012/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2/lib/active_support/duration.rb:144 => true
Method: :-@, line: /Users/st0012/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-6.0.2/lib/active_support/core_ext/date/calculations.rb:102 => -3600.0
We can see that the + method call’s results were different in the 2 versions. Version 5.2.4 returned 2019-12-19T09:00:00+00:00 while 6.0.2 returned 2019-12-19T08:59:59+00:00. Let’s check what’s defined in active_support/core_ext/date_time/calculations.rb:113.
def since(seconds)
self + Rational(seconds, 86400)
end
Nothing weird. Maybe it has been changed recently?
$ git blame lib/active_support/core_ext/date_time/calculations.rb | grep 113
c85e3f65f34 (Edouard CHIN 2018-10-09 13:36:56 -0400 113) self + Rational(seconds, 86400)
commit c85e3f65f3409fc329732912908c3601d8e5fac9
Author: Edouard CHIN <edouard.chin@shopify.com>
Date: Tue Oct 9 13:36:56 2018 -0400
Fix issue where duration where always rounded up to a second:
- Adding a Float as a duration to a datetime would result in the Float
being rounded. Doing something like would have no effect because the
0.45 seconds would be rounded to 0 second.
```
ruby
time = DateTime.parse("2018-1-1")
time += 0.45.seconds
```
This behavior was intentionally added a very long time ago, the
reason was because Ruby 1.8 was using `Integer#gcd` in the
constructor of Rational which didn't accept a float value.
That's no longer the case and doing `Rational(0.45, 86400)` would
now perfectly work fine.
- Fixes #34008
Bingo! There was a round call in 5.2 but it has been removed 6.0 via this commit.
Isn’t this a super-easy way to debug an issue 😉
What does this mean to me (and you)?
As you can see from the above example, what tapping_device provides is a new way to spot behavioral changes in your program.
Whether you’re a pry/bye bug debugger or a put debugger, you always need to go through files so you can build a rough execution path of the program in your mind before actually adding breakpoints or puts to the right location. The downsides of this are:
- If you’re not familiar with the codebase or it’s not written in an easily-understandable way, there could be a lot of trial-and-error before you actually found the right place to inspect your program.
- And it’ll be very easy to lose the big picture when you dive into individual method calls.
But if you use tapping_device, you can inspect the program from an object’s point of view. This means you won’t need to know which way it’ll go to intercept it. You just need to know where it’ll start its journey! It can save you hours when debugging a large application/library.
I hope you can give tapping_device a try after reading this post. And if you do try it, please don't be shy to give me any feedback! I’d love to fix any issue or add any feature that can help people debug more happily!
Top comments (1)
Thanks for sharing this. This is really interesting post. I would definitely try this out.