---
title: "Configuring Log Formatting in Rails"
description:
  "This blog discusses how custom Logger can be used in Rails, and configuring
  Log Formatting."
canonical_url: "https://www.bigbinary.com/blog/logger-formatting-in-rails"
markdown_url: "https://www.bigbinary.com/blog/logger-formatting-in-rails.md"
---

# Configuring Log Formatting in Rails

This blog discusses how custom Logger can be used in Rails, and configuring Log
Formatting.

- Author: Vipul
- Published: March 3, 2014
- Categories: Rails

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

```ruby

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.

```plaintext

Amount must be more than zero

```

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

```ruby

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.

```plaintext

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.

```ruby

# 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](http://www.ruby-doc.org/stdlib-2.1.0/libdoc/logger/rdoc/Logger.html)
. It then overrides `call` method which is originally defined as

```ruby

#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](http://guides.rubyonrails.org/configuring.html)
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.

```ruby

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

```

Now above code produces following log message.

```plaintext

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](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.

## Links

- [Human page](https://www.bigbinary.com/blog/logger-formatting-in-rails)