Search code examples
ruby-on-railsrubyloggingactiverecordruby-on-rails-6

Rails ActiveRecord::LogSubscriber not outputting verbose query logs

I'm trying to enable verbose query logging in Rails, but the ActiveRecord::LogSubscriber is behaving oddly, which is causing the verbose query logging to not work.

The issue seems to be originating here: https://github.com/rails/rails/blob/v6.0.0/activerecord/lib/active_record/log_subscriber.rb#L113

If I inspect the locations variable, I can see that it does have content:

[
  "/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activerecord-6.0.0/lib/active_record/log_subscriber.rb:100:in `debug'",
  "/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activerecord-6.0.0/lib/active_record/log_subscriber.rb:45:in `sql'",
  "/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.0/lib/active_support/subscriber.rb:145:in `finish'",
  "/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.0/lib/active_support/log_subscriber.rb:107:in `finish'",
  "/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.0/lib/active_support/notifications/fanout.rb:160:in `finish'",
  "/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.0/lib/active_support/notifications/fanout.rb:62:in `block in finish'",
  "/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.0/lib/active_support/notifications/fanout.rb:62:in `each'",
  ...
]

But once it's gone through the clean method, it's an empty array. So this:

backtrace_cleaner.clean(locations.lazy).first

is returning nil. Therefore, the source assignment on line 105 is nil, which means the if source on line 107 evaluates to false, and doesn't log anything.

UPDATE

I've added these two puts into ActiveRecord::LogSubscriber:

def log_query_source
  source = extract_query_source_location(caller)

  puts "-----\n-\n-\nCALLERS: #{caller.inspect}\n-\n-\n-----"

  if source
    logger.debug("  ↳ #{source}")
  end
end

def extract_query_source_location(locations)
  puts "-----\n-\n-\nCLEANER: #{backtrace_cleaner.instance_values}\n-\n-\n-----"

  backtrace_cleaner.clean(locations.lazy).first
end

to help gather some context about what's actually being registered as a caller and what the backtrace cleaner has established for filtering and silencing.

Here's the output for callers (I'm just including enough to show that there are sources listed from within our application):

[
  "/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activerecord-6.0.0/lib/active_record/log_subscriber.rb:100:in `debug'",
  
  ...

  "/Users/jeff/Development/lead-simple/LeadSimple/components/api/app/graph/api/loaders/association_loader.rb:47:in `preload_association'",
  "/Users/jeff/Development/lead-simple/LeadSimple/components/api/app/graph/api/loaders/association_loader.rb:34:in `perform'",

  ...

  "/Users/jeff/Development/lead-simple/LeadSimple/components/api/app/controllers/api/graphql_controller.rb:16:in `execute'",

  ...

  "/Users/jeff/Development/lead-simple/LeadSimple/components/api/lib/api/graphql_reloader.rb:18:in `call'",

  ...

  "/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/puma-5.6.5/lib/puma/thread_pool.rb:147:in `block in spawn_thread'"
]

And here's the output for the backtrace cleaner:

{
  "silencers"=>[
    #<Proc:0x0000000108343330@/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.0/lib/active_support/backtrace_cleaner.rb:101>, 
    #<Proc:0x00000001083432e0@/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.0/lib/active_support/backtrace_cleaner.rb:105>, 
    #<Proc:0x00000001083431c8@/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/railties-6.0.0/lib/rails/backtrace_cleaner.rb:19>
  ], 
  "filters"=>[
    #<Proc:0x0000000108343380@/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/activesupport-6.0.0/lib/active_support/backtrace_cleaner.rb:97>, 
    #<Proc:0x0000000108343240@/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/railties-6.0.0/lib/rails/backtrace_cleaner.rb:16>, 
    #<Proc:0x0000000108343218@/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/railties-6.0.0/lib/rails/backtrace_cleaner.rb:17>, 
    #<Proc:0x00000001083431f0@/Users/jeff/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/railties-6.0.0/lib/rails/backtrace_cleaner.rb:18>
  ], 
  "root"=>"/Users/jeff/Development/lead-simple/LeadSimple/"
}

