Configuring Log Formatting in Rails

Ideally we should be logging an exception in Rails like this.

begin
  raise "Amount must be more than zero"
rescue => exception
  Rails.logger.info exception
end

Above code would produce one line log message as shown below.

Amount must be more than zero

In order to get backtrace and other information about the exception we need to handle logging like this.

begin
  raise "Amount must be more than zero"
rescue => exception
  Rails.logger.info exception.class.to_s
  Rails.logger.info exception.to_s
  Rails.logger.info exception.backtrace.join("\n")
end

Above code would produce following log message.

RuntimeError
Amount must be more than zero
/Users/nsingh/code/bigbinary_llc/wheel/app/controllers/home_controller.rb:5:in `index'
/Users/nsingh/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/actionpack-4.0.2/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/Users/nsingh/.rbenv/versions/2.0.0-p247

Now let's look at why Rails logger does not produce detailed logging and what can be done about it.

A closer look at Formatters

When we use Rails.logger.info(exception) then the output is formatted by ActiveSupport::Logger::SimpleFormatter. It is a custom formatter defined by Rails that looks like this.

# Simple formatter which only displays the message.
class SimpleFormatter < ::Logger::Formatter
  # This method is invoked when a log event occurs
  def call(severity, timestamp, progname, msg)
    "#{String === msg ? msg : msg.inspect}\n"
  end
end

As we can see it inherits from Logger::Formatter defined by Ruby Logger . It then overrides call method which is originally defined as

#Format = "%s, [%s#%d] %5s -- %s: %s\n"
def call(severity, time, progname, msg)
  Format % [severity[0..0], format_datetime(time), $$, severity, progname,
    msg2str(msg)]
end

......
......

def msg2str(msg)
  case msg
  when ::String
    msg
  when ::Exception
    "#{ msg.message } (#{ msg.class })\n" <<
      (msg.backtrace || []).join("\n")
  else
    msg.inspect
  end
end

When exception object is passed to SimpleFormatter then msg.inspect is called and that's why we see the exception message without any backtrace.

The problem is that Rails's SimpleFormatter's call method is a bit dumb compared to Ruby logger's call method.

Ruby logger's method has a special check for exception messages. If the message it is going to print is of class Exception then it prints backtrace also.In comparison SimpleFormatter just prints msg.inspect for objects of Exception class.

Configuring logger

This problem can be solved by using config.logger.

From Rails Configuring Guides we have

config.logger accepts a logger conforming to the interface of Log4r or the default Ruby Logger class. Defaults to an instance of ActiveSupport::Logger, with auto flushing off in production mode.

So now we can configure Rails logger to not to be SimpleFomatter and go back to ruby's logger.

Let's set config.logger = ::Logger.new(STDOUT) in config/application.rb and then try following code.

begin
  raise "Amount must be more than zero"
rescue => exception
  Rails.logger.info exception
end

Now above code produces following log message.

I, [2013-12-17T01:05:41.944859 #13537]  INFO -- : Amount must be more than zero (RuntimeError)
test_app/app/controllers/page_controller.rb:3:in `index'
/Users/sward/.rbenv/versions/2.0.0-p353/lib/ruby/gems/2.0.0/gems/actionpack-4.0.2/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/Users/sward/.rbenv/versions/2.0.0-p353/lib/ruby/gems/2.0.0/gems/actionpack-4.0.2/lib/abstract_controller/base.rb:189:in `process_action'
/Users/sward/.rbenv/versions/2.0.0-p353/lib/ruby/gems/2.0.0/gems/actionpack-4.0.2/lib/action_controller/metal/rendering.rb:10:in `process_action'
...<snip>...

Sending log to STDOUT is also a good practice

As per http://12factor.net/logs, an application should not concern itself much with the kind of logging framework being used. The application should write log to STDOUT and logging frameworks should operate on log streams.