Railsで更新系のSQLだけログに出力する方法

最近、鼻づまりがひどいWebエンジニアのほんまです。今までだましだましやってきましたが、ついに花粉症になってしまったかもしれません😷🌸

さて、今回も前回に引き続き、ログ出力で工夫していることを紹介しようと思います。

背景

調査依頼などでログを追っていると、いつ、どういった流れでデータが追加/変更/削除されたのか、知りたい時がある。
そのような時、SQLがログに出力されていると調査がはかどる。
Railsではログレベルを DEBUG にすることで、SQLがログに記録されるようになる。
しかし、SELECTのログも記録されるため、大量のログで見づらくなったり、ディスクを圧迫する問題がある。
更新系のSQLだけログに出力する方法はないものだろうか？

対策

SQL実行の検知

RailsではSQLが発行されるたびに sql.activerecord というイベントを通知しています。 rails/abstract_adapter.rb at v5.2.2 · rails/rails · GitHub

このイベントは ActiveSupport::Subscriber を継承したサブクラスを定義することで、通知を受け取ってなんらかの処理をすることができます。ちょっと試してみます。

# $ rails c --sandbox

class HogeSubscriber < ::ActiveSupport::Subscriber
  attach_to :active_record

  def sql(event)
    puts 'Hoge!!'
  end
end

User.first 
# => Hoge!!
# => :
User.count
# => Hoge!!

user = User.create!(name: 'name', age: 19, birth_date: Date.new(2000, 1, 1))
# => Hoge!!
# => :

user.name = 'New name'
user.save!
# => Hoge!!
# => :

user.destroy!
# => Hoge!!
# => :

SQLが発行されるたびに処理が実行されていることがわかるかと思います。

SQLの種類の検知

これではSELECTも含めた全てのSQLでログ出力してしまうため、更新系のSQLに絞って実行したいです。ここで #sql メソッドに渡される event オブジェクトを見てみます。

#<ActiveSupport::Notifications::Event:.... @name="sql.active_record", 
@payload={
  :sql=>"INSERT INTO \"users\" (\"name\", \"age\", \"birth_date\", \"created_at\", \"updated_at\") VALUES (?, ?, ?, ?, ?)", 
  :name=>"User Create", 
  :binds=>[...], 
  :type_casted_binds=>["name", 20, "2000-01-01", "2019-02-20 01:44:57.289790", "2019-02-20 01:44:57.289790"], 
  :statement_name=>nil, 
  :connection_id=>....
}, 
@time=...., 
@transaction_id="....", 
@end=...., 
@children=[], 
@duration=nil>

ここを見ると event.payload[:sql] を使えば、実行されたSQLを取得することができそうです。

更新系のSQLに限定

上記の結果を使って、更新系のSQLのみ 'Hoge!!' を出力してみます。 SQLのフィルタは、シンプルに正規表現を使って行います。

# $ rails c --sandbox

class HogeSubscriber < ::ActiveSupport::Subscriber
  attach_to :active_record

  def sql(event)
    return unless /\A\s*(insert|update|delete)/mi.match?(event.payload[:sql].to_s)

    puts 'Hoge!!'
  end
end

# 'Hoge!!' が出力されない
User.first 
User.count

user = User.create!(name: 'name', age: 19, birth_date: Date.new(2000, 1, 1))
# => Hoge!!

user.name = 'New name'
user.save!
# => Hoge!!

user.destroy!
# => Hoge!!

うまく更新系のSQLだけ対象にすることができました。実際は INSERT UPDATE DELETE 以外にトランザクションに関連するSQLも出力されていると便利なので、 BEGIN COMMIT ROLLBACK 等も対象にするとよいと思います。

ログを出力する

ここまでくれば、あとはログ出力するだけです。 Railsには ActiveRecord::LogSubscriber という ActiveSupport::Subscriber のサブクラスがあり、これが今回の用途にぴったりなので使います。

# $ rails c --sandbox

class MyLogSubscriber < ::ActiveRecord::LogSubscriber
  attach_to :active_record

  def sql(event)
    payload = event.payload
    return unless /\A\s*(insert|update|delete)/mi.match?(event.payload[:sql].to_s)

    sql = payload[:sql]
    binds = type_casted_binds(payload[:type_casted_binds]) # bind変数の抽出

    info("#{sql}; #{binds}") # ActiveRecord::Base.loggerにINFOで出力
  end
end

# テスト用に標準出力にINFOでログ出力
::ActiveRecord::Base.logger = ::Logger.new(STDOUT, level: :info)

# ログ出力なし
User.first 
User.count

user = User.create!(name: 'name', age: 19, birth_date: Date.new(2000, 1, 1))
# => I, [2019-02-20T14:47:16.953034 #88627]  INFO -- : INSERT INTO "users" ("name", "age", "birth_date", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?); ["name", 19, "2000-01-01", "2019-02-20 05:47:16.951833", "2019-02-20 05:47:16.951833"]

user.name = 'New name'
user.save!
# => I, [2019-02-20T14:47:26.664047 #88627]  INFO -- : UPDATE "users" SET "name" = ?, "updated_at" = ? WHERE "users"."id" = ?; ["New name", "2019-02-20 05:47:26.662978", 5]

user.destroy!
# => I, [2019-02-20T14:47:30.762377 #88627]  INFO -- : DELETE FROM "users" WHERE "users"."id" = ?; [5]

目的を達成することできました😊

Railsに適用する場合、独自のLogSubscriberの定義を config/initializer/ 以下で行えばOKです。

gem化

この手のちょい便利な機能をgem化するのが好きなので、今回もgemにしています。ここで紹介した内容より、もう少し機能やオプションが追加されています。よかったら使って見てください。IssueやPull Requestも歓迎です😄

github.com

まとめ

今回、Railsで更新系のSQLのみを出力する方法を紹介しました。

また今回の方法は、過去のエントリーで紹介した「ログにリクエストIDを入れる」とも組み合わせることができます。組み合わせると「どのリクエストでデータにどういった変更があったのか？」が明確にわかるため、ログ調査がかなりはかどるためオススメです。

tech.unifa-e.com tech.unifa-e.com

以上になります。参考になれば幸いです。最後までご覧いただき、ありがとうございました。

ユニファ開発者ブログ

ユニファ株式会社プロダクトデベロップメント本部メンバーによるブログです。