ruby-on-railsrubyloggingrefactoringlog4r

Contextual Logging with Log4r


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!).


Solution

  • 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.