Debug Rails issues effectively with tapping_device
Tags: rails, ruby, tutorial, productivity
Published: 2019-12-22 11:07:37

# Debug Rails issues effectively with tapping_device
Hello everyone, 👋 I’m the author of the [`tapping_device`](https://github.com/st0012/tapping_device) gem, a debugging tool I created a while ago. I'm also a [Rails contributor](https://contributors.rubyonrails.org/contributors/stan-lo/commits) 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`](https://github.com/st0012/tapping_device)  gem help me find the cause of a Rails issue in an hour ;-)

### Basic Intro of tapping_device

 [`tapping_device`](https://github.com/st0012/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:
1. `tap_on!(target)` - you can use it to track all method calls performed on the target
2. `tap_sql!(target)` - this is a Rails-specific helper. You can use it to track on method calls that generate SQL queries
3. `tap_passed!(target)` - you can use it to track what method takes target as its argument

For more info, here’s a [post](https://dev.to/st0012/want-to-know-more-about-your-rails-app-tap-on-your-objects-bd3) contains some useful examples that you can use in your Rails apps.

### The Issue (#38041)

The [issue](https://github.com/rails/rails/issues/38041) is about a behavioral change on `DateTime` calculation:

```ruby
# 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

1. Check if `“2019-12-19 10:00”.to_datetime` returns the same result in both versions
2. Check if `BigDecimal(1).hour` returns the same result in both versions
3. Digging into what happens when calling `DateTime#-` in both versions
4. (Jumping between files and adding breakpoints or `puts`)

### What I did instead, with tapping_device

1. 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.

```ruby
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
```

2. 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`.

```ruby
  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](https://github.com/rails/rails/commit/c85e3f65f3409fc329732912908c3601d8e5fac9).

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`](https://github.com/st0012/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:

1. 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.
2. And it’ll be very easy to lose the big picture when you dive into individual method calls.

But if you use [`tapping_device`](https://github.com/st0012/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`](https://github.com/st0012/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!