Optimize Your Debugging Process With Object-Oriented Tracing and tapping_device
Tags: showdev, rails, ruby, tutorial
Published: 2020-01-21 13:15:50


As programmers, debugging is one of our daily tasks. And it’s important to sharpen our debugging skills along with other programming skills. But have you ever noticed that, when we’re getting better and better at refactoring, testing, and other coding skills, our debugging skill doesn’t grow as fast as them? In fact, I found myself still using the same debugging tool and process I used 2, 3 years ago.

In the past few weeks, I tried to find a way to debug more effectively. In this post, I will share the reason why it is so hard to improve our debugging skills and how I come up with another approach to tackle this issue.

(To make it easier to explain, the “Bug” here only refers to **a piece of code that breaks a previously working program**.)

## Table of Content
1. How Do We Debug Our Program - Path Comparison Debugging
    1. Build Execution Paths
    2. Compare Execution Paths
    3. The Technical Challenge of This Technic
2. Object-Oriented Tracing
    1. What Is It
    2. What Problem Does It Solve
    3. TappingDevice
3. Conclusion

## How Do We Debug Our Program

The way we usually debug our program is actually very primitive: “Compare”. We do it by comparing how the program should work with how it actually works, and find the places that act differently during the program execution. Most of the time, those places are the keys to finding the bug, if not the bug itself. It’s a 3-steps process:

1. Build the Expected Execution Path
2. Build the Actual Execution Path
3. Compare Both Paths

For example,

