Beautiful Logging for Ruby on Rails 3.2

UPDATE: Go here for the Rails 4 version…

In my previous post I showed you a simple way to get beautiful, easy-to-read logs in your Rails application. That trick stopped working in Rails 3.2. So for Rails 3.1 or earlier, refer to my earlier post; but for 3.2 on, read on…

It’s really easy. Just make a new file in your ‘config/initializers’ directory called something like ‘log_formatting.rb’ and paste into it the following code. Restart your app, and voila: pretty logs again!

class ActiveSupport::BufferedLogger
  def formatter=(formatter)
    @log.formatter = formatter
  end
end

class Formatter
  SEVERITY_TO_TAG_MAP     = {'DEBUG'=>'meh', 'INFO'=>'fyi', 'WARN'=>'hmm', 'ERROR'=>'wtf', 'FATAL'=>'omg', 'UNKNOWN'=>'???'}
  SEVERITY_TO_COLOR_MAP   = {'DEBUG'=>'0;37', 'INFO'=>'32', 'WARN'=>'33', 'ERROR'=>'31', 'FATAL'=>'31', 'UNKNOWN'=>'37'}
  USE_HUMOROUS_SEVERITIES = true

  def call(severity, time, progname, msg)
    if USE_HUMOROUS_SEVERITIES
      formatted_severity = sprintf("%-3s","#{SEVERITY_TO_TAG_MAP[severity]}")
    else
      formatted_severity = sprintf("%-5s","#{severity}")
    end

    formatted_time = time.strftime("%Y-%m-%d %H:%M:%S.") << time.usec.to_s[0..2].rjust(3)
    color = SEVERITY_TO_COLOR_MAP[severity]

    "\033[0;37m#{formatted_time}\033[0m [\033[#{color}m#{formatted_severity}\033[0m] #{msg.strip} (pid:#{$$})\n"
  end

end

Rails.logger.formatter = Formatter.new

Credit for figuring out how to get log formatting working with Rails 3.2 goes to JRochkind. If you’d like a complete log formatting solution in the form of a gem, see his FormattedRailsLogger gem at Github.

9 thoughts on “Beautiful Logging for Ruby on Rails 3.2

  1. This is pretty neat-o! Thanks!

    You probably don’t want to hear this, but: My ‘WARN’s don’t seem to be formatting properly on rails 3.2.13. I get an uncolored:

    [YYYY-MM-DD TT:TT:TT] WARN Could not determine content-length of response body. Set content-length of the response or set Response#chunked = true

    I noticed that it looks like there’s an extra space trailing the ‘WARN ‘, and i tried doing a severity.rstrip, which didn’t change things. It really seems like this message is bypassing this formatter class altogether.

    I know you have probably already long forgotten about this script, but any help would be appreciated

    • I haven’t forgotten about it — I use it in my own Rails work! 🙂

      I’m not sure why WARNs aren’t working for you, as I confirmed they’re working here in 3.2.13. From your pasted output above it’s clear that it’s not just the coloring, it’s as if the whole line bypasses the routine. I can tell because your time is bracketed, and the routine doesn’t do that:

      2013-07-10 10:22:29.853 [WARN ] blah blah blah

      Is it only WARNs that do this? Is it *ALL* WARNs, or just the one about content-length?

      • If i use ‘logger.warn()’ in user code, it is correctly formatted. The only other warn I’ve seen is actually properly formatted:

        2013-07-10 TT:TT:TT.TTT [hmm] DEPRECATION WARNING: Passing the format in the template name is deprecated. Please pass render with :formats => [:html] instead. (called from … )

        I’m also seeing incorrect formatting coming from the WEBrick startup lines:
        [2013-07-10 18:48:38] INFO WEBrick 1.3.1
        [2013-07-10 18:48:38] INFO ruby 1.9.3 (2013-02-22) [x86_64-darwin11.4.2]
        [2013-07-10 18:48:38] INFO WEBrick::HTTPServer#start: pid=969 port=3000

        So, my guess is WEBrick is the originator of those warnings…

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s