ActiveSupport::LogSubscriber をRailsの外で使ってリファクタリングする
Gemを書いてる時に、処理の前後でログを吐いたりSentryに投げたりといろいろなことを書いていたらコードが汚くなってきたので、なんとかモジュール分割できないかと思って調べてみた。
そもそもRailsの中でどういう風にログを出しているのかActiveJobのコードを読んでみると、 ActiveJob::Logging::LogSubscriber でログを出しているようだ。
このクラスは ActiveSupport::LogSubscriber を継承していて、一通りログ系のメソッドが定義されているので、これをうまく使っていけないかと思ったところ見事にハマったので、解決方法を含めて記事に残しておく。
Railsにおけるイベントのフック機能について調べてみた
そもそも ActiveSupport::LogSubscriber は何ぞやと調べてみたところ、Active SupportのPub/Sub機能を使ってログ出力する物であるということがわかってきた。(参照: Active Support の Instrumentation機能)
まず動きを理解するために ActiveSupport::LogSubscriber の親クラスである 」ActiveSupport::Subscriber を使って簡単な処理を書いてみる。
まず、 ①ActiveSupport::Subscriberを継承したクラスを作成した後、 ②.attach_to
でイベントをサブスクライブし、③そこに対して ActiveSupport::Notifications.instrument
でイベントをパブリッシュしてあげることで使うことができるようだ。
# frozen_string_literal: true
require 'active_support'
require 'active_support/subscriber'
# ①
class SampleSubscriber < ActiveSupport::Subscriber
def message(event)
puts format 'SampleSubscriber -> %s %.3fms', event.payload[:text], event.duration
end
end
# ②
SampleSubscriber.attach_to :sample
class Hoge
def self.fuga
# ③
ActiveSupport::Notifications.instrument('message.sample', text: 'HelloInstrumentation!') do
sleep 1
end
end
end
Hoge.fuga
SampleSubscriber -> HelloInstrumentation! 1003.611ms
ActiveSupport::LogSubscriberを使った実装を試してみる
ActiveSupport::LogSubscriberもこの要領で使えるのではないかと考えて、下記のコードを書いてみたが・・・甘かった。。
# frozen_string_literal: true
require 'active_support'
require 'active_support/subscriber'
# ↓動かなかったコード
class SampleLogSubscriber < ActiveSupport::LogSubscriber
def message(event)
puts format 'SampleLogSubscriber -> %s %.3fms', event.payload[:text], event.duration
warn format 'SampleLogSubscriber -> %s %.3fms', event.payload[:text], event.duration
end
end
SampleLogSubscriber.attach_to :sample2
class Hoge2
def self.fuga
ActiveSupport::Notifications.instrument('message.sample2', text: 'HelloInstrumentation!') do
sleep 1
end
end
end
Hoge2.fuga
warn
が出ないのは100歩譲って仕方がないとしても、 puts
が出ないのはふに落ちず、いろいろ調べてみたところ、結論LogSubscriberの中で呼ばれている #logger
が問題だった。
Railsの場合は Rails.logger
が入るが、それ以外だとnilになり、しかもそれをいろんな所のフックで使ってたので、 #logger
がnil以外を返すとサブスクライブが始まらないのがそもそも動かない原因だった。
修正したコードは下記の通り。
# frozen_string_literal: true
require 'active_support'
require 'active_support/subscriber'
class SampleLogSubscriber2 < ActiveSupport::LogSubscriber
# このメソッド定義が鍵だった
def logger
@logger ||= ::Logger.new(STDOUT)
end
def message(event)
puts format 'SampleLogSubscriber2 -> %s %.3fms', event.payload[:text], event.duration
warn format 'SampleLogSubscriber2 -> %s %.3fms', event.payload[:text], event.duration
end
end
SampleLogSubscriber2.attach_to :sample2
class Hoge2
def self.fuga
ActiveSupport::Notifications.instrument('message.sample2', text: 'HelloInstrumentation!') do
sleep 1
end
end
end
Hoge2.fuga
実行結果としては下記の感じで出力される。
SampleLogSubscriber2 -> HelloInstrumentation! 1002.740ms
W, [2020-05-04T16:45:38.153097 #8801] WARN -- : SampleLogSubscriber2 -> HelloInstrumentation! 1002.740ms
実際に活用する
これについて、後付けで @logger
を設定できないか考えたが、 SampleLogSubscriber2
のインスタンスを引っ張り出す方がめんどうそうだったので、インスタンスメソッドの定義でまずはよしとすることにした。
上記だと @logger = ::Logger.new(STDOUT)
で書いたけど、どうせGemだと #{Module名}.logger
でロガーのインスタンスをとることができるようにするだろうから、それを使ってしまおうという作戦。
これでまた少しコードが綺麗になったな。
Discussion