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

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を投げつけているのか？
* [公式のガイド](https://www.phusionpassenger.com/documentation/Users%20guide%20Apache.html)にはそんな方法の記述は無い
* [githubのコード](https://github.com/phusion/passenger/blob/release-4.0.41/lib/phusion_passenger/request_handler.rb#L47)を眺めていると以下のような部分が見つかる

```rb
SOFT_TERMINATION_SIGNAL = "SIGUSR1"
```

* SIGUSR1を投げつければ出来る **かも** という記事もある
 * [Passengerでプロセスを個別にkillする](http://qiita.com/mechamogera/items/ad5fd7d15afcb1ded6c1)

### 自分でも実験してみる
* railsのコードは[先程の記事](http://qiita.com/mechamogera/items/ad5fd7d15afcb1ded6c1)と大体同じ。config/routes.rbに以下のようなのを書いておく

```rb
get "test", to: "application/test"
```
* passengerの設定をapacheに追加

```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を何度も叩き付ける

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

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

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

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

```bash
tailf /var/log/httpd/access_log | grep 500
```
* 連続的なアクセス

```bash
/usr/bin/ab -c 1 -n 10000 http://localhost:3000/test/
```
* 10000件のリクエストが終わる前に、該当プロセスに対してSIGUSR1を投げつける

## 結果
再現

```text
127.0.0.1 - - [09/Jun/2014:17:14:59 +0900] "GET /test HTTP/1.0" 500 614 "-" "ApacheBench/2.3"
```
* SIGUSR1一回に対して、1度だけ発生する
* 必ず発生するわけではないが、高確率で発生するので、関連があると言って良さそう
* 以下の様に設定を変更しても500は発生した

```apache
PassengerMaxPoolSize 2
PassengerMinInstances 1
```

# 実験：reloadやgracefulだとどうなるの？
* ログローテーションの際にreloadを叩く設定となっているようだったので
 * /etc/logrotate.d/httpd

```text
    postrotate
        /sbin/service httpd reload > /dev/null 2>/dev/null || true
    endscript
```
* 連続的なアクセスは上記のabと同じコマンドで
* PassengerMaxPoolSizeは１、２の両方で実験
 * どちらも実験結果に影響は出ていなかった
* またabの-cオプションを5にして同様にしてみたが、実験結果に影響は出ていなかった

## reload

```bash
$ sudo /sbin/service httpd reload
Reloading httpd: 
```
* access_logに500は出ないが、abが切られる

```text
Completed 1000 requests
apr_socket_recv: Connection reset by peer (104)
Total of 1397 requests completed
```
* ログに残らないので、実は把握出来ていないだけで、運用しているサーバーでもログローテーション時に、同様にバスっと切られているリクエスト達が居るのかもしれない・・・。

## graceful

```bash
$ sudo apachectl -k graceful
```

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

```text
::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で運用までした事はないので、悩み中。

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