Rails で `logger.tagged` を使ったらアクションが複数回実行された

# 最初に

このバグは既に Rails に Issue が作成されているものです。
Rails 7.1 あたりから発生している様子。

* [\`Rails\.logger\.tagged\` will execute block as many times as the number of tagged loggers in the broadcast · Issue \#49745 · rails/rails](https://github.com/rails/rails/issues/49745)
* [\`ActiveSupport::BroadcastLogger\` with \`ActiveSupport::TaggedLogging\` throws \`no implicit conversion of String into Integer \(TypeError\)\` · Issue \#51883 · rails/rails](https://github.com/rails/rails/issues/51883)
* [ActiveJob run multiple jobs per single enqueue in Rails 7\.1 · Issue \#52876 · rails/rails](https://github.com/rails/rails/issues/52876)

## 事象

Ruby は `Logger` ライブラリを持ちますが、 Rails は `Logger` が持たない機能を幾つか提供してくれています。

その中の一つに `#tagged` メソッドがあります。

このメソッドは Rails ガイドでも紹介されていて、タグとブロックを渡す使い方がよく知られています。

Rails ガイドからの使用方法の引用:

> ```ruby
> logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
> logger.tagged("BCX") { logger.info "Stuff" }                            # Logs "[BCX] Stuff"
> logger.tagged("BCX", "Jason") { logger.info "Stuff" }                   # Logs "[BCX] [Jason] Stuff"
> logger.tagged("BCX") { logger.tagged("Jason") { logger.info "Stuff" } } # Logs "[BCX] [Jason] Stuff"
> ```

* Rails ガイド:
  * WEBサイト: https://guides.rubyonrails.org/debugging_rails_applications.html#tagged-logging
  * Rails 8.0.1 のソースコード: https://github.com/rails/rails/blob/v8.0.1/guides/source/debugging_rails_applications.md#tagged-logging

しかし、この機能は条件を満たすと**渡したブロックが複数回実行される**という思わぬバグを引き起こします。

ブロックの中で ActiveRecord からレコードを保存していると、一度のリクエストで複数回データが作成されたりして大きな問題になります。

## 原因

Rails が提供している `Logger` の拡張機能は1つではありません。

もう一つ `ActiveSupport::BroadcastLogger` という複数の `Logger` を束ねる便利なクラスが Rails 7.1 で追加されています。

`ActiveSupport::BroadcastLogger` の用途としては、開発中はログファイルと `STDOUT` の両方にログを出力するといったものが想定されていると思います。

その `ActiveSupport::BroadcastLogger` の動作は単純で `Logger` と同じメソッドを実装しており、
それぞれのメソッドは内部に持つ `Logger` の同名メソッドを呼び出す実装になっています。

基本的には `ActiveSupport::BroadcastLogger#dispatch` でこの動作が実現されています。

* `ActiveSupport::BroadcastLogger#dispatch`: https://github.com/rails/rails/blob/v8.0.1/activesupport/lib/active_support/broadcast_logger.rb#L230-L233

`ActiveSupport::BroadcastLogger` には `#tagged` メソッドはありませんが、
しかし、 `method_missing` 経由で呼び出ししようとしたメソッドを持つ `Logger` オブジェクトが集められて、
`Logger` オブジェクトの数だけメソッドが呼び出しされるようになっています。

* `ActiveSupport::BroadcastLogger#method_missing`: https://github.com/rails/rails/blob/v8.0.1/activesupport/lib/active_support/broadcast_logger.rb#L235-L245


なので、 `ActiveSupport::TaggedLogging#tagged` が使えるオブジェクトを `ActiveSupport::BroadcastLogger` に2つ以上渡していると、単純に `#tagged` に渡したブロックが `Logger` オブジェクトの数だけ呼び出しされるという状況になっています。

ブロック内部で複数回実行するべきではない操作があると、不具合が発生するということです。

## 修正

Rails 7.1 の頃に `ActiveSupport::BroadcastLogger` が追加されており、 Issue も報告されているので Merge Request も提出されていますが、
2024年1月の時点でこの修正は取り込みされていませんでした。

* [Reimplement TaggedLogging: by Edouard\-chin · Pull Request \#49771 · rails/rails](https://github.com/rails/rails/pull/49771)
* [BroadcastLogger should support TaggedLogging correctly by armstrjare · Pull Request \#53105 · rails/rails](https://github.com/rails/rails/pull/53105)

## 回避策

修正されていないということは、 `ActiveSupport::TaggedLogging` と `ActiveSupport::BroadcastLogger` は一緒に使うべきではないと考えてしまいますが、
Rails 8 からは `Rails.logger` がデフォルトでこの2つの機能を持つロガーオブジェクトになっているようです。

しかし、 Rails が `config/production.rb` で本番環境ではログにリクエストIDを出力する機能を提供しているのに
私は `ActiveSupport::BroadcastLogger` で複数の `Logger` を使っていても不具合には遭遇しませんでした。

コントローラーで `#tagged` を使ったとたん、今回の不具合に遭遇したのです。

つまり、 Rails がリクエストIDをログに出力するときは `#tagged` を使わずにタグをつけているということになります。

なら、 Rails がリクエストIDをタグに追加しているソースコードを探せばいいということで探してみると、
`Rails::Rack::Logger` が見つかりました。

* `Rails::Rack::Logger`: https://github.com/rails/rails/blob/v8.0.1/railties/lib/rails/rack/logger.rb

ソースコードを眺めてみると `#tagged` ではなく `logger.push_tags` と `logger.pop_tags` を使っています。

この2つのメソッドは `#tagged` 内部で使用されているタグの追加と削除を行うメソッドなのですが、
そのあたりは次のリンク先で調べている方がいらっしゃったので、そちらを読んでいただければと思います。

* [Railsのログに含まれるrequest\_idについてコードリーディングしたメモ](https://zenn.dev/bisque/scraps/e0c58eb6fd07fa)

### `Rails::Rack::Logger` を使う

今の時点で使用できて、モンキーパッチを使わない不具合回避策は
`Rails::Rack::Logger` にタグをつけてもらう方法だと思います。

`config.log_tags` は `Symbol` を渡すと `request` の同名メソッドからタグを生成しますが、
ブロックを渡すと `request` を引数にブロックが実行されてその返り値がタグに使用されます。
これを利用してタグを付けることが出来ます。


```ruby
Rails.application.configure do
  config.log_tags = [
    :request_id,
    ->(request) {
       # Do Stuff
    }
  ]
end
```

### モンキーパッチ

モンキーパッチを使う場合は次のようになると思います。
注意点として、**動作確認はしていません**。
Rails 本体で修正されるべき不具合にモンキーパッチを用意するのはあまり好きではないので。
このモンキーパッチは実際に使用していないということを承知の上で使用してください。

```ruby
module BroadcastLoggerMonkeyPatch
  def tagged(*tags)
    # ブロックが渡されていなければ不具合は発生しないので super を呼び出し。
    return super unless block_given?

    # ブロックが渡されているときは `ActiveSupport::BroadcastLogger#dispatch` から
    # 各ロガーにアクセスしてタグの Push / Pop 操作を実施。
    pushed_counts = []
    begin
      dispatch do |logger|
        pushed_count =
          if logger.respond_to?(:tagged)
            logger.push_tags(*tags).size
          end
        pushed_counts << pushed_count
      end

      yield self
    ensure
      dispatch do |logger|
        pushed_count = pushed_counts.pop
        # logger.push_tags を呼び出していない。
        next if pushed_count.nil?

        logger.pop_tags(pushed_count)
      end
    end
  end
end

class ActiveSupport::BroadcastLogger
  prepend BroadcastLoggerMonkeyPatch
end
```

このモンキーパッチの問題点は `#tagged` に渡したブロック内部で `ActiveSupport::BroadcastLogger` のロガー数が変わるとタグの操作が上手くいかない点です。
多分 `Rails::Rack::Logger` も同じ問題を抱えていますが、いずれ Rails が修正するだろうということで
私はここで調査を打ち切りました。