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 software developer: most of my time in recent years has been spent writing Rails, though I've dabbled in many other things and like most people who have been writing code for decades I can learn new stuff as needed.

Currently I'm unemployed and starting to look around for my next opportunity as a senior manager, team lead, or lead developer. Drop me a comment if you're interested or email MikeG1 [at] larkfarm.com.

« Double Shot #342 | Main | Double Shot #341 »

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:

[sourcecode language='ruby']
Processing PostsController#index (for 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":

[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 )


def initialize
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) } }

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/ }

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

[sourcecode language='ruby']

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):
Some HTML allowed: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <code> <em> <i> <strike> <strong>