ruby-on-rails - Rails 3.1 + Heroku : Can someone help me decipher this Heroku log?

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 请求并返回多个 JSON 响应？

提前非常感谢您的智慧!

Answer 1

同时收到 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 中冒泡并多次触发，而我只想让它们触发一次。这可能会使服务器很快崩溃，因此您绝对应该检查您的应用程序并确保您没有快速触发 AJAX 调用。

捕获此问题的一个非常简单的方法是在任何 ajax 调用之前或之后立即放置一个 alert() ，然后查看它触发的次数与您期望的次数。

我不知道这是否是你的问题，但我以前也遇到过这样的事情。