As you can see, nothing specific to our application code is being silenced (or even filtered). However, there is that "root" instance value, which is very odd because if you look at the source code for ActiveRecord::BacktraceCleaner, the only instance variables that are defined are @filters and @silencers.

I'm guessing that that's involved here, since the path set as the value of "root" would be removing our application-level traces (if being used as a silencer). The problem is that I have no idea where that's coming from.

The only thing I could guess is that one of our gems is overloading ActiveSupport::BacktraceCleaner to add the @root instance variable and some additional layer of silencing based on that. ¯_(ツ)_/¯

Solution

  • The Rails Console Always Disables Verbose Logging

    Are you testing verbose logging by looking at what the Rails server is logging or by looking at activity in the Rails console? This line will always turn off verbose query logging for activity performed in the console:

    # ActiveRecord::Railtie
console do |app|
  require "active_record/railties/console_sandbox" if app.sandbox?
  require "active_record/base"
  unless ActiveSupport::Logger.logger_outputs_to?(Rails.logger, STDERR, STDOUT)
    console = ActiveSupport::Logger.new(STDERR)
    Rails.logger.extend ActiveSupport::Logger.broadcast console
  end
  ActiveRecord::Base.verbose_query_logs = false  # <--- HERE
end

    Here's the commit that added that line. The commit message provides more details and refers back to this issue. This is intentional and was done to reduce noise in the Rails console.

    If you want to turn verbose logging back on in the Rails console, you would have to manually reset the flag with:

    ActiveRecord::Base.verbose_query_logs = true

    Or you could add this in an initializer in your app to turn it on whenever the console boots:

    # config/initializers/verbose_logging.rb
Rails.application.console do
  ActiveRecord::Base.verbose_query_logs = true
end

    Note that the Rails Guide suggests not turning this on in Production because of the memory usage, so you may want to keep it off in that environment depending upon the resources available where you run your Production console.

    The Backtrace is Cleaned Before Logging

    When the verbose logging is made, Rails will attempt to drop out standard Ruby code references and gem reference so that the source location within the app is displayed. This is done using the cleaner in ActiveRecord::LogSubscriber.backtrace_cleaner which by default is the Rails::BacktraceCleaner which inherits from the ActiveSupport::BacktraceCleaner.

    To test if the Rails::BacktraceCleaner is accidentally cleaning out your code you could do something like this:

    # Get the source location for a class method somewhere in your app
path = MyClass.method(:my_class_method).source_location.first

# Run it through the BacktraceCleaner
backtrace_cleaner = Rails::BacktraceCleaner.new
backtrace_cleaner.clean([path])

    If that returns [] you might want to check to see if you put your app code in the RbConfig::CONFIG["rubylibdir"] folder. The BacktraceCleaner will assume that code there is a part of the standard Ruby library and will remove it from the backtrace.

    The Rails::BacktraceCleaner also excludes code that isn't found in the app, config, lib, or test subdirectories. That's done here.

    Your root says it is:

    /Users/jeff/Development/lead-simple/LeadSimple/

    And then the subfolder beneath that is:

    /Users/jeff/Development/lead-simple/LeadSimple/components/...

    Rails will clean that out of the backtrace. You can check with something like:

    test = ['/Users/jeff/Development/lead-simple/LeadSimple/components/api/app/graph/api/loaders/association_loader.rb']
backtrace_cleaner = Rails::BacktraceCleaner.new

# Filtering will drop off everything before the root
filtered = backtrace_cleaner.send(:filter_backtrace, [path])
 => ["components/api/app/graph/api/loaders/association_loader.rb"]

# Silencing will drop off paths that don't start with app, config, lib, or test
backtrace_cleaner.send(:silence, filtered)
 => []

    To avoid this you could:

    • Organize your code into different subfolders, or
    • Override Rails::BacktraceCleaner, or
    • Redefine Rails::BacktraceCleaner::APP_DIRS_PATTERN in an initializer

    The last option would be the easiest but will throw already initialized constant errors when the app boots.