Bug #4958: Internal server error (PhusionPassenger::Rack::ApplicationSpawner::Error)

• Status: Closed
• Assignee: iura (Masahiro Iura)
• Target version: 1.9.3
• ruby -v: -

[iura (Masahiro Iura)]

障害内容：
PhusionPassenger 経由で Ruby on Rails のコンテンツを接続しているのですが、
数日前から Web ブラウザからアクセスすると「Internal server error 」が表示され、
所定のページが表示されない。
ruby 1.9 はほぼ毎日更新しています。

アクセス後にログファイルを確認すると以下の内容が表示されます。
何度やっても同じメッセージが出ます。
お手数ですがよろしくお願いします。

/var/log/httpd/error_log:

[ASYNC BUG] thread_timer: select
EBADF

ruby 1.9.3dev (2011-07-01 trunk 32348) [x86_64-linux]

[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

動作環境：
OS: Scientific Linux 6.0
Linux ns.inc.gr.jp 2.6.32-131.2.1.el6.x86_64 #1 SMP Thu Jun 2 09:49:26 CDT 2011 x86_64 x86_64 x86_64 GNU/Linux
Apache/2.2.15 (Unix) DAV/2 Phusion_Passenger/3.0.7 mod_auth_kerb/5.4 PHP/5.3.2 mod_ssl/2.2.15 OpenSSL/1.0.0-fips
mod_wsgi/3.2 Python/2.6.6 mod_perl/2.0.4 Perl/v5.10.1 configured -- resuming normal operations

[kosaki (Motohiro KOSAKI)]

straceなどの情報を採取することは可能でしょうか？

[ko1 (Koichi Sasada)]

• ruby -v changed from 1.9.3dev (2011-07-01 trunk 32348) [x86_64-linux] to -

　ささだです．

(2011/07/01 14:29), Masahiro Iura wrote:

障害内容：
PhusionPassenger 経由で Ruby on Rails のコンテンツを接続しているのですが、
数日前から Web ブラウザからアクセスすると「Internal server error 」が表示され、
所定のページが表示されない。
ruby 1.9 はほぼ毎日更新しています。

アクセス後にログファイルを確認すると以下の内容が表示されます。
何度やっても同じメッセージが出ます。
お手数ですがよろしくお願いします。

　はじめて Passenger なるものを触ってみました．他のソフトのソースを見た
のも久しぶりな気がします．

　調べてみて，理由がわかりました．結論から言うと，Passenger が酷いこと
（？）をしているので，このエラーが出た，というものです．

(1) Ruby 側の事情

　先日，タイマスレッドの構造を変更しまして，signal handler <-> timer
thread <-> Ruby thread の間の通信を pipe を用いることにしました．プロセ
ス起動時に pipe を開き，そいつでこれらの間を同期的に通信します．fork 後
も，同様に新しい pipe を開きます．

(2) Passenger の事情

　Passenger は，リクエストが来たら ruby を fork して，子プロセスで処理を
させます（多分）．ただ，子プロセスが無駄に file descriptor を開いてし
まって，変なリークを起こさないために，fork で子プロセスが生成された後，
リクエスト処理を行う前の準備処理の時点で，stdin/out や，Passenger が親子
の通信で利用する fd 以外を，問答無用で close してくれます．無駄なfd 資源
がリークしなくなるのでやったね！

問題の箇所：
passenger-3.0.5/lib/phusion_passenger/abstract_server.rb より引用

During Passenger's early days, we used to close file descriptors based

on a white list of file descriptors. That proved to be way too fragile:

too many file descriptors are being left open even though they shouldn't

be. So now we close file descriptors based on a black list.

Note that STDIN, STDOUT and STDERR may be temporarily set to

different file descriptors than 0, 1 and 2, e.g. in unit tests.

We don't want to close these either.

file_descriptors_to_leave_open = [0, 1, 2,
b.fileno, server_socket.fileno,
fileno_of(STDIN), fileno_of(STDOUT), fileno_of(STDERR)
].compact.uniq
NativeSupport.close_all_file_descriptors(file_descriptors_to_leave_open)

(3) 今回の原因

　というわけで，(1) でせっかく作った pipe を，(2) の処理として閉じられて
しまったので，今回の [BUG] に至ったわけです．

　この
NativeSupport.close_all_file_descriptors(file_descriptors_to_leave_open)
をコメントアウトすると，元気に動くことを確認しました．

　いやはや，なんというか．こういうのって普通？

　思わぬ互換性の問題にあたったんですが，さてどうするべきでしょうか．閉じ
て欲しくない fd を返すような API を，一つ作りますかねえ？

--
// SASADA Koichi at atdot dot net

[ko1 (Koichi Sasada)]

　ささだです．

(2011/07/01 14:29), Masahiro Iura wrote:

障害内容：
PhusionPassenger 経由で Ruby on Rails のコンテンツを接続しているのですが、
数日前から Web ブラウザからアクセスすると「Internal server error 」が表示され、
所定のページが表示されない。
ruby 1.9 はほぼ毎日更新しています。

アクセス後にログファイルを確認すると以下の内容が表示されます。
何度やっても同じメッセージが出ます。
お手数ですがよろしくお願いします。

　はじめて Passenger なるものを触ってみました．他のソフトのソースを見た
のも久しぶりな気がします．

　調べてみて，理由がわかりました．結論から言うと，Passenger が酷いこと
（？）をしているので，このエラーが出た，というものです．

(1) Ruby 側の事情

　先日，タイマスレッドの構造を変更しまして，signal handler <-> timer
thread <-> Ruby thread の間の通信を pipe を用いることにしました．プロセ
ス起動時に pipe を開き，そいつでこれらの間を同期的に通信します．fork 後
も，同様に新しい pipe を開きます．

(2) Passenger の事情

　Passenger は，リクエストが来たら ruby を fork して，子プロセスで処理を
させます（多分）．ただ，子プロセスが無駄に file descriptor を開いてし
まって，変なリークを起こさないために，fork で子プロセスが生成された後，
リクエスト処理を行う前の準備処理の時点で，stdin/out や，Passenger が親子
の通信で利用する fd 以外を，問答無用で close してくれます．無駄なfd 資源
がリークしなくなるのでやったね！

問題の箇所：
passenger-3.0.5/lib/phusion_passenger/abstract_server.rb より引用

During Passenger's early days, we used to close file descriptors based

on a white list of file descriptors. That proved to be way too fragile:

too many file descriptors are being left open even though they shouldn't

be. So now we close file descriptors based on a black list.

Note that STDIN, STDOUT and STDERR may be temporarily set to

different file descriptors than 0, 1 and 2, e.g. in unit tests.

We don't want to close these either.

file_descriptors_to_leave_open = [0, 1, 2,
b.fileno, server_socket.fileno,
fileno_of(STDIN), fileno_of(STDOUT), fileno_of(STDERR)
].compact.uniq
NativeSupport.close_all_file_descriptors(file_descriptors_to_leave_open)

(3) 今回の原因

　というわけで，(1) でせっかく作った pipe を，(2) の処理として閉じられて
しまったので，今回の [BUG] に至ったわけです．

　この
NativeSupport.close_all_file_descriptors(file_descriptors_to_leave_open)
をコメントアウトすると，元気に動くことを確認しました．

　いやはや，なんというか．こういうのって普通？

　思わぬ互換性の問題にあたったんですが，さてどうするべきでしょうか．閉じ
て欲しくない fd を返すような API を，一つ作りますかねえ？

--
// SASADA Koichi at atdot dot net

[kosaki (Motohiro KOSAKI)]

• Status changed from Open to Closed

Ko1 made new API. Thus I'll close the ticket.

see [ruby-core:37727], [ruby-core:37759] and r32394.