この記事はクラウドワークスグループ Advent Calendar 2024 シリーズ1の11日目の記事です。

こんにちは。クラウドワークスで不正利用対策チームのバックエンドエンジニアとして働いている得能 (@yoshi_10_11) です。

今回はinitializersに設定した内容が反映されなかった話です。

Railsのconfig内でapplication.rb、environments/xxx.rb、initializers/xxx.rbなどのファイルを編集することがあるかと思います。みなさんはこれらがどのように読み込まれるのかを知っていますか？

完全解説！とまではいきませんが、最終的にはinitializers/xxx.rbのファイルを読み込むコードを読むところまで書いていきますのでひとつの参考になればと思います。

事例

config/application.rbに以下のLogger設定コードが記述されていました。

※記事用にコードを簡略化しています

# config/application.rb
logger = ActiveSupport::Logger.new(STDOUT)
logger.formatter = JsonLogFormatter.new
config.logger = ActiveSupport::TaggedLogging.new(logger)

JsonLogFormatterはLoggerをJSONで出力するための設定です。(RailsのデフォルトはJSON出力ではない)
JSON化したログ出力は出力先で捕捉して保存しAamazon Athenaで閲覧できるようになっています。

config/application.rb内はLogger設定以外にもいろいろ設定コードが記載されているため情報量が多い状態でした。

そこで、「Loggerの設定をinitializersに切り出して可読性を上げよう！」と考えました。
config/initializers/logger.rbという新規ファイルを作成し、上記のコードをそのまま移動させました。

ファイル分割を行ったことでLogger設定がどこで行われているのかがわかりやすくなりました。

しかし、コードの変更前後でログの出力に差異がないかをリリース前にStaging環境でテストしてみたところ、Logger設定が反映されなくなった(RailsのデフォルトのLogger設定が反映されている状態)ことがわかりました。

Loggerの定義場所を移動しただけでLoggerの設定が変わってしまったのです。

JsonLogFormatterなどのFormatter設定が無効になり、非JSON形式となったログを捕捉することができなくなり、適切に保存されなくなってしまいました…

仮説

なぜこのような問題が起きたのでしょう？

Loggerの設定コードの記述自体は変更しておらず、定義する場所が変わったのみです。コード自体に問題があればRailsアプリケーション起動時に何かしらのエラーが起きると思われるため、コード自体には問題はないと思いました。

Logger設定はconfig/application.rb以外にもconfig/environments配下などでも設定することがあり、そちらの場合は問題なく動作します。

そのため、Railsアプリケーション起動時のRailsのConfig周辺の読み込み順の問題なのではないか。config/initializersの読み込み順は全体の中でも遅めの部類に入るのではないか。という仮説を立てました。

RailsのConfigの読み込み順を調査する

では実際に調査をしてみましょう。

Railsガイドを読んでみる

まずはRailsガイドを読んでみましょう。

Rails の初期化プロセス

まずは「1. 起動!」の章を読んでみましょう。
細かい説明はRailsガイドを読んでいただければわかるので省略しますが、開発するRailsアプリケーション内で定義するファイルについてのみ触れると、
Railsが起動後にconfig/application、config/environmentsの順に読み込まれます。

config/environments内に記述したLogger設定は有効に機能するので、ここまでの設定はまだ問題ありません。

さらに読み進めて「2. Railsを読み込む」を見てみましょう。
「2.3 railties/lib/rails/application.rb」を見ると

def initialize!(group = :default) # :nodoc:
    raise "Application has been already initialized." if @initialized
    run_initializers(group, self)
    @initialized = true
    self
end

アプリケーションは一度だけ初期化できます。railties/lib/rails/initializable.rbで定義されているrun_initializersメソッドによって、Railtieのさまざまなイニシャライザが実行されます。

引用元: https://railsguides.jp/initialization.html#railties-lib-rails-application-rb

と書かれています。

こちらに書かれているinitializersは

Railtieイニシャライザ全体と、load_config_initializersイニシャライザのインスタンスやそれに関連するconfig/initializers以下のイニシャライザ設定ファイルを混同しないようにしましょう。

引用元: https://railsguides.jp/initialization.html#railties-lib-rails-application-rb

と書かれているようにイコールconfig/initializersではないため注意が必要です。Railsアプリケーションを実行するうえで初期化処理を行うものを処理する箇所になります。

しかし、config/initializersとはイコールではありませんが、この初期化処理されるリストの中にconfig/initializersで定義したファイル群が含まれます。そのため、この中のrun_initializersを見ると今回の疑問を解消することができそうです。

railties/lib/rails/initializable.rb

def run_initializers(group = :default, *args)
    return if instance_variable_defined?(:@ran)
    initializers.tsort_each do |initializer|
        initializer.run(*args) if initializer.belongs_to?(group)
    end
    @ran = true
end

引用元: https://railsguides.jp/initialization.html#railties-lib-rails-application-rb

読んでみるとざっくりinitializersをtsort_eachして、ひとつひとつrunで初期化処理をしているという流れに見えます。

