Read more

How to fix: Rails query logs always show lib/active_record/log_subscriber.rb as source

Arne Hartherz
September 10, 2020Software engineer at makandra GmbH

Rails 5.2+ supports "verbose query logs" where it shows the source of a query in the application log.
Normally, it looks like this:

  User Load (0.5ms)  SELECT "users".* FROM "users" WHERE ...
  ↳ app/controllers/users_controller.rb:42:in `load_users'
Illustration book lover

Growing Rails Applications in Practice

Check out our e-book. Learn to structure large Ruby on Rails codebases with the tools you already know and love.

  • Introduce design conventions for controllers and user-facing models
  • Create a system for growth
  • Build applications to last
Read more Show archive.org snapshot

However, you may encounter ActiveRecord's LogSubscriber as the source for all/most queries which is not helpful at all:

  User Load (0.5ms)  SELECT "users".* FROM "users" WHERE ...
  ↳ activerecord (6.0.3.3) lib/active_record/log_subscriber.rb:100:in `debug'

While there was an issue back in 2018 Show archive.org snapshot which can be resolved by upgrading Rails, this also happens when ActiveSupport's BacktraceCleaner is configured to not hide gems from the backtrace. In such cases, log_subscriber.rb is the inner-most (i.e. "best") source in the backtrace.

You probably have an initializer with this line:

Rails.backtrace_cleaner.remove_silencers!

Remove it, and your verbose query logs will be helpful.

If you're using verbose query logs only in development, you may also choose to enable silencers in development only:

unless Rails.configuration.active_record.verbose_query_logs
  Rails.backtrace_cleaner.remove_silencers!
end
Posted by Arne Hartherz to makandra dev (2020-09-10 10:13)