ruby-on-rails - Rails 3.1 + Heroku: この Heroku ログの解読を手伝ってくれる人はいますか?

Question

Heroku 上の Rails サーバーへの単一の HTTP リクエスト (と思われる) からクライアントが複数の JSON レスポンスを受信するという断続的な問題が発生しています。問題を示すHerokuログは次のとおりです...

2012-04-20T00:22:27+00:00 app[web.1]: Started POST "/games/2/call" for 76.171.181.11 at 2012-04-19 17:22:27 -0700
2012-04-20T00:22:27+00:00 app[web.1]:   Processing by GamesController#call as */*
2012-04-20T00:22:27+00:00 app[web.1]:   Parameters: {"fb_id"=>"0", "id"=>"2"}
2012-04-20T00:22:27+00:00 app[web.1]: Completed 200 OK in 163ms (Views: 0.3ms | ActiveRecord: 93.3ms)
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4594ms status=200 bytes=2013
2012-04-20T00:22:27+00:00 app[web.1]: cache: [POST /games/2/call] invalidate, pass
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4546ms status=200 bytes=2013
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4594ms status=200 bytes=2012
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4570ms status=200 bytes=2013
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4560ms status=200 bytes=2013
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4534ms status=200 bytes=2013
2012-04-20T00:22:27+00:00 heroku[nginx]: 76.171.181.11 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 560 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 76.171.181.11 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 560 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 76.171.181.11 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 539 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 207.151.231.155 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 540 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 207.151.231.155 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 540 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 207.151.32.38 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 540 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_3) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.151 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 108.70.74.121 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 540 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19"

私は Rails と Heroku を初めて使用するので、何が起こっているのかを把握するのに十分なほどこのログを理解できません。Heroku 上の Rails アプリがクライアントから複数の HTTP リクエストを受信していますか? それとも、HTTP リクエストを 1 つだけ受信して複数の JSON レスポンスを返していますか?

あなたの知恵を前もってどうもありがとう！

score 2 · Accepted Answer

同時に 7 つの POST リクエストを受け取ります。

# First Request, heroku starts to process it normally
2012-04-20T00:22:27+00:00 app[web.1]: Started POST "/games/2/call" for 76.171.181.11 at 2012-04-19 17:22:27 -0700
2012-04-20T00:22:27+00:00 app[web.1]:   Processing by GamesController#call as */*
2012-04-20T00:22:27+00:00 app[web.1]:   Parameters: {"fb_id"=>"0", "id"=>"2"}

# First request returns OK
2012-04-20T00:22:27+00:00 app[web.1]: Completed 200 OK in 163ms (Views: 0.3ms | ActiveRecord: 93.3ms)

# Second request starts
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4594ms status=200 bytes=2013

# It looks like the second request fails
2012-04-20T00:22:27+00:00 app[web.1]: cache: [POST /games/2/call] invalidate, pass

# Request 3-7 come in
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4546ms status=200 bytes=2013
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4594ms status=200 bytes=2012
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4570ms status=200 bytes=2013
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4560ms status=200 bytes=2013
2012-04-20T00:22:27+00:00 heroku[router]: POST myapp.heroku.com/games/2/call dyno=web.1 queue=0 wait=0ms service=4534ms status=200 bytes=2013

# Heroku responds to the requests... though I'm  not sure what it's serving up.
2012-04-20T00:22:27+00:00 heroku[nginx]: 76.171.181.11 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 560 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 76.171.181.11 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 560 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 76.171.181.11 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 539 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 207.151.231.155 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 540 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 207.151.231.155 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 540 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 207.151.32.38 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 540 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_3) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.151 Safari/535.19" myapp.heroku.com
2012-04-20T00:22:27+00:00 heroku[nginx]: 108.70.74.121 - - [20/Apr/2012:00:22:27 +0000] "POST /games/2/call HTTP/1.1" 200 540 "http://myapp.heroku.com/pages/fb/webplayer_64.unity3d" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.19 (KHTML, like Gecko) Chrome/18.0.1025.162 Safari/535.19"

私は時折、このような問題を抱えていました.JavascriptリクエストがDOMをバブルアップさせ、1回だけ起動するつもりだったのに複数回起動します。これにより、サーバーが非常に高速にクラッシュする可能性があるため、必ずアプリを調べて、AJAX 呼び出しをトリガーする連射していないことを確認する必要があります。

これをキャッチする非常に簡単な方法はalert()、ajax 呼び出しの直前または直後に配置し、それが何回発生するかを確認することです。

それがあなたの問題かどうかはわかりませんが、私は以前にそのようなことが起こったことがあります.

ruby-on-rails - Rails 3.1 + Heroku: この Heroku ログの解読を手伝ってくれる人はいますか?

1 に答える 1

Related

Reference