Passengerが時折500エラーを残しているけど、原因不明だったので、少し実験してみた。

500エラーのログ

apacheのaccess_logには500を返したログがある
apacheのerror_logには以下

[error] [client 127.0.0.1] Premature end of script headers:

railsのアプリログには何も出ていない

前提

Passenger 4.0.41　(多分バージョンは大して関係がない気がする）
Apache 2.2.15　(多分バージョンは関係ない気がする)
Rails 3.2.18　(多分バージョンは関係ないry)
CentOS 6.4　（多分バージョンはry）
定期的にPassenger RackAppのメモリ使用量に応じて、 プロセス毎に 再起動させている　（ここが重要）

バージョンが古いのは手元のVMに入れていた環境をそのまま使ったので（笑
なお、本投稿の実験はリクエスト元もリクエスト先も同じマシン内です。

Passengerの再起動方法

passenger-memory-statsの結果からPassenger RackAppを引っ掛けて、メモリ使用量が大きくなっているプロセスにSIGUSR1を投げつける

なぜSIGUSR1を投げつけているのか？

公式のガイドにはそんな方法の記述は無い
githubのコードを眺めていると以下のような部分が見つかる

SOFT_TERMINATION_SIGNAL = "SIGUSR1"

SIGUSR1を投げつければ出来るかもという記事もある
- Passengerでプロセスを個別にkillする

自分でも実験してみる

railsのコードは先程の記事と大体同じ。config/routes.rbに以下のようなのを書いておく

get "test", to: "application/test"

passengerの設定をapacheに追加

LoadModule passenger_module /home/user/.rvm/gems/ruby-1.9.3-p392@test/gems/passenger-4.0.41/buildout/apache2/mod_passenger.so
PassengerRoot /home/user/.rvm/gems/ruby-1.9.3-p392@test/gems/passenger-4.0.41
PassengerDefaultRuby /home/user/.rvm/wrappers/ruby-1.9.3-p392@test/ruby

PassengerMaxPoolSize 1
PassengerMinInstances 1

LISTEN 3000
<VirtualHost *:3000>
  DocumentRoot /var/testApp/public    
  RailsEnv development
  <Directory /var/testApp/public>
     Options FollowSymLinks
     AllowOverride None
  </Directory>
</VirtualHost>

あとは以下のようなコマンドを叩いて、レスポンスが返ってくる前に、該当プロセスにSIGUSR1を何度も叩き付ける

wget --spider http://localhost:3000/test/

処理が途切れる事なく、確かに200が返ってくる
- 問題無さそう

この実験では、ウマい具合に処理されていて、問題もなさそうなのに、現実として500が返ってきている。なぜ？
⇒もしかして、連続的にアクセス着ているのが辛い？

実験：連続してアクセスが来ている状況でSIGUSR1を投げる

連続的にアクセスが来ている状況で、SIGUSR1を投げつけてみる
* ログを眺める

tailf /var/log/httpd/access_log | grep 500

連続的なアクセス

/usr/bin/ab -c 1 -n 10000 http://localhost:3000/test/

10000件のリクエストが終わる前に、該当プロセスに対してSIGUSR1を投げつける

結果

再現

127.0.0.1 - - [09/Jun/2014:17:14:59 +0900] "GET /test HTTP/1.0" 500 614 "-" "ApacheBench/2.3"

SIGUSR1一回に対して、1度だけ発生する
必ず発生するわけではないが、高確率で発生するので、関連があると言って良さそう
以下の様に設定を変更しても500は発生した

PassengerMaxPoolSize 2
PassengerMinInstances 1

実験：reloadやgracefulだとどうなるの？

ログローテーションの際にreloadを叩く設定となっているようだったので
- /etc/logrotate.d/httpd

    postrotate
        /sbin/service httpd reload > /dev/null 2>/dev/null || true
    endscript

連続的なアクセスは上記のabと同じコマンドで
PassengerMaxPoolSizeは１、２の両方で実験
- どちらも実験結果に影響は出ていなかった
またabの-cオプションを5にして同様にしてみたが、実験結果に影響は出ていなかった

reload

$ sudo /sbin/service httpd reload
Reloading httpd:

access_logに500は出ないが、abが切られる

Completed 1000 requests
apr_socket_recv: Connection reset by peer (104)
Total of 1397 requests completed

ログに残らないので、実は把握出来ていないだけで、運用しているサーバーでもログローテーション時に、同様にバスっと切られているリクエスト達が居るのかもしれない・・・。

graceful

$ sudo apachectl -k graceful

叩くたびに以下のようなログがaccess_logに残っているが、500を出したというログは出ない

::1 - - [09/Jun/2014:19:38:30 +0900] "OPTIONS * HTTP/1.0" 200 - "-" "Apache/2.2.15 (CentOS) (internal dummy connection)"

再起動なので、しばらくaccess_logは停まるが、その後、普通に流れ出している様子

まとめ

結局、原因はよくわからないが、SIGUSR1によるPassengerプロセス単体再起動は500エラーを産む要因にはなっているらしい
- アクセスが多い状況では辞めておいた方が無難
再起動を行うなら、sudo apachectl -k gracefulが良さそう
- その間、そのサーバーにはPassengerプロセスが居ない事になると思うので、困る環境の場合は、さらに別手段かな〜？
logrotate時も、reloadではなく、gracefulとかの方が良さそう
- 場合によっては、そもそもロテートしないという選択肢もアリかな？
- まだgracefulで運用までした事はないので、悩み中。

以上、実験報告でした！！

Passengerを再起動させると500エラー