log_method_calls.rb

require 'rubygems'
require 'active_support'


# >> class Foo
# >>   include LogMethodCalls
# >>   log_methods :bar, :say, :one_plus, :do_something
# >>   
# ?>   def bar; puts "bar"; end
# >>   def say(something); puts something; end
# >>   def one_plus(num); 1+num.to_i; end
# >>   def do_something; yield 1, 2; end
# >> end
# => nil
# >> 
# ?> f = Foo.new
# => #<Foo:0x190a884>
# >> f.bar
# [Sat May 16 18:30:01 2009] bar: entering
# bar
# [Sat May 16 18:30:01 2009] bar: exited (duration: 2.0e-05s)
# => nil
# >> f.say "hi"
# [Sat May 16 18:30:01 2009] say (["hi"]): entering
# hi
# [Sat May 16 18:30:01 2009] say (["hi"]): exited (duration: 1.5e-05s)
# => nil
# >> f.one_plus 1
# [Sat May 16 18:30:01 2009] one_plus ([1]): entering
# [Sat May 16 18:30:01 2009] one_plus ([1]): exited (duration: 4.0e-06s)
# => 2
# >> f.do_something do |a, b|
# ?>   puts "something, #{a}, #{b}"
# >> end
# [Sat May 16 18:30:01 2009] do_something: entering
# something, 1, 2
# [Sat May 16 18:30:01 2009] do_something: exited (duration: 0.000474s)
# => nil


module LogMethodCalls
  def self.included(klass)
    klass.class_eval do
      @@methods_to_log = []
      @@methods_with_logging_added = []

      cattr_reader :method_logger
      @@method_logger = Logger.new(STDOUT)
      
      class << self
        def log_methods(*method_names)
          @@methods_to_log = (@@methods_to_log + method_names).flatten
        end
        
        def set_method_logger(method_logger)
          @@method_logger = method_logger
        end

        def method_added(method_name)
          if (@@methods_to_log - @@methods_with_logging_added).include?(method_name.to_sym)
            add_logging_to_method(method_name.to_sym)
          end
          super
        end

        def add_logging_to_method(method_name)
          class_eval <<-EOD
            def #{method_name}_with_logging(*args, &block)
              __lenm '#{self.to_s}##{method_name}', *args
              start_time = Time.now
              retval = send('#{method_name}_without_logging', *args, &block)
              duration = (Time.now - start_time)
              __lexm '#{self.to_s}##{method_name}', duration, *args
              retval
            end
EOD
          @@methods_with_logging_added << method_name
          alias_method_chain method_name, :logging
        end
      end
    end
  end
  
  # log and flush
  def __lf(msg, method_name = (caller[0] =~ /`([^']*)'/ and $1), *args)
    method_signature = "#{method_name}"
    method_signature << " (#{args.inspect})" if args.any?
    @@method_logger.info "[#{Time.now.strftime('%c')}] #{method_signature}: #{msg}"
    @@method_logger.flush if self.class.method_logger.respond_to?(:flush)
  end
  
  # log entered method
  def __lenm(method_name, *args)
    __lf("entering", method_name, *args)
  end
  
  # log exiting method
  def __lexm(method_name, duration, *args)
    __lf("exited (duration: #{sprintf("%.6f", duration)}s)", method_name, *args)
  end
end