Here is a short snippet of code that has become one of my favourite debugging tools recently. It’s not efficient, definitely not elegant, but man is it useful.

       location = caller.first
       location = location[0...location.rindex(":")]
       line_number = location[(location.rindex(":")+1)..-1]
       file = location[0...location.rindex(":")]
       puts location
       puts File.open(file).readlines[line_number.to_i - 1]
       puts "#{values}"
       puts "--"*20

But let’s back up a moment, how did I get to this stage?

Background

As part of consultancy work we often inherit applications developed by other Rails shops of varying quality. Previous developers of the code we receive have often used, well, let’s just say “creative” approaches.

In most rails apps a line like this is pretty clear:

widget.cost_of_production

Simple. Widget is an ActiveRecord model, cost_of_production is either a DB field or a method defined in Widget. Easy right? Except when widget is not an ActiveRecord class.

Off the rails

In this particular case, the previous developer(s) used immutable structs (via the Hamsterdam gem) internally. Not only so, but each ActiveRecord model would be transformed into three of these structs – raw, calculated, and combined. With combined being a wrapper that zipped data and calculated into one struct.

Basically, imagine re-implementing ActiveRecord but without any of the “magic” that makes it nice to use…

Crawling through the code was difficult to say the least. “Jump to definition” fails because the “method” you’re looking for is not a method, it is a member of a struct. Even a simple grep is misleading because the structs are combined using .merge on the hashes, so the individual “fields” may not be named in the file. Not to mention that the structs and the DB may be using different names for the same field…

Debugging Ruby

Aaron Patterson (of core Ruby and core Rails fame) has an awesome blog post titled I am a puts debuggerer which should be required reading for any Rubyist, where he outlines some of the things we can do in Ruby when debugging. Perhaps the most memorable sentence is this one:

This is debugging code, so you can do whatever you want.

Debugging code is inherently throw-away code. It can be messy, inefficient, and downright ugly, as long as it’s useful.

A simple example

I’ll use OpenStruct here as a simple example of using the snippet at the top of this post, but you can drop it into any class.

Let’s start with a basic script:

require 'ostruct'

struct = OpenStruct.new(
  value: 'complicated calc result'
)

puts "#{struct}"

Easy stuff. Run the code and we get: #<OpenStruct value="complicated calc result">

Now imagine you don’t know where that value came from, and jumping through the code isn’t making things any clearer.

Luckily, Ruby allows us to re-open a class and inject new code (aka “monkey patching”). This makes for a great debugging tool in the tool belt.

Using our own OpenStruct constructor and snippet, we get this script:

require 'ostruct'

class OpenStruct
  def initialize(hash=nil)
    @table = {}
    if hash
      hash.each_pair do |k, v|
        k = k.to_sym
        @table[k] = v
      end
      location = caller.first
      location = location[0...location.rindex(":")]
      line_number = location[(location.rindex(":")+1)..-1]
      file = location[0...location.rindex(":")]
      puts location
      puts File.open(file).readlines[line_number.to_i - 1]
      puts "#{hash}"
      puts "--"*20
    end
  end
end

struct = OpenStruct.new(
  value: 'complicated calc result'
)

puts "#{struct}"

The basic initialise method code here is taken straight from the OpenStruct source code, with our snippet added to the bottom of the if hash block.

Trouble managing your Github Pull Requests?

GitArborist was created to simplify Pull Request management on Github
Mark PR dependencies, automatic merging, scheduled merges, and more →

So what’s happening here?

caller gives us a stack trace up to that line. For my purposes, I only care about the first entry (i.e. the point where OpenStruct.new was called).

Next, we do some quick-and-dirty parsing of that line to grab the filename and line number (the trace will be in a format like: ./<filename>:<linenum>: in ‘<method>’)

Lastly, we print out: the file location, the line in that file that called the method I’m in, any values we want to see, and then a lot of hyphens (hyphens purely as a divider in the log as there might be a lot of these printed out).

Running the above gives:

./sharp_knives.rb:25
struct = OpenStruct.new(
{:value=>"complicated calc result"}
----------------------------------------
#<OpenStruct value="complicated calc result">

Location of call, actual line that does the call, and the values passed in.

Now tracing back the value allocations can be done by looking at the logs. I wouldn’t say this made the process “easy” by any means, but it was certainly an improvement over trying to trace through the convoluted logic with my brain.

Cool story bro

You might be saying to yourself “Yeah well that was cool and all for that one weird scenario, but in a normal rails app we don’t need that kind of stuff right?”

Maybe.

Since “crafting” that snippet (and yes, I’m being extremely generous with the term craft here) I’ve already used it on another project.

This time the scenario was a Rails upgrade. The code was much more conventional and, most importantly, used the money) gem.

Around version 6.7 money included a breaking change so that == would raise when comparing against other non-Money objects. i.e. Money.new(1) == 1 would now raise an exception, unless you are comparing against zero – Money.new(1) == 0 will not raise an exception.

This was pretty tricky to clear up, in part because you can’t just search your codebase for Money objects (unless you know every single Money object’s name I suppose). And in some cases the call may not be for == but rather eq (as in a spec). In one particularly troublesome case, I was actually hitting this exception inside ActiveRecord’s validations when creating a new test object (using FactoryBot), so the call stack was full of ActiveSupport and FactoryBot entries, making it difficult to pinpoint where the error was occurring in the app code. To help out, I just monkey-patched the above snippet into the Money::Arithmetic#== to have a look at what was causing the exception.

Poking around I eventually discovered that ActiveRecord’s numericality validation essentially calls old_value != new_value (not an exact copy, just to give the idea) and this was causing my problem. Some more investigation and I found there was a custom validation inside the model that updates one of the fields. The problem? It was updating the raw value_cents field (i.e. not the Money-ified value version) with a Money object. This Numeric <-> Money mismatch was the root cause of my problem, and the solution was as simple as changing value_cents = <Money obj> to value = <Money obj>.

Summary

Ruby has some very powerful tools baked in (source_location is another notable mention worth knowing about) and combined with the ability to monkey-patch these into existing classes, it gives us some very useful debugging techniques that few languages can compete with.

Just remember, anything goes with debugging code. It can have terrible performance, it can be riddled with dodgy monkey-patching, it can be full of duplication. After all, there’s no point polishing it – once the bug is fixed you’ll be throwing it away.