Photo credit

This is just a quick tip that you may never need but came in very handy for me this week.

While perusing the log of one of my Rails apps, I noticed that a certain method of one of my models was being called four times when I expected it to only be called once. I did the usual Find in Files to see where I'm calling it, but that didn't really answer the question. A mental walkthough of my code didn't reveal why this method was getting called more than once.

I'm actually at home while I write this, and I can't remember the exact code, but it went something like this:

def something_important
  RAILS_DEFAULT_LOGGER.info "About to do something important"
  if something_exists?
    do_expensive_operation
  end
end

I found a test which was already exercising code which called this method, and sure enough, when I ran that one test, I got multiple log statements emitted into the test log file.

During testing, I tend to use puts statements when I want to see some debug output (although tailing the log file would work too). So I did this:

def something_important
  puts caller.grep(/\/app\//).first
  RAILS_DEFAULT_LOGGER.info "About to do something important"
  if something_exists?
    do_expensive_operation
  end
end

And presto, when I ran the test, it displayed for me the exact line that was calling this method each time. That revealed the source of the problem, which was easily fixed. In this case, seeing the actual call stack was really helpful.

caller is not Rails magic; it's a Ruby method of the Kernel class, which all objects inherit. It returns an array of strings representing the call stack. Now, in a Rails application, the call stack can be really long. In my case, the 15 or so methods at the top of the stack were coming from the Rails framework itself, so that was a lot of noise to weed through.

By doing a grep on the array and choosing the first match, I filtered out everything up until the first entry in the call stack that was coming from a file in the app folder or below. In other words, this revealed the most recent line in my code that triggered this method.