tachibanakikaku.com: Railsアプリがアボートした話 + α

よくあるApache2 + Phusion Passengerの構成で
Railsアプリケーションを動かそうとしたらクラッシュしたので
調査して対応したという話。

# Internal Server Error 500

アクセスしてアプリを触ってたらみんな大好き500エラーが出てた。
なのでApacheのエラーログを見ることに。

# とりあえずログ (抜粋)

[NOTE]
You may have encountered a bug in the Ruby interpreter or extension libraries.
Bug reports are welcome.
For details: http://www.ruby-lang.org/bugreport.html
[ pid=2662 thr=139689980598240 file=ext/apache2/Hooks.cpp:841 time=2013-04-02 14:45:09.779 ]: The backend application (process 6194) did not send a valid HTTP response; instead, it sent nothing at all. It is possible that it has crashed; please check whether there are crashing bugs in this application.
/usr/local/rvm/gems/ruby-1.9.3-p362/gems/activerecord-3.2.11/lib/active_record/relation.rb:241: [BUG] Segmentation fault
ruby 1.9.3p362 (2012-12-25 revision 38607) [x86_64-linux]
-- Control frame information -----------------------------------------------
c:0101 p:0016 s:0578 b:0575 l:000574 d:000574 METHOD /usr/local/rvm/gems/ruby-1.9.3-p362/gems/activerecord-3.2.11/lib/active_record/relation.rb:241
c:0100 p:0026 s:0572 b:0572 l:000571 d:000571 METHOD /usr/local/rvm/gems/ruby-1.9.3-p362/gems/activerecord-3.2.11/lib/active_record/scoping/default.rb:41
c:0099 p:0022 s:0569 b:0569 l:001278 d:000568 LAMBDA /usr/local/rvm/gems/ruby-1.9.3-p362/gems/activerecord-3.2.11/lib/active_record/scoping/named.rb:180
(中略)
7fa5207ac000-7fa5207ad000 r--p 0001f000 ca:01 4240 /lib64/ld-2.12.so
7fa5207ad000-7fa5207ae000 rw-p 00020000 ca:01 4240 /lib64/ld-2.12.so
7fa5207ae000-7fa5207af000 rw-p 00000000 00:00 0
7fff2e37c000-7fff2e39d000 rw-p 00000000 00:00 0 [stack]
7fff2e3ff000-7fff2e400000 r-xp 00000000 00:00 0 [vdso]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0 [vsyscall]
(中略)
[NOTE]
You may have encountered a bug in the Ruby interpreter or extension libraries.
Bug reports are welcome.
For details: http://www.ruby-lang.org/bugreport.html
[ pid=2665 thr=139689980598240 file=ext/apache2/Hooks.cpp:841 time=2013-04-02 14:52:29.683 ]: The backend application (process 6329) did not send a valid HTTP response; instead, it sent nothing at all. It is possible that it has crashed; please check whether there are crashing bugs in this application.

did not send a valid HTTP responseは多分問題無いということが

他のソースから分かっていたのでこの時点でRuby周りかなという感じだった。

ひとまず、すぐに確認できそうなことから可能性を潰すことにした。

# 再現および状況把握

それ以降も何度も発生したのでサーバリソース周りを見ておくことにした。
sysstat入れて久しぶりにsarコマンド使ってCPU/Memory/IOの様子を確認。

=>異常無し

# 可能性の検討 + 行動

Rubyインタプリタのバグ踏んだ (ログの通り。人間素直が一番)
Passenger, Rails等いずれかのライブラリのバグ (ログからは一度Passengerの可能性も考えた)
ApacheやPassengerがsarで汲み取れない一瞬で何らかの閾値を振り切った (スカウターで確認できない程の一瞬で戦闘力を上げて攻撃されたイメージ)

可能性として1, 2, 3の順に高いと考え、
StackOverflowやら何やらで情報を探すと以下のものに突き当たった。

https://github.com/gitlabhq/gitlabhq/issues/2436
https://github.com/gitlabhq/gitlabhq/issues/2476

結論としては偶々サーバに入ってたバージョンのRubyが

buggyだったのでアップデートしろということだった。

これ以外にもStackOverflowでログがほぼ同じ投稿があったけど

解決方法がログやテンポラリスペースが云々とあったので無関係と判断。

その後、
Rubyのバージョンを1.9.3p362からp392に上げて、
Apacheのconfigを書き換えた。

$ sudo rvm get stable
$ rvm reload
$ rvm list known
$ sudo rvm autolibs enable
$ sudo rvm upgrade 1.9.3-p362
$ rvmsudo passenger-install-apache2-module

LoadModule passenger_module /usr/local/rvm/gems/ruby-1.9.3-p392/gems/passenger-3.0.19/ext/apache2/mod_passenger.so
PassengerRoot /usr/local/rvm/gems/ruby-1.9.3-p392/gems/passenger-3.0.19
PassengerRuby /usr/local/rvm/wrappers/ruby-1.9.3-p392/ruby

=>クラッシュしなくなった。

# 自分への教訓

メインで使ってるソフトウェアのバグやセキュリティフィックスくらいは
恒常的に意識的に追いかけましょう。

# + α

4/1から新しい会社で働いています。

tachibanakikaku.com

2013年4月5日金曜日

Railsアプリがアボートした話 + α