How to Log Every Method That's Called in a Ruby Program

How do I log every method that's called in a Ruby program?

This is definitely possible -- in fact, there's even a method for it! Just add this somewhere in your code before the point that you want to start logging things:

set_trace_func proc { |event, file, line, id, binding, classname|
  printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
}

The secret sauce you want comes from Kernel#set_trace_func, as noted above:

• set_trace_func(proc) => proc
• set_trace_func(nil) => nil

Establishes proc as the handler for tracing, or disables tracing if the parameter is nil. proc takes up to six parameters: an event name, a filename, a line number, an object id, a binding, and the name of a class. proc is invoked whenever an event occurs. Events are: c-call (call a C-language routine), c-return (return from a C-language routine), call (call a Ruby method), class (start a class or module definition), end (finish a class or module definition), line (execute code on a new line), raise (raise an exception), and return (return from a Ruby method). Tracing is disabled within the context of proc.

Here's a handy example:

class Test
  def test
    a = 1
    b = 2
  end
end

set_trace_func proc { |event, file, line, id, binding, classname|
  printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
}

t = Test.new
t.test

(Note: don't try this in irb unless you want a huge scrolling screen of text.) The resulting output is:

    line test.rb:11               false
  c-call test.rb:11        new    Class
  c-call test.rb:11 initialize   Object
c-return test.rb:11 initialize   Object
c-return test.rb:11        new    Class
    line test.rb:12               false
    call test.rb:2        test     Test
    line test.rb:3        test     Test
    line test.rb:4        test     Test
  return test.rb:4        test     Test

You can play around with the formatting string above to get just the results you want to log (for example, it sounds like you're only interested in call events). Hope that helps, and good luck with sorting through all those unit tests!

Logging all method calls in a Rails app

It's easy to do. Just add 5 lines of code into your script/server:

#!/usr/bin/env ruby
set_trace_func proc {
  |event, file, line, id, binding, classname| 
  if event == "call" or event == "return" 
    printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
  end
}

require File.expand_path('../../config/boot',  __FILE__)
require 'commands/server'

It's described at http://phrogz.net/ProgrammingRuby/ospace.html#tracingyourprogramsexecution

Your application will become quite slow and you might get more output than you want. You can easily add more conditions on file/class/function names to avoid printing unwanted stuff.

Ruby module to print all method calls and returns in class

You can achieve that by defining a new wrapper method for each public instance method of the class that performs the log logic that you need.

module Loginator
  def logify_me
    self.public_instance_methods.each do |method|
      proxy = Module.new do
        define_method(method) do |*args|
          puts "Method #{method}(#{args.join(', ')}) called"
          # added join to match the exact desired output

          value = super *args

          puts "returns #{value}"

          value
        end
      end
      self.prepend proxy
    end
  end
end

class A
  extend Loginator

  def add(a, b)
    a + b
  end

  def sub(a, b)
    a - b
  end

  logify_me
end

Which yields the following output:

>> A.new.sub(1,2)
Method 'sub' called with args '[1, 2]'
returns -1
=> -1

>> A.new.add(4,7)
Method 'add' called with args '[4, 7]'
returns 11
=> 11

Explanation for the future :)

• define_method(method) :

  Defines an instance method in the receiver. The method parameter can be a Proc, a Method, or an UnboundMethod object. If a block is specified, it is used as the method body. This block is evaluated using instance_eval ref. can be found here

• prepend

  prepend will insert the module at the bottom of the chain, even before the class itself.fourth ref on my post

Section to Edit by @pedrosfdcarneiro

please, add some brief explanation about the second inner module proxy = Module.new do end and why it's important for the return value and the usage of the super.

plus why did you preferred to use the public_instance_methods over instance_methods.

please kindly add some explanation about it because first its a bit unclear to me and secondly for the other noobs out there.
thanks in advance :)

This answer was heavily based on this fantastic answer: https://stackoverflow.com/a/23898539/1781212.

Capturing logger output inside a method

I've done this in several different ways, and the most convenient I've found is to build a delegation object that routes messages to two or more loggers:

require 'stringio'
require 'logger'

class LoggerTee

  def initialize *loggers
    @loggers = loggers
  end

  def method_missing meth, *args, &block
    @loggers.each { |logger| logger.send(meth, *args, &block) }
  end

end

capture_stringio = StringIO.new
console_log = Logger.new(STDOUT)
string_log = Logger.new(capture_stringio)
log = LoggerTee.new(console_log, string_log)

log.debug 'Hello world'
puts capture_stringio.string

Output:

D, [2013-04-30T18:59:18.026285 #14533] DEBUG -- : Hello world
D, [2013-04-30T18:59:18.026344 #14533] DEBUG -- : Hello world

In this example, the LoggerTee class is instantiated with two separate loggers, one that goes to the console, the other to a StringIO instance. The resulting LoggerTee instance is a drop-in replacement for any standard logger object.

Executing code for every method call in a Ruby module

Like this:

module M
  def self.before(*names)
    names.each do |name|
      m = instance_method(name)
      define_method(name) do |*args, &block|  
        yield
        m.bind(self).(*args, &block)
      end
    end
  end
end

module M
  def hello
    puts "yo"
  end

  def bye
    puts "bum"
  end

  before(*instance_methods) { puts "start" }
end

class C
  include M
end

C.new.bye #=> "start" "bum"
C.new.hello #=> "start" "yo"

Ruby - share logger instance among module/classes

With the design you've laid out, it looks like the easiest solution is to give Crawler a module method that returns a module ivar.

module Crawler
  def self.logger
    @logger
  end
  def self.logger=(logger)
    @logger = logger
  end
end

Or you could use "class <<self magic" if you wanted:

module Crawler
  class <<self
    attr_accessor :logger
  end
end

It does the exact same thing.

How should I log in ruby with minimum assumptions about the calling code

There is a pretty common pattern in various ruby logger implementations to mimic the method interface of the standards library Logger, namely

• the logger object responds to the methods debug, info, warn, error, fatal where you can pass a string containing the log message. Many logger implementations also allow to pass a block (which returns the log message) rather than an actual string
• You also generally have an add method where you can pass a numeric log severity and the log message.

In your code, you can generally expect that all logger implementations implement at least this interface. You can then allow users of your code to provide their own logger object (which should implement those methods) which you can then use. This pattern is called dependency injection

Generally, in Ruby, you don't care about actual types of a given object. You just assume that is responds to messages send to it ("methods called"). As such, you don't need to care about a specific logger implementation, but just that it implements the expected interface. In Ruby, this is often called duck typing.

---

Related Topics