Railsで何をやっても Routing Error uninitialized constant ~と言われて泣きそうになった時

昨日まで、午前中まで、ちょっとさっきまで、正常に動いていた Ruby On Rails のアプリが、急に何をやっても「Routing Error : Uninitialized constant XXXXX Controller」というエラーになってしまい、うんともすんとも言わなくなってしまうという謎の症状に陥り、原因究明まで1ヶ月ほど泣きそうになっていたというしびれる経験をしたので、ここに解決までのTIPS(もとい、奮闘記?)を書いておこうかと。

犯人捜索編

まずはもうトラウマに近くなったこのRailsのエラー画面…。

Routing Error

まず、このエラーに陥ると、Railsくんは直接URLを指定して呼び出されるコントローラーを切り替えても、いやもうそれ以外何をしても、ただひたすら同じ「Routing Error」でコントローラ名だけ違うというエラーを吐き続けます。もうそれしかエラーメッセージ知らないかのようにそれしか言わなくなってしまうんです。でも、Railsのルート設定ファイルである config/routes.rb は正常なのです(だってさっきまで動いてたし、ルーティング変えてないんだから当然ですよ)。Railsのログ見てもエラー画面と同じ程度の情報しか出ないし、サーバ側のエラーログ見ても毎回 404エラー で、そのルート(URL)にはコンテンツがない(Railsのcontrollerが動いてない)よ──としか書いてない。エラーログの処理スタックを遡って行っても特におかしいところがない… いったいこりゃなんだ!? もう心は折れました、だいぶベキベキと折れて、Rails嫌いになりました、でも捨てられません、お仕事なので、原因究明させないと前に進めないんです(T_T)

StackOverflowとかサポートフォーラムを検索すると、同じ症状に陥っている人の質問がいくつかあるんですよねぇ…でも、回答が書いてない。 まじかよ~誰も解決してないのかよ~!? 誰か助けてくれ~…という状態。

そしてこの症状のさらに謎なところが、Rails環境を再構築(ゼロからすべてインストールし直す)と解消するのです(というか、その当時はそれでしか復旧する術がなかったのですがね)。そのため、最初はサーバ側(ApacheやRailsを中継していたPassengerとか)の設定とかキャッシュとかが問題なのかとか色々調べたんですが、すべて的外れでした(バグフィックスの時に「ここじゃね?」という勘が外れると凹むんだよねぇ…自分も老いたな──とか思ってしまう)。

さて、何度目かのRails再ビルドで、RubyのバージョンとRailsのバージョンを変えてみました。最初はRuby1.9.3+Rails4.1.0だったのを、Ruby2.0.0+Rails4.2.0にしてみました。バージョンってのには何気に相性がかなりあるので、その辺から攻めてみた次第。リビルド直後は問題なし、でも次の日のお昼にまた同じ症状が発生してしまった。 RailsのSQLiteデータベースが壊れているのかもと、リビルド直後にバックアップしていたDBに切り戻してみても駄目だ。もう一度DB初期化してデータを入れ直してみる。…ん? seeds.rb が通らない(Railsではデータベースに初期データを登録する時は db/seeds.rb を使って rake db:seed コマンドを実行するのだが、これがエラーになるのだ )。これは Rake のバイナリが壊れているのか?

──いやぁ、このあたりが一番泣きそうな感じでしたねぇ…もう徒労感と絶望感しかない感じ。閃きも出ないしね。

そんなこんなで、一ヶ月近く同じ調査を続けてたのですが、そこにようやく光明が差し込んだ次第。いやぁ、苔の一念…ってヤツですかね~。なんと、こんなサイトを発見!

Rubyが突然動かなくなった “/usr/bin/ruby: No such file or directory”

prelink とな? CentOS環境では、必須でインストールされており cron.daily (一日一回動くcronジョブ) で勝手に実行されちゃう。弊害としてRubyのバイナリファイルを壊してしまう場合がある──とのこと。かなり怪しい。今度は prelink+ruby で検索してみるとようやっと出てきました…金脈にたどり着いた感じだ。

