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

" ) device_for_time . calls . each do | payload | puts ( payload . method_name_and_location + " => #{ payload . return_value } " ) end puts ( "==============================" ) puts ( "Calls on one_h

" ) 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.