Log around a function call

Question

I've got a module I use to log around functions that performs external requests.

# Functions to track when a block begins and ends
module LogAround
 # log at begin and end of a given block
 # with a mesage and the given params
 def log_around(message, *args)
 start_time = Time.now
 Rails.logger.info "#{message}(#{args.inspect}) - start"
 result = yield
 ensure
 end_time = Time.now - start_time
 Rails.logger.info "#{message}(#{args.inspect}) - end (#{end_time}s)"
 result
 end
end

This module is used in this way:

class Wrapper
 include LogAround
 # TODO: log_around :get_artist
 alias_method :_orig_get_artist, :get_artist
 # log the external request
 def get_artist(*args)
 log_around 'Discogs::Wrapper.get_artist', *args do
 _orig_get_artist *args
 end
 end
end

This solution is much closer to what I want compared with what I had before, but ideally what I'm looking for is a function in LogAround that could be used in this way

# this class is already defined by Discogs
# and this is a customization
class Wrapper
 include LogAround
 log_around :get_artist
end

and provides the same (or better params list) output, which is:

Discogs::Wrapper.get_artist(["pink floyd"]) - start
Discogs::Wrapper.get_artist(["pink floyd"]) - end (1.919805308s)

Answer 1

If you are using Rails (and it seems so, because you used Rails.logger) you can use the alias_method_chain function.

# Functions to track when a block begins and ends
module LogAround
 extend ActiveSupport::Concern
 # Log before and after its block
 # with a message and the given params
 def log_around(message, *args)
 start_time = Time.now
 Rails.logger.info "#{message}(#{args.inspect}) - start"
 result = yield
 ensure
 end_time = Time.now - start_time
 Rails.logger.info "#{message}(#{args.inspect}) - end (#{end_time}s)"
 result
 end
 module ClassMethods
 def log_around(*methods)
 names = methods.flatten.map(&:to_sym)
 names.each do |name|
 class_eval <<-RUBY
 def #{name}_with_logging(*args, &block)
 log_around(self.class.name + '##{name}') do
 #{name}_without_logging(*args, &block)
 end
 end
 RUBY
 alias_method_chain name, :logging
 end
 end
 end
end

Here's an example usage:

class Foo
 include LogAround
 def bar
 puts "hello"
 end
 log_around :bar
end

It's important to note that log_around may only be called after its argument method (here, bar) has been defined.

It also supports multiple methods.

log_around :foo, :bar, :baz

• Ian Vaughan: Is there a way of mixing it into all project classes without having to manually add the include to each file?

Answer 2

You may not define a free message, but I think this may be a solution:

module LogAround
 # log at begin and end of a given block
 # with a mesage and the given params
 def log_around( method_to_log )
 alias_method "_orig_#{method_to_log}".to_sym, method_to_log
 define_method(method_to_log ){ | *args, &blck | 
 start_time = Time.now
 puts "call #{method_to_log} with args #{args.inspect} #{'and a block' if blck} "
 result = send "_orig_#{method_to_log}".to_sym, *args, &blck
 end_time = Time.now - start_time
 puts "called #{method_to_log} with args #{args.inspect} - (#{end_time}s)"
 result
 }
 end #self.log_around( method_to_log )
end
class Wrapper
 def test
 puts 'in test'
 sleep 1.2
 end
 def test_with_block
 puts 'in test_with_block'
 yield
 end
 extend LogAround
 log_around :test
 log_around :test_with_block
end
Wrapper.new.test
Wrapper.new.test_with_block { puts 'inside block' }

Remarks:

• Rails.logger.info is replaced by puts
• I extended, not included LogAround (log_around should be a class method, not an instance method).
• not well tested ;)

• ecoologic: thanks, that's a good solution, and yes, I agree LogAround had to be extended and not included
• Simone Carletti: Nothing prevents you to include LogAround in this particular case.