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 online protection

Rails Long Term Support

Rails LTS provides security patches for old versions of Ruby on Rails (2.3, 3.2, 4.2 and 5.2)

  • Prevents you from data breaches and liability risks
  • Upgrade at your own pace
  • Works with modern Rubies
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)