Rails ActiveRecord::LogSubscriber が詳細なクエリ ログを出力しない
概要
Rails で詳細クエリ ログを有効にしようとしていますが、ActiveRecord::LogSubscriber の動作がおかしく、詳細クエリ ログが機能しません。
問題はここから発生しているようです: https://github.com/rails/rails/blob/v6.0.0/activerecord/lib/active_record/log_subscriber.rb#L113
location 変数を調べると、内容があることがわかります。
[
"/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'",
...
]
ただし、clean メソッドを通過すると、空の配列になります。したがって、この：
backtrace_cleaner.clean(locations.lazy).first
nilを返しています。したがって、105 行目のソース割り当ては nil です。これは、107 行目の if ソースが false と評価され、何も記録されないことを意味します。
これら 2 つの put を 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
これは、実際に発信者として登録されているものと、バックトレース クリーナーがフィルタリングとサイレンシングのために確立したものに関するコンテキストを収集するのに役立ちます。
呼び出し元の出力は次のとおりです (アプリケーション内からリストされたソースがあることを示すのに十分なものだけを含めています)。
[
"/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'"
]
バックトレース クリーナーの出力は次のとおりです。
{
"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/"
}
ご覧のとおり、アプリケーション コードに固有のものは何もサイレント化 (またはフィルター処理) されていません。ただし、「ルート」インスタンス値が存在します。これは非常に奇妙です。ActiveRecord::BacktraceCleaner のソース コードを見ると、定義されているインスタンス変数は @filters と @silencers だけであるためです。
「root」の値として設定されたパスはアプリケーションレベルのトレースを削除することになるため、これが関係していると思います（サイレンサーとして使用されている場合）。問題は、それがどこから来たのかわからないことです。
私が推測できる唯一のことは、Gem の 1 つが ActiveSupport::BacktraceCleaner をオーバーロードして、@root インスタンス変数とそれに基づいたサイレンシングの追加レイヤーを追加しているということです。 ￣(ツ)/￣
解決策
Rails サーバーがログに記録している内容を確認することによって、または Rails コンソールのアクティビティを確認することによって、詳細ログをテストしていますか?この行は、コンソールで実行されるアクティビティの詳細なクエリのログを常にオフにします。
# 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
その行を追加したコミットは次のとおりです。コミット メッセージには詳細が記載されており、この問題についても言及されています。これは意図的なもので、Rails コンソールのノイズを減らすために行われました。
Rails コンソールで詳細ログをオンに戻したい場合は、次のようにフラグを手動でリセットする必要があります。
ActiveRecord::Base.verbose_query_logs = true
または、これをアプリのイニシャライザーに追加して、コンソールが起動するたびにオンにすることもできます。
# config/initializers/verbose_logging.rb
Rails.application.console do
ActiveRecord::Base.verbose_query_logs = true
end
Rails ガイドでは、メモリ使用量を理由に、運用環境ではこれをオンにしないことを推奨しているため、運用コンソールを実行する利用可能なリソースに応じて、その環境では無効にしておくことが必要になる場合があります。
詳細ログが作成されると、Rails はアプリ内のソースの場所が表示されるように、標準の Ruby コード参照と gem リファレンスを削除しようとします。これは、ActiveRecord::LogSubscriber.backtrace_cleaner のクリーナーを使用して行われます。デフォルトでは、ActiveSupport::BacktraceCleaner から継承する Rails::BacktraceCleaner です。
Rails::BacktraceCleaner が誤ってコードを消去しているかどうかをテストするには、次のようなことができます。
# 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])
[] が返された場合は、アプリのコードを RbConfig::CONFIG[“rubylibdir”] フォルダーに配置しているかどうかを確認してください。 BacktraceCleaner は、コードが標準 Ruby ライブラリの一部であると想定し、バックトレースから削除します。
Rails::BacktraceCleaner は、app、config、lib、または test サブディレクトリに見つからないコードも除外します。それはここで完了です。
あなたのルートは次のように述べています：
/Users/jeff/Development/lead-simple/LeadSimple/
そして、その下のサブフォルダーは次のとおりです。
/Users/jeff/Development/lead-simple/LeadSimple/components/...
Rails はバックトレースからそれを削除します。次のようなもので確認できます。
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)
=> []
これを回避するには、次のようにすることができます。
最後のオプションが最も簡単ですが、アプリの起動時にすでに初期化された定数エラーがスローされます。