2011-03-23 01:10:40 +0900
heroku consoleが原因でブラウザからのアクセスがブロックされる場合がある。
という挙動が手元では確認できているのですが、いまいち因果関係がつかめないので、確認できたことだけ書いておきます。Herokuで運用中のアプリケーションをheroku console
でメンテする時は気に留めておくといいかもしれません。
Herokuにデプロイしたアプリケーションはheroku console
で対話的な操作が可能となるため、簡単なメンテナンス作業やデバッグをここで済ませてしまうこともあると思いますが、ここで時間のかかる処理を行うと、その間ブラウザからのリクエストが(heroku console
のレスポンスが返るまで)待たされることがあります。のんびりループとか回してると、その間誰もアクセスできない恐怖。
このことは、たとえばheroku console
でsleep 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.