Sooey

2011-03-23 01:10:40 +0900

heroku consoleが原因でブラウザからのアクセスがブロックされる場合がある。

という挙動が手元では確認できているのですが、いまいち因果関係がつかめないので、確認できたことだけ書いておきます。Herokuで運用中のアプリケーションをheroku consoleでメンテする時は気に留めておくといいかもしれません。

Herokuにデプロイしたアプリケーションはheroku consoleで対話的な操作が可能となるため、簡単なメンテナンス作業やデバッグをここで済ませてしまうこともあると思いますが、ここで時間のかかる処理を行うと、その間ブラウザからのリクエストが(heroku consoleのレスポンスが返るまで)待たされることがあります。のんびりループとか回してると、その間誰もアクセスできない恐怖。

このことは、たとえばheroku consolesleep 20といったコマンドを実行している間に、ブラウザでアプリケーションにアクセスするとリクエストの完了までに20秒以上待たされることから確認できると思います。

調べてみてわかったことは、heroku consoleコマンドが裏側でHeroku APIに対してPOSTリクエストを送るような構造になっていることと(/lib/heroku/client.rb#L209)、そのリクエストが最終的にDynoで処理されているということ。

例として、アプリケーションのDynoが1つだけの場合、以下のようにしてheroku consoleを実行すると、

$ heroku console "puts 'console with 1 dyno'"

heroku logsで取得できるログは次のようになります。

2011-03-23 00:29:15 +0900 app[web.1]: console with 1 dyno
2011-03-23 00:29:15 +0900 heroku[router]: POST myapp.heroku.com/_heroku/console dyno=web.1 queue=0 wait=0ms service=4ms bytes=189
2011-03-23 00:29:15 +0900 heroku[nginx]: POST /_heroku/console? HTTP/1.1 | 50.16.64.138 | 171 | http | 200

Heroku APIに向けて投げられたconsoleコマンドのPOSTリクエストが、Router、Nginxを経由して自分のアプリケーションのDyno(=この場合はweb.1)までたどり着いています。各行の順序がしっくりこないのはたぶんそういうもの。

heroku consoleがDynoを専有するから…ということであれば話は簡単で、アプリケーションに割り当てるDynoを2や3にすれば解決しそうですが、実際に試したところ、タイミングによってブロックされたりされなかったりという感じで、Dynoだけの問題ではなさそう。複数のDynoを起動して、heroku consoleとブラウザからのリクエストを何度か行ったケースのログを見ると、Dynoがレスポンスを返した後のNginxかRouterで詰まっているような気がしないこともない。

そうでなくても以下のようなこともあるし、基本的にheroku consoleで待ち時間の発生する処理はしないということで今のところは逃げています。

$ heroku console
>> sleep 70
Timed out. Long running requests are not supported on the console.
Please consider creating a rake task instead.