怪しすぎるぞ prelink 。

cron.daily が実行されるのは毎朝3:00~4:00間にランダムとのこと。そういえばRails環境のタイムゾーンはUTCだから、+9:00すると日本だとお昼の12:00~13:00の間に prelink が動いてしまうわけだ。今まで不具合が発生したのもお昼の時間だったなぁ…ということは…

prelink、おまえなのかぁ~?

そんなわけで、実際に検証をしてみた。再構築したRails環境下で SQLiteデータベースへの書き込み処理が行われている最中 (けっこうこのタイミングが重要なんです。本筋アプリケーションがバイナリへ変更処理かけている時に prelink が重ならないと症状が発生しない場合がありました)に prelink を手動実行してみたところ…

Routing Error

やはり、犯人はおまえだったか、prelink !

めでたく「Routing Error」となった! いや、Railsアプリ壊れちゃってめでたくないんだが、私を含めた関係者的にはすごくめでたい♪

で、 prelink 実行前にRailsの checksum をとっていたので、実行後の checksum と比較してみると、おっと Gemfile.lockdb/development.sqlite3 のバイナリが壊れているようだ。どおりでSQLiteデータベースのファイルだけ差し戻しても復旧できないわけだ。

特に、 Gemfile.lock が壊されてしまうと、Gemの依存関係やバージョン、取得先(ファイルパス)を集約管理しているバイナリだけに、Railsがどんな挙動をするかわからない。今回は一律で「Routing Error」になっていたが、環境によってはまた別のエラーしか言わなくなるRailsくんが出来上がってしまうかもしれない。

さーて、ここまでが原因究明までの奮闘記。ここからは不具合修正のTIPSになります。

まず、 prelink とは何ぞや?──確かに、今のところ容疑者格だが、別にそこまで悪いことをするヤツではないのかもしれない。調べてみると、 prelink はアプリケーションのパフォーマンスを最適化するためにバイナリファイル実行前にそのバイナリが生成する動的リンク処理などを事前に解析してバイナリ本体に埋め込んでおくというミドルウェアだ。うーん、パフォーマンス向上用とはいえ、バイナリ勝手に書き換えちゃうのはイカンだろう。 「たまに書き換え失敗してバイナリ壊しちゃうこともあるんですけどね、テヘペロ♥ 」 とか、 ありえん! ──なんか調べると、百害あって一利なしアプリっぽいのだ。なぜCentOSはこんな爆弾をデフォルトでインストールするんだろう?

あぁ、CentOSもやっと気づいたのね。彼の危険さに(笑)

ま、そんなわけでこんな危険なヤツにはさっさとご退場願いたい。 では、 prelink の無効化の仕方だ。以下のようにいくつかある。

  1. cron.daily から prelink をはずす
  2. /etc/prelink.conf にバイナリ書き換えを行って欲しくないファイルやパスをブラックリストとして指定する
  3. /etc/sysconfig/prelink で PRELINKING=no にする

まず1番だが、 cron.daily には他のミドルウェアの設定も入っているのであまりいじりたくない(万一他に影響が出たらイヤなので)。 次に、2番だが、 prelink 自体がブラックリスト一直線なくせに正常に動いているアプリたちを「ブラックリスト」呼ばわりするのは名誉毀損で気分が悪い。…なので、これは却下だ(笑) 最後の設定が一番しっくりくる。CentOS7でもこの方法で無効化しているし、再度変更したい時にはyesに戻すだけなので(まぁ、そんな時はもう来ないんだが…)。

というわけで、 prelink は3番の方法で無効化しよう。 OFFにした後は、念のためにサーバを再起動しておくと、枕を高くして眠れる。

まとめ

最後まで読んでいただいた方、長文・雑文におつきあいいただきありがとうございました。長いこの記事の要旨を一言でまとめると下記のようになります。

ただ、Railsを使っていない環境でも、基本的にCentOS環境では prelink は無効化していた方が無難です。