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_datetime returns the same result in both versions
Check if BigDecimal(1).hour returns 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!