Improving the Rails Logger

Posted by Guy Naor Fri, 22 Sep 2006 20:02:00 GMT

The rails logger is VERY useful. It amazes me that I don't really feel I need a debugger in rails (after using one for years in Visual C++) and a lot of it is the console and the logger.

One thing missing from the logger, is the process id of the rails instance that is logging. This is important when you have more than one instance of your app serving requests through fcgi or mongrel or whatever. It's needed in order to enable us to see how the request was handled, as we can extract only logs that pertain to this specific request, even when it's mixed with other requests.

Using the fact that all classes in Ruby are open, we modify the logger to do what we need. Either create a file in your lib directory, or anywhere else you prefer, and in your config/environment.rb add the line:

require 'pid_logger'

The file should include the following (most of it extracted from the default rails logger):

class Logger
  private
    # Ruby 1.8.3 transposed the msg and progname arguments to format_message.
    # We can't test RUBY_VERSION because some distributions don't keep Ruby
    # and its standard library in sync, leading to installations of Ruby 1.8.2
    # with Logger from 1.8.3 and vice versa.
    if method_defined?(:formatter=)
      log_str = ""
      def format_message(severity, timestamp, progname, msg)
        log_str = "[#{$$}][#{severity[0...1]}] msg\n" # This is the only real change... Added a pid
      end
    else
      def format_message(severity, timestamp, msg, progname)
        log_str = "[#{$$}][#{severity[0...1]}] msg\n" # This is the only real change... Added a pid
      end
    end
  end

One more possible change that I use in some applications, is to color the background of debug messages I sent to the logger. The change here is also very slight. Here is the same file, but with the added coloring of the output with a green or red background depending on severity, when a line start with 4 or more > + - = characters (e.g: ">>>>>>>> This is a test" will have the >>>>>>>> part with a red backround if error, and green otherwize). It makes finding the log messages very eash.

class Logger
  private
    # Ruby 1.8.3 transposed the msg and progname arguments to format_message.
    # We can't test RUBY_VERSION because some distributions don't keep Ruby
    # and its standard library in sync, leading to installations of Ruby 1.8.2
    # with Logger from 1.8.3 and vice versa.
    if method_defined?(:formatter=)
      log_str = ""
      def format_message(severity, timestamp, progname, msg)
        log_str = "[#{$$}][#{severity[0...1]}] #{color_special_msg(msg, severity)}\n" # This is the only real change... Added a pid
      end
    else
      def format_message(severity, timestamp, msg, progname)
        log_str = "[#{$$}][#{severity[0...1]}] #{color_special_msg(msg, severity)}\n" # This is the only real change... Added a pid
      end
    end

    def color_special_msg msg, severity  
      # A small trick to get highlighting of the messages if they are our logged messages
      # that start with a long sequence of >>> or *****
      sub_color = severity[0...1] == 'E' ? '41' : '42' # Red for errors, green otherwize
      msg.sub(/^((\*|>|\+|-|=){4,})/, "\033[1;#{sub_color}m\\1\033[0m")     
    end

end