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

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 ;)