tsort_eachはトポロジカルソートしてイテレータを返すメソッドで、各initializerの処理の順序依存を考慮したソートをしてくれます。

Ruby tsort_each

より詳細に実装を追ってみる

initializersに実際にどんな物が入っているのかを見てみたいですね。ちょっと簡単に見てみましょう。

railties/lib/rails/initializable.rbでrun_initializers内にデバッガーを埋め込んでRailsサーバーを起動してみましょう。環境依存などがないように新規でrails newで作成したアプリケーションを確認すると良いかもしれません。

デバッガーでinitializersの中身を見てみると

#<Rails::Initializable::Initializer:0x000000012dd84dd8
 @after=nil,
 @before=nil,
 @block=#<Proc:0x000000014a4d78f8 /Users/user/repos/rails/railties/lib/rails/application/bootstrap.rb:13>,
 @context=#<MytestApp::Application>,
 @group=:all,
 @name=:load_environment_hook>

のようなデータをたくさん持ったものであることがわかりました。これらすべてRails起動時の初期化処理対象です。
ちなみに、Rails::Initializable::Initializerを読み込むとtsort_each_childでtsortで並び替える基準の設定を行っているのもわかります。

件数もとても多いですね。

initializers.count
# => 344

で、この中の@nameを頼りに調べてみると、

:load_config_initializers(定義場所: railties/lib/rails/engine.rb)
:initialize_logger(定義場所: railties/lib/rails/application/bootstrap.rb)

が見つかりました。(load_config_initializersは複数見つかりますが、詳細をよく見ると@contextの中身が違っていたりします。こちらの説明は割愛。)

それぞれを詳しく見てみます。

:load_config_initializersはconfig/initializers配下の読み込み処理を行っていますね。

initializer :load_config_initializers do
    config.paths["config/initializers"].existent.sort.each do |initializer|
        load_config_initializer(initializer)
    end
end

引用元: rails/railties/lib/rails/engine.rb

:initialize_loggerの処理内容は既に設定したconfig.loggerがあればそちらを、なければloggerのデフォルト設定をRails.loggerに代入しているようです。

Rails.logger ||= config.logger || begin
  logger = if config.log_file_size
    ActiveSupport::Logger.new(config.default_log_file, 1, config.log_file_size)
  else
    ActiveSupport::Logger.new(config.default_log_file)
  end
  logger.formatter = config.log_formatter
  logger = ActiveSupport::TaggedLogging.new(logger)
  logger

引用元: rails/railties/lib/rails/application/bootstrap.rb

Rails.loggerに代入された設定がRailsアプリケーションに最終的に反映されるLogger設定となるため、固有のLogger設定を行いたい場合は:initialize_loggerが実行される前に設定する必要性がありそうです。

上記の初期化処理の読み込み順を見てみます。
run_initializers内の initializers.tsort_each で読み込み順の決定、周回を行っているため、各initializerのnameを出力する方法で確認してみます。

# 処理順にinitializerの名前を出力
initializers.tsort_each { |initializer| p initializer.name }
=> 
...
:initialize_logger
...
...
...
:load_config_initializers
...

はい、先に:initialize_loggerが読み込まれていますね。つまり、initializers配下に定義したLogger設定が反映されなかったのは、:load_config_initializersが:initialize_loggerより後に呼ばれるからだったというわけです。

他に気をつけるべき定義はないかな？

では、Logger以外にconfig/initializersに定義しても反映されないもの、気をつけるべきものはあるのでしょうか？その他のinitializerの読み込みを見てみると…

# 処理順にinitializerの名前を出力
initializers.tsort_each { |initializer| p initializer.name }
=> 
...
:initialize_cache,
...
"action_xxx.set_configs",
 ...
"action_xxx.set_configs",
...
...
...
:load_config_initializers
...

人によって気になるものはいろいろあるかと思いますが、CacheやActionXXXの設定(XXXにはMailerやControllerなどが入ります)はconfig/initializersが呼ばれる前に確定するようです。

基本的にこれらはconfig/environments配下で定義していることが多いと思うのでそこまで気にする必要はないかもしれませんが、もし、「設定定義をわかりやすくファイル分割したいんや！」と思った際には、initializerの読み込み順について思い出してみてください。

おわりに

Logger設定をconfig/initializersに移動しただけで設定が反映されなくなった！？という事例からinitializersの読み込みタイミングを実装コードで見るところまでご紹介しました。このあたりご存知でしたか？

Railsアプリケーションを新規開発時にはそこまで気にならないかもしれませんが、プロダクトが大きくなるとともにファイル分割したい、凝った設定を組み込みたいという要望が高まるので、もしかすると今回と同じような場面に遭遇することがあるかもしれません。

なんとなくconfig/initializersに入れておいたものはすべてRailsアプリケーション起動前に実行してくれる！と思いがち(私だけ？)ですが、決してそうではないことがわかりました。
なにかの設定を追加する際には今回の読み込み順を意識して設定するとよいでしょう。また、興味があれば、その他の設定についてもどのような順番で読み込まれているのかを確認しておくとおもしろいかもしれません。