Contextual Logging with Log4r

Question

Here's how some of my existing logging code with Log4r is working. As you can see in the WorkerX::a_method, any time that I log a message I want the class name and the calling method to be included (I don't want all the caller history or any other noise, which was my purpose behind LgrHelper).

class WorkerX

  include LgrHelper

  def initialize(args = {})
    @logger = Lgr.new({:debug => args[:debug], :logger_type => 'WorkerX'})
  end

  def a_method
    error_msg("some error went down here")
    # This prints out: "WorkerX::a_method - some error went down here"
  end

end


class Lgr
  require 'log4r'
  include Log4r

  def initialize(args = {}) # args: debug boolean, logger type
    @debug = args[:debug] 
    @logger_type = args[:logger_type]

    @logger = Log4r::Logger.new(@logger_type)
    format = Log4r::PatternFormatter.new(:pattern => "%l:\t%d - %m")
    outputter = Log4r::StdoutOutputter.new('console', :formatter => format)
    @logger.outputters = outputter

    if @debug then
      @logger.level = DEBUG
    else
      @logger.level = INFO
    end
  end

  def debug(msg)
    @logger.debug(msg)
  end

  def info(msg)
    @logger.info(msg)
  end

  def warn(msg)
    @logger.warn(msg)
  end

  def error(msg)
    @logger.error(msg)
  end

  def level
    @logger.level
  end

end


module LgrHelper

  # This module should only be included in a class that has a @logger instance variable, obviously.

  protected

  def info_msg(msg)
    @logger.info(log_intro_msg(self.method_caller_name) + msg)
  end

  def debug_msg(msg)
    @logger.debug(log_intro_msg(self.method_caller_name) + msg)
  end

  def warn_msg(msg)
    @logger.warn(log_intro_msg(self.method_caller_name) + msg)
  end

  def error_msg(msg)
    @logger.error(log_intro_msg(self.method_caller_name) + msg)
  end

  def log_intro_msg(method)
    msg = class_name
    msg += '::'
    msg += method
    msg += ' - '

    msg
  end

  def class_name
    self.class.name
  end

  def method_caller_name
    if  /`(.*)'/.match(caller[1]) then # caller.first
      $1
    else
      nil
    end
  end

end

I really don't like this approach. I'd rather just use the existing @logger instance variable to print the message and be smart enough to know the context. How can this, or similar simpler approach, be done?

My environment is Rails 2.3.11 (for now!).

Answer 1

After posting my answer using extend, (see "EDIT", below), I thought I'd try using set_trace_func to keep a sort of stack trace like in the discussion I posted to. Here is my final solution; the set_trace_proc call would be put in an initializer or similar.

#!/usr/bin/env ruby

# Keep track of the classes that invoke each "call" event
# and the method they called as an array of arrays.
# The array is in the format: [calling_class, called_method]
set_trace_func proc { |event, file, line, id, bind, klass|
  if event == "call"
    Thread.current[:callstack] ||= []
    Thread.current[:callstack].push [klass, id]
  elsif event == "return"
    Thread.current[:callstack].pop
  end
}

class Lgr
  require 'log4r'
  include Log4r

  def initialize(args = {}) # args: debug boolean, logger type
    @debug = args[:debug]
    @logger_type = args[:logger_type]

    @logger = Log4r::Logger.new(@logger_type)
    format = Log4r::PatternFormatter.new(:pattern => "%l:\t%d - %m")
    outputter = Log4r::StdoutOutputter.new('console', :formatter => format)
    @logger.outputters = outputter

    if @debug then
      @logger.level = DEBUG
    else
      @logger.level = INFO
    end
  end

  def debug(msg)
    @logger.debug(msg)
  end

  def info(msg)
    @logger.info(msg)
  end

  def warn(msg)
    @logger.warn(msg)
  end

  def error(msg)
    @logger.error(msg)
  end

  def level
    @logger.level
  end

  def invoker
    Thread.current[:callstack] ||= []
    ( Thread.current[:callstack][-2] || ['Kernel', 'main'] )
  end
end

class CallingMethodLogger < Lgr
  [:info, :debug, :warn, :error].each do |meth|
    define_method(meth) { |msg| super("#{invoker[0]}::#{invoker[1]} - #{msg}") }
  end
end

class WorkerX
  def initialize(args = {})
    @logger = CallingMethodLogger.new({:debug => args[:debug], :logger_type => 'WorkerX'})
  end

  def a_method
    @logger.error("some error went down here")
    # This prints out: "WorkerX::a_method - some error went down here"
  end
end

w = WorkerX.new
w.a_method

I don't know how much, if any, the calls to the proc will affect the performance of an application; if it ends up being a concern, perhaps something not as intelligent about the calling class (like my old answer, below) will work better.

[EDIT: What follows is my old answer, referenced above.]

How about using extend? Here's a quick-and-dirty script I put together from your code to test it out; I had to reorder things to avoid errors, but the code is the same with the exception of LgrHelper (which I renamed CallingMethodLogger) and the second line of WorkerX's initializer:

#!/usr/bin/env ruby

module CallingMethodLogger
  def info(msg)
    super("#{@logger_type}::#{method_caller_name} - " + msg)
  end

  def debug(msg)
    super("#{@logger_type}::#{method_caller_name} - " + msg)
  end

  def warn(msg)
    super("#{@logger_type}::#{method_caller_name} - " + msg)
  end

  def error(msg)
    super("#{@logger_type}::#{method_caller_name} - " + msg)
  end

  def method_caller_name
    if  /`(.*)'/.match(caller[1]) then # caller.first
      $1
    else
      nil
    end
  end
end

class Lgr
  require 'log4r'
  include Log4r

  def initialize(args = {}) # args: debug boolean, logger type
    @debug = args[:debug]
    @logger_type = args[:logger_type]

    @logger = Log4r::Logger.new(@logger_type)
    format = Log4r::PatternFormatter.new(:pattern => "%l:\t%d - %m")
    outputter = Log4r::StdoutOutputter.new('console', :formatter => format)
    @logger.outputters = outputter

    if @debug then
      @logger.level = DEBUG
    else
      @logger.level = INFO
    end
  end

  def debug(msg)
    @logger.debug(msg)
  end

  def info(msg)
    @logger.info(msg)
  end

  def warn(msg)
    @logger.warn(msg)
  end

  def error(msg)
    @logger.error(msg)
  end

  def level
    @logger.level
  end
end

class WorkerX
  def initialize(args = {})
    @logger = Lgr.new({:debug => args[:debug], :logger_type => 'WorkerX'})
    @logger.extend CallingMethodLogger
  end

  def a_method
    @logger.error("some error went down here")
    # This prints out: "WorkerX::a_method - some error went down here"
  end
end

w = WorkerX.new
w.a_method

The output is:

ERROR:  2011-07-24 20:01:40 - WorkerX::a_method - some error went down here

The downside is, via this method, the caller's class name isn't automatically figured out; it's explicit based on the @logger_type passed into the Lgr instance. However, you may be able to use another method to get the actual name of the class--perhaps something like the call_stack gem or using Kernel#set_trace_func--see this thread.