A Fresh Cup is Mike Gunderloy's software development weblog, covering Ruby on Rails and whatever else I find interesting in the universe of software. I'm a full-time Rails developer and contributor, available for long- or short-term consulting, with solid experience in working as part of a distributed team. If you'd like to hire me, drop me a line. I'm also the author of Rails Rescue Handbook and Rails Freelancing Handbook.

Navigation
« Double Shot #342 | Main | Double Shot #341 »
Saturday
Nov292008

Rails 2.3: Backtrace Silencing

If you develop Rails applications, you're probably used to seeing this sort of thing in your log files:

terminalthumb

Really, the only important thing there (as far as helping me find the source of the error) is the very first line of the backtrace: ActiveRecord::StatementInvalid (SQLite3::SQLException: no such table: posts: SELECT * FROM "posts" ):. But Rails throws in another 55 lines of backtrace information, just in case I have exposed a bug somewhere in Active Record or Action Pack or the dispatcher or Mongrel or Rack or even the initial script/server command. In most cases, that's just noise.

Rails 2.3 (inspired by Thoughtbot's Quiet Backtrace plugin) is smart enough to just shut up about the parts I don't care. Here's the default Rails 2.3 log in the same situation:

[sourcecode language='ruby']
Processing PostsController#index (for 127.0.0.1 at 2008-11-29 08:12:31) [GET]
Post Load (0.0ms) SQLite3::SQLException: no such table: posts: SELECT * FROM "posts"

ActiveRecord::StatementInvalid (SQLite3::SQLException: no such table: posts: SELECT * FROM "posts" ):
/app/controllers/posts_controller.rb:5:in `index'

Rendered /Users/mike/scratch/blog23/vendor/rails/actionpack/lib/action_controller/templates/rescues/_trace (18.0ms)
Rendered /Users/mike/scratch/blog23/vendor/rails/actionpack/lib/action_controller/templates/rescues/_request_and_response (0.6ms)
Rendering /Users/mike/scratch/blog23/vendor/rails/actionpack/lib/action_controller/templates/rescues/layout.erb (internal_server_error)
Completed in 34ms (DB: 0) | 500 Internal Server Error [http://localhost/posts]
[/sourcecode]

Much nicer. Rails uses a combination of silencers (which just throw away lines matching a particular pattern) and filters (which make regex-based substitutions) to clean up the backtrace.

The guts of the backtrace cleaner are in ActiveSupport::BacktraceCleaner, letting you set up your own cleaners. Most of us, though, will be using the default backtrace cleaner that Rails spins up during initialization, Rails::BacktraceCleaner. Rails adds a variety of filters and silencers "out of the box":

[sourcecode language='ruby']
ERB_METHOD_SIG = /:in `_run_erb_.*/

VENDOR_DIRS = %w( vendor/plugins vendor/gems vendor/rails )
SERVER_DIRS = %w( lib/mongrel bin/mongrel lib/rack )
RAILS_NOISE = %w( script/server )
RUBY_NOISE = %w( rubygems/custom_require benchmark.rb )

ALL_NOISE = VENDOR_DIRS + SERVER_DIRS + RAILS_NOISE + RUBY_NOISE

def initialize
super
add_filter { |line| line.sub(RAILS_ROOT, '') }
add_filter { |line| line.sub(ERB_METHOD_SIG, '') }
add_filter { |line| line.sub('./', '/') } # for tests
add_silencer { |line| ALL_NOISE.any? { |dir| line.include?(dir) } }
end
[/sourcecode]

So, by default, Rails will throw away all the messages from the vendor folders and the servers, among other things. Naturally, you can change these defaults. Rails 2.3 adds a config/initializers/backtrace_silencers.rb file to your application. You can add your own silencers or filters in this file:

[sourcecode language='ruby']
Rails.backtrace_cleaner.add_silencer { |line| line =~ /my_noisy_library/ }
[/sourcecode]

You can also tell Rails to remove the default silencers if you're worried that you have uncovered a deeper bug:

[sourcecode language='ruby']
Rails.backtrace_cleaner.remove_silencers!
[/sourcecode]

Because the silencer is set up during the initialization process, you need to restart the server if you make any changes to it.

Currently in edge, the in-browser backtrace pages that you get in development mode show the full backtrace, not the silenced one.

Reader Comments (4)

For example, you could pretty print lines generated by gems like this (your gem path may vary):


Rails.backtrace_cleaner.add_filter {|line|
line.sub(/(\/usr\/lib\/ruby\/gems\/1.8\/gems\/)([a-z]+)-([0-9.]+)\/(.*)/) {|match| " #{$2} (#{$3}) :#{$4}"}
}

Getting backtraces like


/app/controllers/blogs_controller.rb:5:in `index'
thin (0.6.4) :lib/thin/connection.rb:35:in `process'
thin (0.6.4) :lib/thin/connection.rb:23:in `receive_data'
eventmachine (0.10.0) :lib/eventmachine.rb:1056:in `event_callback'
eventmachine (0.10.0) :lib/eventmachine.rb:224:in `run_machine'
eventmachine (0.10.0) :lib/eventmachine.rb:224:in `run'
thin (0.6.4) :lib/thin/server.rb:113:in `start'

November 29, 2008 | Unregistered CommenterJuan Lupión

Juan, that's a great filter! Looks really nice.

November 30, 2008 | Unregistered CommenterDHH

I added cleaner and a pleasure to work, thanks for the example

February 18, 2009 | Unregistered CommenterRuby developer

PostPost a New Comment

Enter your information below to add a new comment.
Author Email (optional):
Author URL (optional):
Post:
 
Some HTML allowed: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <code> <em> <i> <strike> <strong>