Rails 2.3: Backtrace Silencing

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

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:

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]

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”:

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

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:

Rails.backtrace_cleaner.add_silencer { |line| line =~ /my_noisy_library/ }

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

Rails.backtrace_cleaner.remove_silencers!

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.