We write about Ruby on Rails, React.js, React Native, remote work, open source, engineering and design.
Ideally we should be logging an exception in Rails like this.
1
2begin
3 raise "Amount must be more than zero"
4rescue => exception
5 Rails.logger.info exception
6end
7
Above code would produce one line log message as shown below.
1
2Amount must be more than zero
3
In order to get backtrace and other information about the exception we need to handle logging like this.
1
2begin
3 raise "Amount must be more than zero"
4rescue => exception
5 Rails.logger.info exception.class.to_s
6 Rails.logger.info exception.to_s
7 Rails.logger.info exception.backtrace.join("\n")
8end
9
Above code would produce following log message.
1
2RuntimeError
3Amount must be more than zero
4/Users/nsingh/code/bigbinary_llc/wheel/app/controllers/home_controller.rb:5:in `index'
5/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'
6/Users/nsingh/.rbenv/versions/2.0.0-p247
7
Now let's look at why Rails logger does not produce detailed logging and what can be done about it.
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.
1
2# Simple formatter which only displays the message.
3class SimpleFormatter < ::Logger::Formatter
4 # This method is invoked when a log event occurs
5 def call(severity, timestamp, progname, msg)
6 "#{String === msg ? msg : msg.inspect}\n"
7 end
8end
9
As we can see it inherits from Logger::Formatter
defined by Ruby Logger .
It then overrides call
method which is originally defined as
1
2#Format = "%s, [%s#%d] %5s -- %s: %s\n"
3def call(severity, time, progname, msg)
4 Format % [severity[0..0], format_datetime(time), $$, severity, progname,
5 msg2str(msg)]
6end
7
8......
9......
10
11def msg2str(msg)
12 case msg
13 when ::String
14 msg
15 when ::Exception
16 "#{ msg.message } (#{ msg.class })\n" <<
17 (msg.backtrace || []).join("\n")
18 else
19 msg.inspect
20 end
21end
22
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.
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 ofActiveSupport::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.
1
2begin
3 raise "Amount must be more than zero"
4rescue => exception
5 Rails.logger.info exception
6end
7
Now above code produces following log message.
1
2I, [2013-12-17T01:05:41.944859 #13537] INFO -- : Amount must be more than zero (RuntimeError)
3test_app/app/controllers/page_controller.rb:3:in `index'
4/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'
5/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'
6/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'
7...<snip>...
8
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.