Ennoumuが無応答になる

[sibapy]

いつもお世話になっております。 NougakuDo 1.3.5の環境で、RailsアプリをEnnoumuで実行していると、レスポンスが返ってこなくなることがあります（Win2008 R2、SQLServer2012Express使用）。 管理者コマンドプロンプトで、rackup -s Ennoumu -p 80 で実行しています。 まれに、コマンドプロンプトでEnterを叩くと動き出すことがあります。 ２プロセスで使用していますが、やがて、新たなリクエストも受け付けられなくなり、Ctrl-Cを押しても Ennou(1.1.6) stop service for http://+:80/da pid=xxx を表示するものの終了しません（しばらく放置するとTerminate batch job (Y/N)?が表示されます）。

ennoumu.rb に rescue を（rescue Interruptの下に）追加し backtrace を取得してみたところ、以下を延々と出力しているようです。

#<SystemCallError: unknown error - wait HttpReceiveHttpRequest (6)>
C:/**/NOUGAK~1/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:55:in `wait'
C:/**/NOUGAK~1/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:55:in `block (2 levels) in run'
C:/**/NOUGAK~1/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:53:in `loop'
C:/**/NOUGAK~1/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:53:in `block in run'
C:/**/NOUGAK~1/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:28:in `open'
C:/**/NOUGAK~1/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:28:in `run'
C:/**/NOUGAK~1/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/server.rb:265:in `start'
C:/**/NOUGAK~1/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/server.rb:137:in `start'
C:/**/NOUGAK~1/lib/ruby/gems/1.9.1/gems/rack-1.4.1/bin/rackup:4:in `<top (required)>'
C:/**/NOUGAK~1/bin/rackup:23:in `load'
C:/**/NOUGAK~1/bin/rackup:23:in `<main>'

なにが原因かわかりますでしょうか？ お手数ですがよろしくお願いいたします。

[arton]

どうも、ご迷惑をおかけしているようで、申し訳ありません。 バックトレースを見ると、HTTPキューがクローズされているため、例外を投げているようです。 ということは、^Cを押した後ということでしょうか。 で、本来ならそのままloopを抜けて子プロセスは終了するはずですが、「延々と出力」ということは、runメソッドから例外で抜けても、rack-1.4.1のstartメソッドはリトライをしているということのように見えます。 手元のrack-1.3.2ではそういうことはないので、1.4.1を確認してみます。

[sibapy]

いつも素早い対応ありがとうございます。 すいません。延々と出力、、、は、私の修正が悪いためです。 以下のようにしていたため、プロセスを終了せずにループしてしまいました。 本来（オリジナルのソース）なら子プロセスは終了します。

ただ、応答がなくなるのは Ctrl-Cを押したからではなく、いつの間にかリクエストが受け付けられなくなっています。 きっかけがわからないので？？？というところです。 こちらも rack-1.3.2 で試してみたいと思います。

            server.script =  @script
            @logger.info "script=#{server.script}, #{@script}"
            @logger.info "Ennou(#{::Ennou::VERSION}) start for http://#{@host}:#{@port}#{@script} pid=#{$$}"
            loop do
              begin
                r = server.wait(60)
                next if r.nil?
                run_thread(app, *r)
              rescue Interrupt
                break
              rescue => e
                p e
                p e.backtrace.join("\n")
              end
            end
            @logger.info "Ennou(#{::Ennou::VERSION}) stop service for http://#{@host}:#{@port}#{@script} pid=#{$$}"

[arton]

情報ありがとうございます。おそらくrackの問題ではなくennouに何か考慮不足があるのだと思います。 いずれにしても、レスポンスが返らなくなる原因は実行中になんらかの理由でHTTPのキューがクローズされてしまい（あるいはしてしまい）、そこで例外となるため、@logger.infoを通らずに黙って子プロセスが死んでしまうということです。（コマンドプロンプトは親プロセス側が持っているので、子プロセスが死んでも、ログを出さないとわからない） とりあえず、 rescue => e p e p e.backtrace.join("\n") break end で例外となった子プロセスを終わらせるか、または、runの中身全体をrescue Interrupt以外の原因で内部のループから抜けた場合に再試行するループを作って、キューがなくなったら、最初の@server.openから再試行するのが対症療法となりますが、なぜキューがクローズされたのか、その原因を調べるのが本来ですね。 他に、何か怪しいログは出ていないでしょうか？

[sibapy]

回答ありがとうございます。 はい。ループしてしまったので、break を入れております。 この場合、２プロセスで動作していたのが、１プロセスで動作していることになるのですよね？

なるほど、@server.open から再試行するというのは試してみたいと思います。

他に怪しいログが出ているのには気づきませんでした。 もうしばらく確認してみたいと思います。

[sibapy]

EnnouでもEnnoumuでも起きるようですが、Ennoustでは起きませんでした。 DB（TinyTDS）の有無なども疑いましたが、assetsの静的イメージのリクエストでも発生しました。 同じ（と思われる）構成の環境で、全く発生しないPCも存在するのでWindowsそのももの環境にも依存しているのかも。 全く役に立たない情報ですいません。

[arton]

どうもありがとうございます。ということは、ennou（Rubyの可能性もありますが）の、スレッド制御がうまくいっていなくて、HTTPキューをよからぬ状態にしてしまうバグがありそうです。とりあえずは、その方向で見直してみます。 どうもすみません。

[sibapy]

その後、Ennoust（正確には以前非公式に頂いたシングルスレッド版Ennoumuです。Ennoustとの差異はキュー名のみ）でも発生を確認しました。 その時のスタックトレースは以下です（同じ現象なのかわかりませんが、、、）。 レスポンスが返るのが遅いリクエストが存在している状態で、別のリクエストが処理される（レスポンスが返る）時に発生しているようです。

C:/***/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:86:in `close': unknown error - call HttpSendHttpResponse (1229)(SystemCallError)
        from C:/***/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:86:in `run_single_thread'
        from C:/***/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:57:in `block (2 levels) in run'
        from C:/***/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:53:in `loop'
        from C:/***/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:53:in `block in run'
        from C:/***/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:28:in `open'
        from C:/***/lib/ruby/vendor_ruby/1.9.1/rack/handler/ennoumu.rb:28:in `run'
        from C:/***/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/server.rb:265:in `start'
        from C:/***/lib/ruby/gems/1.9.1/gems/rack-1.4.1/lib/rack/server.rb:137:in `start'
        from C:/***/lib/ruby/gems/1.9.1/gems/rack-1.4.1/bin/rackup:4:in `<top (required)>'
        from C:/***/bin/rackup:23:in `load'
        from C:/***/bin/rackup:23:in `<main>'

[sibapy]

http://support.microsoft.com/kb/820729/ja#LetMeFixItMyselfAlways に従い、http.sys のログを採取しましたが、 Connection_Abandoned_By_ReqQueue というのが記録されていました。何かわかりますでしょうか？

あと、意図せず workerが死んだ時に、再度 workerを起動するアドホックなパッチを作成してみました。 可能であればレビューしていただけないでしょうか？ STDOUT.print "\n" しているのは、たまに、Enterを打たないとリクエストが処理されないことがあるためです。 → 果たして効果あるのかわかりません。（＾＾；

お手数ですがよろしくお願いいたします。

※ preタグ使っているのに、なぜか < が展開されてしまうので、一部 &lt; と書いています。

diff -ur orig/ennoumu.rb ad_hoc/ennoumu.rb
--- orig/ennoumu.rb 2013-06-03 21:28:22.000000000 +0900
+++ ad_hoc/ennoumu.rb   2013-07-03 18:58:22.000000000 +0900
@@ -42,14 +42,22 @@
               @logger.info " spawn worker pid=#{pids.last}"
             end
             until @stoprun do
-              sleep 1
-            end  
+              chld = Process.wait
+              pids.reject! {|pid| pid == chld}
+              if $?.exitstatus == 2
+                # spawn the new worker process(ad hoc)
+                pids << spawn(cmd)
+                @logger.info " spawn worker pid=#{pids.last}"
+                STDOUT.print "\n"
+              end
+            end
             @logger.info "Ennou(#{::Ennou::VERSION}) controller pid=#{$$} stop"
             Process.waitall
           else
             server.script =  @script
             @logger.info "script=#{server.script}, #{@script}"
             @logger.info "Ennou(#{::Ennou::VERSION}) start for http://#{@host}:#{@port}#{@script} pid=#{$$}"
+            ret = 0
             loop do
               begin
                 r = server.wait(60)
@@ -57,9 +65,13 @@
                 run_thread(app, *r)
               rescue Interrupt
                 break
+              rescue => e
+                ret = 2
+                break
               end
             end
             @logger.info "Ennou(#{::Ennou::VERSION}) stop service for http://#{@host}:#{@port}#{@script} pid=#{$$}"
+            exit ret
           end
         end
       end   

[arton]

パッチありがとうございます。EnnnouMuとEnnouSt両方に取り込みました。 Connection_Abandoned_By_ReqQueueで調べるとわかりそうなので（ぱっと見た感じ既にクライアント側がクローズしているのに送信しようとしているということかな？）、追ってみます。 どうもありがとうございます。

[sibapy]

もう一点だけ、すいません。 以前 #12 でもお伺いしたのですが（Close後でしたが）、ennoust.rb の 42行目のサーバ指定は、-s Ennoumu ではなくて、 -s Ennoust ですよね？ よろしくお願いします。

[arton]

すみません、完全に見落としていました。 修正してコミットしました。

[sibapy]

色々調べていて、こちらのコードが不具合のトリガーになっていると思われるのを見つけました。

アプリログに assets のログを出さないようにするため、下記の config/initializers/quiet_assets.rb を追加していました。 コードはググるとすぐに見つかるものですが、最初の一行をコメントアウトすることで、今回の不具合が起こらなくなりました。 検索で見つかるのは、どれも '/dev/null' となっており、UNIX系のサンプルですが、windows の nul デバイスを同じように使うと問題が起きているようです。

Rails.application.assets.logger = Logger.new('nul')    # これをコメントアウトすると発生しない。
Rails::Rack::Logger.class_eval do
  def call_with_quiet_assets(env)
    previous_level = Rails.logger.level
    Rails.logger.level = Logger::ERROR if env['PATH_INFO'].index("/assets/") == 0
    call_without_quiet_assets(env).tap do
      Rails.logger.level = previous_level
    end
  end
  alias_method_chain :call, :quiet_assets
end

[arton]

調査、どうもありがとうございます。 nulを指定すると、おかしなことが起きるか試してみましたが、どうもわかりません（出力は単に捨てられているだけに見える）。

[sibapy]

そうですか、こちらでは効果があった（と感じただけかもしれませんが、、、）のですが、確かに他にも色々沢山作っているので、それらの複合条件でおきるのかもしれません。 可能であれば、もう少しコンパクトなサンプルで再現できるようにしてみたいと思います。 一旦、このチケットはクローズで良いかと思います。

どうも色々とありがとうございました。

[arton]

どうもお役に立てなくてすみません。

[kikaihonyaku]

いつもNougakuDoにお世話になっております。またクローズ後時間がたっての書き込み失礼します。

私もこちらと同様の現象がでました。 私の場合、production.logに書き込みされるタイミングでこちらのエラーがでました。 （ログに書き込まれるとエラーが毎回発生するわけではないですが、 　エラーが発生する時は必ずログが書き込まれるタイミングと同じ）

上記で書かれているassets_quiet.rbに加え、 config/environments/production.rbに「config.log_level = :fatal 」として 致命的エラー以外はproduction.logに書き込みされないようにするとほぼ発生しなくなりました。

ご報告まで。

[arton]

ご報告どうもありがとうございます。 時間を作ってログ周りを調べてみます。