最初に

このバグは既に 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
`ActiveSupport::BroadcastLogger` with `ActiveSupport::TaggedLogging` throws `no implicit conversion of String into Integer (TypeError)` · Issue #51883 · rails/rails
ActiveJob run multiple jobs per single enqueue in Rails 7.1 · Issue #52876 · rails/rails

事象

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

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

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

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

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月の時点でこの修正は取り込みされていませんでした。

回避策

修正されていないということは、 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についてコードリーディングしたメモ

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

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

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

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

モンキーパッチ

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

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 が修正するだろうということで
私はここで調査を打ち切りました。