rails開発環境で起きた"A copy of {module} has been removed from the module tree but is still active!" に挑む
4年前くらいに作成されたRailsのプロジェクトで,最近Vueを導入して一部をコンポーネント化した
すると,開発環境で特にVueを使ったページがうまく動かないことが多くなり,Vueからリクエストを受けたAPIが500ばかり返すようになった.
/users
にアクセスした時に,コンポーネントがAPIリクエストを再度サーバーに送るのだが(ここでは/api/foo/bar/tests
とする )これが動かない.
エラーを見ると
A copy of Foo::Bar has been removed from the module tree but is still active!
というようなメッセージが表示されていた.
不思議なのが,100%いつも500ではなかったことで,うまくAPIがJSONを返す時もあった.
あと,API部分だけをChromeの別タブで開いてリクエストすると問題なく200が返ってくることも不思議だった
ただ,総じてアプリケーションとして開発してて動かないことが多くて開発体験がすんごい悪い
さて,このエラーメッセージをググると,定数( Constant)の名前解決に失敗してるので当該 Constantに ::
をつけるというのがよく紹介されている
今回のケースで言うと
class ::Api::Foo::Bar::TestsController < ApplicationController
# ...
というようにしろということか?
いや流石にこれは.なんかあまりみない.(ちなみにやっても問題は解決しなかった)
そして不思議なのは,エラーになる定数が時には
A copy of Api::Foo::Bar has been removed from the module tree but is still active!
なのに,時には
A copy of Api::Foo has been removed from the module tree but is still active!
であり,いつも同じではないということであった.
というわけでRailsのソースコードを読んでいくことにする
まず,今回のメッセージが発生するのは ActiveSupport::DependenciesというModuleであった.
そこで,この部分に puts
で記述するログを仕込み,エラーメッセージもより詳細に書き換えて状況の把握に勤めることにする
$ vi /bundle/ruby/2.7.0/gems/activesupport-6.0.3.6/lib/active_support/dependencies.rb
def load_missing_constant(from_mod, const_name)
puts "#{Thread.current.object_id} ==============> #{from_mod} #{from_mod.object_id} | #{const_name} #{Inflector.constantize(from_mod.name).object_id}"
from_mod_name = real_mod_name(from_mod)
unless qualified_const_defined?(from_mod_name) && Inflector.constantize(from_mod_name).equal?(from_mod)
msg =<<-TEXT
A copy of #{from_mod} has been removed from the module tree but is still active!
qualified_const_defined? #{qualified_const_defined?(from_mod_name)}
Inflector.constantize.equal? #{Inflector.constantize(from_mod_name).equal?(from_mod)}
ObjectID #{from_mod.object_id} vs #{Inflector.constantize(from_mod_name).object_id}
TEXT
raise ArgumentError, msg
end
エラーが再現する部分を見ると,確かにobject_idが異なっていて unless文の中に入ってしまうことがわかった
...
web | 01:40:14 web.1 | 22120 ==============> ActionText::Engine 40980 | ApplicationController 40980
web | 01:40:14 web.1 | 22120 ==============> ActionText 41000 | ApplicationController 41000
web | 01:40:14 web.1 | 22120 ==============> Object 20740 | ApplicationController 20740
web | 01:40:14 web.1 | 22120 ==============> Object 20740 | Foo 20740
web | 01:40:18 web.1 | F, [2021-04-10T01:40:18.595169 #23] FATAL -- :
web | 01:40:18 web.1 | ArgumentError - A copy of Foo::Bar has been removed from the module tree but is still active!
web | 01:40:18 web.1 | qualified_const_defined? : true
web | 01:40:18 web.1 | Inflector.constantize equal? : false
web | 01:40:18 web.1 | Object ID: 753480 vs 753440:
web | 01:40:18 web.1 | F, [2021-04-10T01:40:18.595169 #23] FATAL -- :
web | 01:40:18 web.1 | ArgumentError - A copy of Foo::Bar has been removed from the module tree but is still active!
web | 01:40:18 web.1 | qualified_const_defined? : true
web | 01:40:18 web.1 | Inflector.constantize equal? : false
web | 01:40:18 web.1 | Object ID: 753440 vs 753420:
/users のページでVueコンポーネントが2本のAPIリクエストをしており /api/foo/bar/tests と /api/hoge へのリクエストが重複して走っていることで何かしら問題が起きているのではないかと考えられる
そこで,片方のAPIリクエストを走らないようにして再度ページを読み込むと,問題なくロードされた.
これは,APIエンドポイントを個別の別タブで開いたときに必ず問題なくレスポンスが返ってくる事象とも整合性がつく
つまり,問題は同時に2本のAPIリクエストがサーバーで受け取られるときにあるのではないかと考えられる
ということは,1つのリクエストが処理し終わる前にもう1本リクエストを受けていると発生するのではないかと気になったので,別タブで開いていた
http://localhost/api/foo/bar/tests
を5連打したところ,予想通りこの問題が発生した
さらに気になったのは,これはAPIリクエストだけで発生するのではなく,普通のHTMLを返すようなリクエストでも再現するのではないかと思い,
ERBでレンダーされるページ(http://localhost/samples
)を5連打してみたところ
確かにエラーは発生した...
が,発生箇所が異なっていた
Unable to autoload constant Foo::SamplesController, expected /app/controllers/foo/samples_controller.rb to define it
吐き出されるログをみていると,かならずDelayedJobっぽい挙動の直後に今回のエラーメッセージが発生しているなと思って,DJを止めてサーバースタートしたが,だめ,やはり発生した
また, jsonを返すコントローラーかHTMLを返すコントローラーかでエラーメッセージが差があるのか見るために
api/foo/bar/tests のレスポンスをJSONではなくrender '/users/new' にしてみたが,エラーメッセージに変化はなかった.つまり,今回のエラーは戻り値には無関係だった.
その後も色々試す.するとERBを返すURLである /foo/samples
も大量に(10連打くらい)リクエストすると
A copy of Foo has been removed from the module tree but is still active!
今回のエラーが出現することがわかった(ただし出現しないときもある).
コントローラーの名前空間におけるネストが少ないほど,今回のエラーは発生しづらいと感じた.
これを確かめることにした.
そこで, One::Two::Three::Four::Five::TestsController
というものを作り,URLを連打すると,容易に同じ問題が再現した
一方で One::TestsController
というものを作り,URLを連打すると,今回のエラーは生じにくかった
階層が浅い場合はエラーが生じにくいと言う仮説は正しそうであった
さて,今回のエラーはもし本当に一般的に再現するならかなり不便だろうと思い,社内の別のRailsプロダクトでも再現するのかを試すことにした.
なんとなくネストが深いコントローラーで生じやすいことがわかったので,別プロジェクトのほうでも One::Two::Three::Four::Five::TestsController
というものを作り,URLを連打すると,,,全くエラーが再現されなかった
もっというと,そもそも別プロジェクトの方ではputsログを仕込んだのにURL連打しても全然ログが出てこない,つまりそもそも ActiveSupport::Dependencies # load_missing_const
メソッドに処理が流れていないということがわかった
どうやら表題のエラーはプロジェクトに固有の問題であることがわかってきたので,別プロジェクトと問題が起きているプロジェクトで,アプリケーションとして差がある部分に着目した
するといくつか差がある部分がわかった
項目 | 問題になっているプロジェクト | 別プロジェクト |
---|---|---|
非同期処理 | DelayedJob | Sidekiq |
application server | unicorn | puma |
rails version | 6.0 | 6.0 |
この差が原因かもしれないと思い,問題になっているプロジェクトについて
- delayedJobを起動しないでサーバーだけで動かす
- アプリケーションサーバーをpumaに変更(早く変えろよと言う話はさておき)
を試したのだが,なんとまったく解決しなかった
ミドルウェアに問題があるわけでもなく,Railsのバージョンも同じなのだから configurationが違うのかもと思い,両者の
- config/application.rb
- config/environment/development.rb
の差分をみていくと,気になる部分があった
エラーが起きるプロジェクトのほうでは
# config/environment/development.rb
# ...
# In the development environment your application's code is reloaded on
# every request. This slows down response time but is perfect for development
# since you don't have to restart the web server when you make code changes.
config.reload_classes_only_on_change = false
という1文があった.別プロジェクトのほうではこれはなかった.
Git blameをみると追加されたのは2年前(場所の修正).元をたどると3年前に追加されたものだった
気になってRailsのソースコードを検索する
config.reload_classes_only_on_change = false
だとここが走ることになるとわかった
そしてこの callbackは あの ActiveSupport::Dependencies.clear を含んでいる
たぶんこれによってConstantsが毎度全消しされて,リクエストの都度全ての定数を定義し直し,リクエストが2本飛んできている時などにエラーを起こしたのではないだろうか
その他参考ファイル
そう.今回の元々の原因はObjectクラスなど諸々のクラスにぶら下がるConstantsが削除されていることが諸悪の根源である,削除されてしまってるからリクエストの都度コントローラー名の名前解決が必要で(One::Two::Three::Four::Five::TestsController
)について先頭から潤に新規で定数とクラス解析を走り直すことがよくない.
2本のリクエストをほぼ同時にうけとることで,定数を2個並走してつくってしまい.object_idに乖離が生じるのがエラーの原因である
development.rbのあの1行を削除すれば良いのではないかと思ったが,本当にそれでいいのか確かめるためにまずは /bundle/ruby/2.7.0/gems/railties-6.0.3.6/lib/rails/application/finisher.rb
に以下のようなロガーを仕込んでみた.
# /bundle/ruby/2.7.0/gems/railties-6.0.3.6/lib/rails/application/finisher.rb
initializer :set_clear_dependencies_hook, group: :all do |app|
callback = lambda do
ActiveSupport::DescendantsTracker.clear
puts "======= CAUSION constants will be removed ======="
ActiveSupport::Dependencies.clear
end
なお, ActiveSupport::Dependencies.clear
というのがconstantsを一斉削除するメソッドである
config.reload_classes_only_on_change = false
だとリクエストごとに上記で仕込んだログが出てきた.
なるほどたしかにこれが原因で都度定数が初期化され,再度必要な定数を作り直す必要が出て,2本リクエスト同時にもらっているとそこでObjectIdが異なる2つの定数ができるのが問題になったと思われる
よし,ではこれをtrue にすれば問題ないのでは.
trueにしてみてサーバーを起動してみると...
今回の問題が現れなくなった
よかった...
今回のバグの原因究明で大変だったのは,
- 100%の再現性が担保できなかったこと
- ググって検索したときの頻出解決策では解消できなかったこと
- エラーのバックトレースでは根源の原因がわからなかったこと(それとは別の処理が原因で生じたバグだったため)
- Railsのけっこう根本の処理で生じるバグだったので,ロガーを仕込んでも大量のノイズログが出力されたこと
などであった
3年前になぜ
config.reload_classes_only_on_change = false
がconfiguration に追加されたのかは当時のPRをみてもわからなかった.
ただ,当時はSPA化など想定しておらず,まさかあとになってこのような問題を引き起こすとは想定できなかっただろう
これで解決していることを祈る
ちなみに,Railsのソースコードいじるのはきちんと気をつけてやらないとですね
とくにコンテナ使って開発してない場合は,変更した部分を元に戻すの忘れるととても危ないのでお気をつけて.