![code paths image](https://i.imgur.com/EXf9URA.png)

### Build the Execution Paths

The “Execution Path” of a program can somehow be thought of as its path of method/function calls, or simply call it "call path". But depends on the size of the program, it might perform many method calls. So usually, we only mean “the call path of business logic related methods”. For example, during a request to `OrdersController#create`, there can be many method calls like, `Array#[]`, `Object#inspect`…etc. But when we’re building the execution paths, we only care about those related to Order’s creation and ignore others.

### Compare Execution Paths

Under most conditions, the bug of the program can be found in the first place that acts differently (returning a different value, calls different methods…etc.). So in the following case, the bug is probably inside the `bar` method or its dependencies.

![bug in bar method's example](https://i.imgur.com/TO3Bcb6.png)

### The Challenge of This Technique

I believe most people debug like this approach, but not exactly the same. Ideally, we should build the execution paths as detailed as possible, so we can have enough information to make an accurate comparison. However, in reality, for reasons like the limit amount of time, or laziness..etc., we usually just pick some methods that we “guess” are related to the bug, and hope we made the right guess. 🤞

![ideal vs reality](https://i.imgur.com/pBmZf0u.png)

It means that the effectiveness of our debugging practices are determined by the method we pick to build the paths. And that can be affected by 

1. Our experience in the language/framework
2. How well do we understand the codebase
3. Luck?

This is why we still debug faster over time, even though we don’t put too much attention on our debugging skills.

In my opinion, the root cause of this phenomenon is that we don’t have an efficient tool to work with our debugging strategy. Whether you’re a `puts` debugger or a `pry`-debugger. For most of the time, inspecting the program’s behavior is an overwhelming job, for several reasons:

1. We need to collect  arguments manually

	```ruby
	# super annoying
	def foo(var1, var2)
	  puts("var1: #{var1}")
	  puts("var2: #{var2}")
	  # …
	end
	```
2. We need to collect return values manually

	```ruby
	# eithr
	def new_cart(attributes)
	  Cart.new(attributes).tap { |c| puts(c) }
	end

	# or 
	cart = new_cart(attributes)
	puts(cart)
	```

3. We need to jump between different methods, or even files to place the `puts` or breakpoints.

The more manual job it needs to collect information, the more likely we’ll just make a guess and take a chance. Despite being annoying, manually collecting these different kinds of information also creates other problems:

1. To collect the information we need effectively (e.g., at the right place, call the right method), we need to understand the program well enough. So the less experienced you are, the harder you can understand the program.
2. Adding breakpoints or tracing methods is a kind of code pollution. For example, if a method changes an object’s state and you call it when tracing the code (to get its return value or something), it’d change the program’s behavior.
3. In my personal experience, when messing around with the code, it’s easy to forget my original purpose is just to inspect the method call and start digging deeper.

## Object-Oriented Tracing
But if we look at our debugging behavior close enough, we can find some patterns that we might take advantage of. For example:
1. If you’re debugging a web application’s feature, we can start from a specific endpoint’s logic (e.g., particular controller action). Which gives us a perfect position to start the debugging process.
2. In an object-oriented programming language like Ruby, a feature can usually be linked to 1 or a few classes. For example, you know you should look for something like `OrderCreationService` when there’s a bug about orders. So you can build the most of the execution paths by observing one or a few object’s method calls.

And the concept “Object-Oriented Tracing” is built upon the above assumptions and Ruby’s powerful `TracePoint` feature. Let me explain it with examples.

Assume we have an `OrdersController#create` endpoint for creating orders

```ruby
class OrdersController < ApplicationController
  def create
    @cart = Cart.find(order_params[:cart_id])
    promotion = Promotion.find_by(id: order_params[:promotion_id])
    @order = OrderCreationService.new.perform(@cart, promotion)
    ……
  end
```


And we want to build the execution path of Order’s creation. We can write 

```ruby
class OrdersController < ApplicationController
  def create
    @cart = Cart.find(order_params[:cart_id])
    promotion = Promotion.find_by(id: order_params[:promotion_id])

    TracePoint.new(:call) do |tp|
      if tp.self.class.name == "OrderCreationService"
        puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
      end
    end.enable do
      @order = OrderCreationService.new.perform(@cart, promotion)
    end
```

Which would print

```
Called :initialize from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:2
Called :perform from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:6
Called :validate_cart from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:17
Called :apply_discount from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:23
Called :create_order from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:27
```

Now we know what the `OrderCreationService` does to create an Order, we have a pretty clear execution path immediately. But with some of Ruby’s meta-programming tricks, we can get more information, like each method call’s arguments!

```ruby
class OrdersController < ApplicationController
  def create
    @cart = Cart.find(order_params[:cart_id])
    promotion = Promotion.find_by(id: order_params[:promotion_id])

    TracePoint.new(:call) do |tp|
      if tp.self.class.name == "OrderCreationService"
        puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
        tp.binding.local_variables.each do |name|
          value = tp.binding.local_variable_get(name)
          puts("  Arg #{name}: #{value.inspect}")
        end
      end
    end.enable do
      @order = OrderCreationService.new.perform(@cart, promotion)
    end
```

```ruby
Called :initialize from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:2
  Arg options: {}

Called :perform from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:6
  Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
  Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">

Called :validate_cart from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:17
  Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">

Called :apply_discount from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:23
  Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
  Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">

Called :create_order from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:27
  Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
```


Isn’t this super cool? Now we know what method got called and what arguments they took. Let’s add the last piece of information: the return value.

```ruby
class OrdersController < ApplicationController
  def create
    @cart = Cart.find(order_params[:cart_id])
    promotion = Promotion.find_by(id: order_params[:promotion_id])

    TracePoint.new(:return) do |tp|
      if tp.self.class.name == "OrderCreationService"
        puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
        tp.binding.local_variables.each do |name|
          value = tp.binding.local_variable_get(name)
          puts("  Arg #{name}: #{value.inspect}")
        end
        puts("  => #{tp.return_value}")
      end
    end.enable do
      @order = OrderCreationService.new.perform(@cart, promotion)
    end
```

```ruby
Called :initialize from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:4
  Arg options: {}
  => {}

Called :validate_cart from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:21
  Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
  =>

Called :apply_discount from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:25
  Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
  Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
  => true

Called :create_order from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:29
  Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
  => #<Order:0x00007f91455ebd10>

Called :perform from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:13
  Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
  Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
  => #<Order:0x00007f91455ebd10>
```

If you read the above example carefully, you’ll notice that there are other changes in the code and output, except for the return value:

1. `TracePoint` now tracks `return` event, instead of the `call` event like other 2 examples.
2. The output’s order is somewhat different from the previous ones.

This is because we need to wait for a method call to finish (return) before we can retrieve its return value. So the output is ordered by the time the method is returned, instead of called. For example:

```ruby
def perform
  # …
  create_order
end

# call order: perform -> create_order
# return order: create_order -> perform
```

Once we understand this small difference, this small change in the output won’t confuse us that much. In fact, I sometimes find it more useful in some instances. e.g., when I want to observe how different methods update and return the same value, ordering them with return value makes more sense.

With Object-Oriented Tracing, now we can know the program’s call path, each call’s arguments, and even their return values in a glance. Other than being super-efficient, object-oriented tracing also avoids some problems I mentioned earlier:
1. In the past, we need to understand what `OrderCreationService` would call, in order to get inside those methods and collect the information we need. Now we only need to know where would `OrderCreationService#perform` be called (which is super easy to find).
2. Unless we need more detailed information or perform some tests on the logic of `OrderCreationService`, we don’t need to touch any line of its code. So we can keep it clean even while debugging.

### TappingDevice

Although `TracePoint` is already capable of doing what we want, there still are things we can do to make it easier:

1. The boilerplate code is quite long (~10 lines). It’s not so easy to remember.
2. If you’re not familiar with `TracePoint`, it could take you some time to deal with some edge cases (trust me, I’ve been there before). This means the boilerplate code might end up getting longer to work around those cases.

This is why I created [tapping_device](https://github.com/st0012/tapping_device) to make this easier for you! Do you still remember the code we wrote in the last example? Well, I don’t. And I don’t want to remember it! How about making that piece of code into just one method call? Instead of

```ruby
  def create
    @cart = Cart.find(order_params[:cart_id])
    promotion = Promotion.find_by(id: order_params[:promotion_id])
    service = OrderCreationService.new

    TracePoint.new(:return) do |tp|
      if tp.self.class.name == "OrderCreationService"
        puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
        tp.binding.local_variables.each do |name|
          value = tp.binding.local_variable_get(name)
          puts("  Arg #{name}: #{value.inspect}")
        end
        puts("  => #{tp.return_value}")
      end
    end.enable do
      @order = service.perform(@cart, promotion)
    end
    # …
  end
```

We only need to add 2 lines now:

```ruby
  include TappingDevice::Trackable # include this

  def create
    @cart = Cart.find(order_params[:cart_id])
    promotion = Promotion.find_by(id: order_params[:promotion_id])
    service = OrderCreationService.new

    print_calls(service) # <— and you only need this now
    @order = service.perform(@cart, promotion)
    # …
  end
```

And we can get the same information!

```ruby
:validate_cart # OrderCreationService
    from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:8
    <= {:cart=>#<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
    => nil
:apply_discount # OrderCreationService
    from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:10
    <= {:cart=>#<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">, :promotion=>#<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
    => true
:create_order # OrderCreationService
    from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:11
    <= {:cart=>#<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
    => #<Order id: 1, number: nil, total: 5, customer_id: 1, promotion_id: 1, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">
:perform # OrderCreationService
    from: /Users/st0012/projects/tapping_device-demo/app/controllers/orders_controller.rb:10
    <= {:cart=>#<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">, :promotion=>#<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
    => #<Order id: 1, number: nil, total: 5, customer_id: 1, promotion_id: 1, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">
```

In addition to `print_calls`, [tapping_device](https://github.com/st0012/tapping_device) also provides different level’s of APIs for different kind of information, like `print_traces`

Assume we don’t find anything wrong on the `OrderCreationService`’s method calls. And we suspect it’s something wrong on the `@cart` object. We can use `print_traces`  to see how it interacts with other parts of the program.

```ruby
  include TappingDevice::Trackable

  def create
    @cart = Cart.find(order_params[:cart_id])
    promotion = Promotion.find_by(id: order_params[:promotion_id])
    service = OrderCreationService.new

    print_traces(@cart, exclude_by_paths: [/gems/]) # exclude gems so we don’t see ActiveRecord’s internal method calls
    @order = service.perform(@cart, promotion)
```

```ruby
Passed as 'cart' in 'OrderCreationService#perform' at /Users/st0012/projects/tapping_device-demo/app/controllers/orders_controller.rb:9
Passed as 'cart' in 'OrderCreationService#validate_cart' at /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:8
Called :reserved_until from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:18
Called :errors from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:9
Passed as 'cart' in 'OrderCreationService#apply_discount' at /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:10
Called :apply_discount from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:24
Called :total from: /Users/st0012/projects/tapping_device-demo/app/models/cart.rb:6
Called :update! from: /Users/st0012/projects/tapping_device-demo/app/models/cart.rb:6
Passed as 'cart' in 'OrderCreationService#create_order' at /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:11
Called :total from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:28
Called :customer from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:28
Called :promotion from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:28
```

We can not only see what’s been called on `@cart`, but we can also see what methods took it as its arguments! This can save you some time when debugging. 😉

If you want to know more about how to use [tapping_device](https://github.com/st0012/tapping_device) to optimize your debugging workflow, you can read its  [readme](https://github.com/st0012/tapping_device/blob/master/README.md) to explore different types of useful helpers! You can also see how I used it to address the cause of a Rails issue in [Debug Rails issues effectively with tapping_device](https://dev.to/st0012/debug-rails-issues-effectively-with-tappingdevice-c7c).

## Conclusion

Debugging is mostly about collecting information about how our program works (or used to work). And doing this manually is pretty overwhelming. So as humans, it’s tempting to cheat by guessing how it works in our head and ends up spending more time on the issue.

But with the help of Object-Oriented Tracing, we can take advantage of the paradigm of OOP, and Ruby’s super powerful `TracePoint` to enhance our efficiency on inspecting our programs. I believe this can reduce debugging’s painfulness for junior developers, while allows experienced developers to speed up their debugging process largely.

If you have any opinions on this post or [tapping_device](https://github.com/st0012/tapping_device), please feel free to leave a comment below, I’d love to discuss them with you! Also, if you have a different or better strategy on debugging, please let me know as well ;-)