Logging every method call in debug log by name

Question

Im trying to debug some tests that arent working and I'm having some issues. I'm tailing the test.log as I run my tests and outputting key messages to the log but due to all the interwoven callbacks and hooks Im not sure which method from what model is calling which SQL :)

I wrote a little something to log a method name:

def log_mname
  caller[0]=~/`(.*?)'/  # note the first quote is a backtick
  Rails.logger.debug '=' * 80
  Rails.logger.debug ">> #{Time.now} - #{$1}"
  Rails.logger.debug '=' * 80
end

which works great BUT requires that I add log_mname to every method in my model, which is not realistic. What I want is to add a simple line or block to my rails app that lets me basically say "log all methods as they are called to the debug log."

I tried using ruby's set_trace_func at the top of a model but it didn't work. I also would prefer to not have to add something to each model but add something to either test/debug.rb environment files or the like.

Any thoughts?

Answer 1

The concept you are asking about is known as Reflection; if you are interested in reading more about it.

To answer your question, __method__ inside the method you want to know it's name returns the method name as a symbol

i.e.

$ irb
irb(main):001:0> def qwerty
irb(main):002:1> __method__
irb(main):003:1> end
=> nil
irb(main):004:0> qwerty
=> :qwerty
irb(main):005:0> 

And this works from Ruby 1.8.7

EDIT

The above is to print method names.

To dynamically show method calls, I would use a flavour of ActiveSupport's #constantize mixed with set_trace_func show call traces.

# in your test environment initializer file
require 'active_support/inflector/inflections'
MODELS_TO_WATCH = Dir.entries("#{Rails.root}/app/models/").
                      gsub(".rb", ""). # strip all extensions from filenames
                      capitalize!. # no reason for the bang, just saving space
                    # constantize # make "User" string into User model, for e.g.
# if you constantize, remove `to_s` from `classname` in the proc below
# the version that worked for me was without constantizing but I figure both 
# variations yield the same result

class_eval do |c| # Replace this with a "class DummyClass" for proper sandboxing
  set_trace_func proc { |event, id, classname|
    if event == "call" && MODELS_TO_WATCH.include?(classname.to_s)
      puts "called #{classname}'s #{id}"
    end
  }
end

Note! set_trace_func is a leech function. It would latch unto your Ruby process until the process is killed (many deaths of IRB can testify to this). I didn't find a way to undo set_trace_func yet. And without the conditions introduced, it has a nasty print out; which may look like errors but they aren't.

This is the reason why I suggest this is put in your test initializer; and most probably in a dummy class! This way, when you restart your Rails application in development, production or any other environment you have setup, this hack would not affect it.

It is essential this is in evaluated in the class context. I found if it is evaluated in the instance context, hence instance_eval, it prints every event that occurs in the execution of a Ruby program except the function being called.