ActiveSupport::LogSubscriber をRailsの外で使ってリファクタリングする

Gemを書いてる時に、処理の前後でログを吐いたりSentryに投げたりといろいろなことを書いていたらコードが汚くなってきたので、なんとかモジュール分割できないかと思って調べてみた。

そもそもRailsの中でどういう風にログを出しているのかActiveJobのコードを読んでみると、 [ActiveJob::Logging::LogSubscriber](
https://github.com/rails/rails/blob/v6.0.2.2/activejob/lib/active_job/logging.rb#L55) でログを出しているようだ。
このクラスは [ActiveSupport::LogSubscriber](https://github.com/rails/rails/blob/v6.0.2.2/activesupport/lib/active_support/log_subscriber.rb) を継承していて、一通りログ系のメソッドが定義されているので、これをうまく使っていけないかと思ったところ見事にハマったので、解決方法を含めて記事に残しておく。


# Railsにおけるイベントのフック機能について調べてみた

そもそも [ActiveSupport::LogSubscriber](https://github.com/rails/rails/blob/v6.0.2.2/activesupport/lib/active_support/log_subscriber.rb) は何ぞやと調べてみたところ、Active SupportのPub/Sub機能を使ってログ出力する物であるということがわかってきた。（参照： [Active Support の Instrumentation機能](https://railsguides.jp/active_support_instrumentation.html#active-job)）

まず動きを理解するために [ActiveSupport::LogSubscriber](https://github.com/rails/rails/blob/v6.0.2.2/activesupport/lib/active_support/log_subscriber.rb) の親クラスである 」[ActiveSupport::Subscriber](https://github.com/rails/rails/blob/v6.0.2.2/activesupport/lib/active_support/subscriber.rb) を使って簡単な処理を書いてみる。

まず、 ①[ActiveSupport::Subscriber](https://github.com/rails/rails/blob/v6.0.2.2/activesupport/lib/active_support/subscriber.rb)を継承したクラスを作成した後、 ②`.attach_to` でイベントをサブスクライブし、③そこに対して `ActiveSupport::Notifications.instrument` でイベントをパブリッシュしてあげることで使うことができるようだ。

```ruby
# 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
```

```plaintext
SampleSubscriber ->  HelloInstrumentation! 1003.611ms
```

# ActiveSupport::LogSubscriberを使った実装を試してみる

[ActiveSupport::LogSubscriber](https://github.com/rails/rails/blob/v6.0.2.2/activesupport/lib/active_support/log_subscriber.rb)もこの要領で使えるのではないかと考えて、下記のコードを書いてみたが・・・甘かった。。

```ruby
# 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`](https://github.com/rails/rails/blob/eca6c273fe2729b9634907562c2717cf86443b6b/activesupport/lib/active_support/log_subscriber.rb#L83-L87) が問題だった。

Railsの場合は `Rails.logger` が入るが、それ以外だとnilになり、しかもそれをいろんな所のフックで使ってたので、 `#logger` がnil以外を返すとサブスクライブが始まらないのがそもそも動かない原因だった。

修正したコードは下記の通り。

```ruby
# 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
```

実行結果としては下記の感じで出力される。

```plaintext
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` でロガーのインスタンスをとることができるようにするだろうから、それを使ってしまおうという作戦。

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