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 が出ないのは１００歩譲って仕方がないとしても、 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 でロガーのインスタンスをとることができるようにするだろうから、それを使ってしまおうという作戦。

これでまた少しコードが綺麗になったな。