Zenn
🌊

[デバッグ効率化] Rails のログにプレースホルダー置換済みのクエリを出力したい

2024/04/08に公開
Rails
SQL
tech

はじめに

Rails アプリケーションの開発中、ログに出力されたクエリの調査・分析をすることがあると思います。しかし、ログにあるクエリはプレースホルダーが置換されておらず、データベースで実行できる形式ではありません。例えば、次のようなログです。

User Load (0.1ms)  SELECT "users".* FROM "users" WHERE "users"."id" = $1  [["id", 1]]

このクエリをデータベースで実行可能にするためには、プレースホルダーを置換して次のようなクエリを組み立てる必要があります。

SELECT "users".* FROM "users" WHERE "users"."id" = 1

この組み立ての手間を省くため、ログにプレースホルダー置換済みのクエリを出力する方法を考えました。この記事では、その方法を順を追って解説します。

動作環境

  • Rails 7.1.3.2
  • Ruby 3.3.0
  • PostgreSQL 16.2

Rails のクエリのログはどのように出力される？

Rails では、ActiveRecord::LogSubscriber を介してクエリのログが出力されます。ActiveRecord::LogSubscriberは、ActiveRecord によるクエリ発行時に発火する'sql.active_record'という名前のイベントをサブスクライブして、そのクエリ情報をログに出力しています。

'sql.active_record'をサブスクライブするためには、ActiveSupport::Notifications.subscribe を使います。

ActiveSupport::Notifications.subscribe 'sql.active_record' do |event|
  Rails.logger.debug event
end

このコードを config/initializers/custom_log_subscriber.rb に配置して Rails を起動すると、'sql.active_record'イベントの中身がログに出力されるようになります。クエリの詳細情報は 'sql.active_record' の payload に含まれています。以下はその例です。

{
  sql: "SELECT \"users\".* FROM \"users\" WHERE \"users\".\"id\" = $1",
  name: "User Load",
  binds: [#<ActiveRecord::Relation::QueryAttribute:0x000000010788c630 @name="id", @value_before_type_cast="1", ...],
  type_casted_binds: [1],
  statement_name: nil,
  async: false,
  connection: #<ActiveRecord::ConnectionAdapters::PostgreSQLAdapter:0x000000011153f040...
}

sql はクエリの本文、type_casted_binds は型変換済みのバインド変数（ プレースホルダーに割り当てる実際の値 ）です。

イベント 'sql.active_record' からクエリを組み立てる

イベント 'sql.active_record' の payload にあるクエリ本文（sql ）と型変換済みバインド変数（ type_casted_binds ）を用いて、実行可能なクエリを組み立てることができます。

ActiveRecord には、値をサニタイズ（無害化）してプレースホルダーを置換するメソッドが様々備わっています。以下はActiveRecord::Base.sanitize_sql_arrayを使った例です。

ActiveRecord::Base.sanitize_sql_array([
  "SELECT \"users\".* FROM \"users\" WHERE \"users\".\"id\" = ?",
  1,
])
#=> "SELECT \"users\".* FROM \"users\" WHERE \"users\".\"id\" = 1"

なお、ここでは $1 を ? に事前に置換しています。というのも、ActiveRecord::Base.sanitize_sql_array は $1 という形式のプレースホルダーに未対応であり、位置指定ハンドラ（ ? ）もしくは名前付きハンドラ（ :hoge など）のみに対応しているためです。

組み立て済みのクエリをログに出力する

ActiveRecord::Base.sanitize_sql_arrayを用いたプレースホルダー置換を、イベント 'sql.active_record' の変換処理に組み込むと、次のようになります。


ActiveSupport::Notifications.subscribe 'sql.active_record' do |event|
  sql = event.payload[:sql].gsub(/\$\d+/, '?') # $1, $2, ... を ?, ?, ... に変換
  type_casted_binds = event.payload[:type_casted_binds]
  sanitized_sql = ActiveRecord::Base.sanitize_sql_array([sql, *type_casted_binds])

  Rails.logger.debug "/* sanitized sql */ #{sanitized_sql}"
end

これで、ログにプレースホルダー置換済みのクエリが出力されるようになりました🎉

/* sanitized sql */ SELECT "users".* FROM "users" WHERE "users"."id" = 1

組み立て済みクエリのログ出力の最適化

上記のコードを実際に試すと、すべてのクエリがログに出力されるようになります。不要なクエリをログに出力しないようにするため、また、本番環境での意図しないログ出力を行わないようにするため、次のような改善が考えられます。

ActiveSupport::Notifications.subscribe 'sql.active_record' do |event|
  next unless Rails.env.development? # 開発環境に限定する

  payload = event.payload

  next if payload[:name] == 'SCHEMA' # DB 設定等のクエリを対象外とする
  next if payload[:type_casted_binds].blank? # バインド変数がある場合のみを対象とする

  sql = payload[:sql].gsub(/\$\d+/, '?')

  # type_casted_binds は Proc を返すことがある
  type_casted_binds = payload[:type_casted_binds].respond_to?(:call) ? payload[:type_casted_binds].call : payload[:type_casted_binds]
  sanitized_sql = ActiveRecord::Base.sanitize_sql_array([sql, *type_casted_binds])

  Rails.logger.debug "/* sanitized sql */ #{sanitized_sql}"
end

まとめ

Rails でのクエリのログ出力の仕組みの大枠と、実行可能なクエリを組み立てる方法、および組み立て済みのクエリをログに出力する方法を紹介しました。本記事が、Rails のログのクエリの調査・分析の一助となれば幸いです。

参考資料

Discussion