Strategies for Rails Logging and Error Handling
TLDR: Clean logging and error handling is a critical aspect of a RoR app. What's a good strategy? Why does this matter?
A Rails app can have awesome unit and functional tests, and then in production, something goes wrong and the right error handling does not happen, making a bad situation worse. By this, I mean, it's bad enough that something went wrong in production. It's even worse if:
- You don't have clear log messages that identify exactly what went wrong.
- You didn't get automatically notified via email that something went wrong. Instead, the customer told the customer service rep that there's an issue. Ideally, when an error happens, the responsible developers should be notified.
Here's some tips on logging setup and error handling, including a utility method to log the stack trace and send an email.
The next article, Testing Error Handling, will show you how to verify that your error handling strategy is properly implemented, includind with rspec tests.
Log Setup
Notification of any Exceptions via Email with Gem exception_notification
Check out the gem exception_notification. It works great. One things the docs don't point out is that it works great with MailCatcher. This allows you to "test" that your exception notification emails are being sent as expected without using a real mail account. Thus, do enable exception logging in development mode, contrary to the basic setup. Here's a config example at this post on MailCatcher and mail_view.
Log the Browser Details with Gem 'browser_details'
The gem browser_details will tell you what type of browser was used, which can be very important when errors occur. I cracked up when I read this from the gem info page:
Have you ever had the conversation:
Your site doesn't work. What browser are you using and do you have Javascript enabled?
What's a browser?
Control Rails Log Verbosity with Gem lograge
Sometimes too much of a good thing (log info) is a bad thing, and that's true with Rails default logging. Check out the gem 'lograge'. The big difference is that a single request will take a single line. To quote the README, instead of logs like this:
Started GET "/" for 127.0.0.1 at 2012-03-10 14:28:14 +0100
Processing by HomeController#index as HTML
Rendered text template within layouts/application (0.0ms)
Rendered layouts/_assets.html.erb (2.0ms)
Rendered layouts/_top.html.erb (2.6ms)
Rendered layouts/_about.html.erb (0.3ms)
Rendered layouts/_google_analytics.html.erb (0.4ms)
Completed 200 OK in 79ms (Views: 78.8ms | ActiveRecord: 0.0ms)
After installing lograge, you'll have one line for the request:
method=GET path=/jobs/833552.json format=json controller=jobs action=show status=200 duration=58.33 view=40.43 db=15.26
The one issue with lograge
is that the default configuration does not
log request parameters, which can be useful for debugging. This blog
post, How to add request parameters to lograge
logs,
addresses that shortcoming.
Utility Method to Log Exceptions
This sample method Utility.log_exception
takes care of logging an
exception along with sending out an email notification.
Example of calling Utility.log_exception
:
def my_method_with_error foobar
do_something_that_raises foobar
rescue => e # catches StandardError (don't use rescue Esception => e)
Utility.log_exception e, info: "called do_something_that_raises wihh #{foobar}"
end
Definition of Utility.log_exception
:
class Utility
# Logs and emails exception
# Optional args:
# request: request Used for the ExceptionNotifier
# info: "A descriptive messsage"
def self.log_exception e, args
extra_info = args[:info]
Rails.logger.error extra_info if extra_info
Rails.logger.error e.message
st = e.backtrace.join("\n")
Rails.logger.error st
extra_info ||= "<NO DETAILS>"
request = args[:request]
env = request ? request.env : nil
if env
ExceptionNotifier::Notifier.exception_notification(env, e, :data => {:message => "Exception: #{extra_info}"}).deliver
else
ExceptionNotifier::Notifier.background_exception_notification(e, :data => {:message => "Exception: #{extra_info}"}).deliver
end
end
end
Strategy: Error Handling and Logging
- Avoid rescuing/catching if you can't do anything with the exception.
For example, in a model method, you might be calling that from a
controller, but you also might be calling that from some scheduled
job. Thus, it's hard to say what the right action should be. A
special case is calling
raise
without arguments: sometimes it is reasonable to catch all exceptions, logging the exception, and then re-raising it like it was never caught. - If you catch an exception, consider if you should re-throw the exception because code at a different level will be able to handle the exception more properly.
- Consider how the code is being invoked, such as from a call to generate HTML or an ajax request, or maybe a batch job. All of these cases have very different needs for how the error should be handled.
- Be sure you understand the order of your rescue clauses matter. This
article The Universe between
begin
andend
provides a good explanation. Basically put the most specific exception types first and something likerescue => e
last. - Ruby does not support the concept of a "cause" with an exception. Thus, if you catch an exception and are going to rethrow a different exception, then it's important to log the stack of the original exception, or else that information will be lost.
- Test the logging of the exception in both development and production mode. You want to ensure that any exception prints clearly regardless of Rails environment.
- A good way to test error handling is to temporarily put in
raise ArgumentError
(or whatever other error), and see how the exception is handled, both by the logger and the UI. - The worst scenario is catching an exception and failing to log any messages. This can make troubleshooting a problem very tricky.
Verification and Testing
The next article, Testing Error Handling, will show you how to verify that your error handling strategy is properly implemented, and how to add rspec unit and functional tests on error handling.