所有Passenger进程突然挂起 – 回溯指示读取POST数据?

我一直有我的nginx / Passenger服务器的问题,其中请求似乎卡住,任何后续请求不完成,队列达到其最大值,该网站开始投放503s。 我必须重新启动nginx才能重新开始。

当问题发生时,乘客状态就是这样说的:

Version : 4.0.37 Date : 2014-05-29 18:02:57 +0000 Instance: 18354 ----------- General information ----------- Max pool size : 4 Processes : 4 Requests in top-level queue : 0 ----------- Application groups ----------- /home/www/mysite#default: App root: /home/www/mysite Requests in queue: 100 * PID: 19495 Sessions: 1 Processed: 158 Uptime: 9m 23s CPU: 1% Memory : 131M Last used: 4m 19s ago * PID: 19505 Sessions: 1 Processed: 5 Uptime: 9m 23s CPU: 0% Memory : 40M Last used: 4m 18s ago * PID: 19514 Sessions: 1 Processed: 60 Uptime: 9m 23s CPU: 0% Memory : 53M Last used: 4m 20s ago * PID: 19524 Sessions: 1 Processed: 26 Uptime: 9m 23s CPU: 0% Memory : 72M Last used: 4m 16s ago 

所以每个Passenger实例都有一个请求,但是他们没有使用CPU,并且在4分钟前最后一次被使用,还有100个请求正在等待。

在Rails日志中,最后一项是从一个IP快速连续开始的一系列HEAD请求。 我不确定这是相关的还是红鲱鱼。

 I, [2014-05-26T20:05:02.339151 #22084] INFO -- : Started HEAD "/help" for 60.50.73.30 at 2014-05-26 20:05:02 +0000 I, [2014-05-26T20:05:02.375930 #22093] INFO -- : Started HEAD "/" for 60.50.73.30 at 2014-05-26 20:05:02 +0000 I, [2014-05-26T20:05:02.395532 #22110] INFO -- : Started HEAD "/users/124" for 60.50.73.30 at 2014-05-26 20:05:02 +0000 I, [2014-05-26T20:05:02.420103 #22270] INFO -- : Started HEAD "/articles" for 60.50.73.30 at 2014-05-26 20:05:02 +0000 I, [2014-05-26T20:05:02.637894 #23655] INFO -- : Started HEAD "/help/writing-articles" for 60.50.73.30 at 2014-05-26 20:05:02 +0000 

在nginx日志中,我可以看到应该去Passenger的请求,导致499(客户端取消)和503。非乘客请求仍然正确地完成。

当我说出卡住的ruby进程时,他们都说:

 App 18360 stderr: [ 2014-05-29 18:03:06.9345 19514/0x0000001b09fd38(Main thread) request_handler.rb:394 ]: ========== Process 19514: backtrace dump ========== App 18360 stderr: ------------------------------------------------------------ App 18360 stderr: # Thread: #<Thread:0x0000001b09fd38 run>(Main thread), [main thread], [current thread], alive = true App 18360 stderr: ------------------------------------------------------------ App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/utils.rb:146:in `backtrace' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/utils.rb:146:in `block in global_backtrace_report' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/utils.rb:145:in `each' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/utils.rb:145:in `global_backtrace_report' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler.rb:394:in `print_status_report' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler.rb:380:in `block in install_useful_signal_hand lers' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler.rb:517:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler.rb:517:in `select' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler.rb:517:in `wait_until_termination_requested' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler.rb:206:in `main_loop' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/helper-scripts/rack-preloader.rb:161:in `<module:App>' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/helper-scripts/rack-preloader.rb:29:in `<module:PhusionPassenger>' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/helper-scripts/rack-preloader.rb:28:in `<main>' App 18360 stderr: App 18360 stderr: ------------------------------------------------------------ App 18360 stderr: # Thread: #<NewRelic::Agent::Threading::AgentThread:0x0000001e565518 sleep>, alive = true App 18360 stderr: ------------------------------------------------------------ App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/agent/worker_loop.rb:47:in `sleep' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/agent/worker_loop.rb:47:in `run' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/agent/agent.rb:581:in `create_and_run_worker_loop' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/agent/agent.rb:648:in `block (2 levels) in deferred_work!' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/agent.rb:403:in `disable_all_tracing' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/agent/agent.rb:640:in `block in deferred_work!' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/agent/agent.rb:620:in `catch_errors' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/agent/agent.rb:639:in `deferred_work!' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/agent/agent.rb:672:in `block in start_worker_thread' App 18360 stderr: App 18360 stderr: ------------------------------------------------------------ App 18360 stderr: # Thread: #<Thread:0x0000001eb5e320 sleep>(Worker 1), alive = true App 18360 stderr: ------------------------------------------------------------ App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/utils/unseekable_socket.rb:244:in `eof?' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/utils/unseekable_socket.rb:244:in `eof?' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/utils/tee_input.rb:148:in `socket_drained?' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/utils/tee_input.rb:115:in `read' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/rack-1.5.2/lib/rack/request.rb:204:in `POST' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/http/request.rb:282:in `POST' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/http/parameters.rb:16:in `parameters' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/http/filter_parameters.rb:37:in `filtered_parameters' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_controller/metal/instrumentation.rb:22:in `process_action' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_controller/metal/params_wrapper.rb:245:in `process_action' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/activerecord-4.0.3/lib/active_record/railties/controller_runtime.rb:18:in `process_action' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/abstract_controller/base.rb:136:in `process' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/abstract_controller/rendering.rb:44:in `process' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_controller/metal.rb:195:in `dispatch' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_controller/metal.rb:231:in `block in action' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/routing/route_set.rb:80:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/routing/route_set.rb:80:in `dispatch' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/routing/route_set.rb:48:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/journey/router.rb:71:in `block in call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/journey/router.rb:59:in `each' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/journey/router.rb:59:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/routing/route_set.rb:680:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/rack/error_collector.rb:55:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/rack/agent_hooks.rb:32:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/newrelic_rpm-3.7.2.195/lib/new_relic/rack/browser_monitoring.rb:27:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/warden-1.2.3/lib/warden/manager.rb:35:in `block in call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/warden-1.2.3/lib/warden/manager.rb:34:in `catch' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/warden-1.2.3/lib/warden/manager.rb:34:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/rack-1.5.2/lib/rack/etag.rb:23:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/rack-1.5.2/lib/rack/conditionalget.rb:25:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/rack-1.5.2/lib/rack/head.rb:11:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/middleware/params_parser.rb:27:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/middleware/flash.rb:241:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:225:in `context' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:220:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/middleware/cookies.rb:486:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/activerecord-4.0.3/lib/active_record/query_cache.rb:36:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/activerecord-4.0.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:626:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/activesupport-4. App 18360 stderr: 0.3/lib/active_support/callbacks.rb:373:in `_run__202321469828990653__call__callbacks' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/activesupport-4.0.3/lib/active_support/callbacks.rb:80:in `run_callbacks' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/middleware/callbacks.rb:27:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/middleware/remote_ip.rb:76:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/railties-4.0.3/lib/rails/rack/logger.rb:38:in `call_app' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/railties-4.0.3/lib/rails/rack/logger.rb:20:in `block in call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/activesupport-4.0.3/lib/active_support/tagged_logging.rb:67:in `block in tagged' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/activesupport-4.0.3/lib/active_support/tagged_logging.rb:25:in `tagged' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/activesupport-4.0.3/lib/active_support/tagged_logging.rb:67:in `tagged' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/railties-4.0.3/lib/rails/rack/logger.rb:20:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/actionpack-4.0.3/lib/action_dispatch/middleware/request_id.rb:21:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/rack-1.5.2/lib/rack/methodoverride.rb:21:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/rack-1.5.2/lib/rack/runtime.rb:17:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/activesupport-4.0.3/lib/active_support/cache/strategy/local_cache.rb:83:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/rack-1.5.2/lib/rack/sendfile.rb:112:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/railties-4.0.3/lib/rails/engine.rb:511:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/railties-4.0.3/lib/rails/application.rb:97:in `call' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/rack/thread_handler_extension.rb:77:in `process_request' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler/thread_handler.rb:142:in `accept_and_process_next_request' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler.rb:448:in `block (3 levels) in start_threads' App 18360 stderr: App 18360 stderr: ------------------------------------------------------------ App 18360 stderr: # Thread: #<Thread:0x0000001eb5ddd0 sleep>(HTTP helper worker), alive = true App 18360 stderr: ------------------------------------------------------------ App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler/thread_handler.rb:127:in `accept' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler/thread_handler.rb:127:in `accept_and_process_next_request' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop' App 18360 stderr: /home/www/.rvm/gems/ruby-2.0.0-p353/gems/passenger-4.0.37/lib/phusion_passenger/request_handler.rb:464:in `block (2 levels) in start_threads' App 18360 stderr: App 18360 stderr: App 18360 stderr: [ 2014-05-29 18:03:06.9346 19514/0x0000001b09fd38(Main thread) request_handler.rb:395 ]: Threads: [#<Thread:0x0000001eb5e320 sleep>, #<Thread:0x0000001eb5ddd0 sleep>] 

看起来像表示它正在等待POST数据。 我的post正文大小设置为5MB。 我可以理解,如果一个过程是这样做的,但他们都在同一时间,并花了一个多小时才能完成…这将是一个疯狂或恶意的客户端。

我查看了nginx的configuration选项,看看我能否超时这些请求。 client_body_timeout听起来像它的名字,但我没有改变它,所以它应该是默认的60年代。 它也说“超时只设置了两个连续的读操作之间的一段时间,而不是整个请求体的传输”,所以也许这不是我想要的。

乘客有passenger_max_request_time ,但是这只在他们的企业版中可用。

软件:

  • nginx / 1.4.4由gcc构build4.4.7 20120313(Red Hat 4.4.7-4)(GCC)启用了TLS SNI支持的configuration参数:–prefix = / opt / nginx –with-http_ssl_module –with-http_gzip_static_module – -with-http_stub_status_module –with-cc-opt = -Wno-error –with-pcre = / tmp / passenger.1tqkr9f / pcre-8.32 –add-module = / home / www / .rvm / gems / ruby​​- 2.0.0-P353 /gem/乘客-4.0.37 / EXT / nginx的
  • 乘客4.0.37
  • ruby2.0.0p353(2013-11-22修订版43784)[x86_64-linux]
  • Rails 4.0.3

相关的非默认nginx选项:

  • keepalive_timeout 65;
  • client_max_body_size 5m;

这似乎是由没有Content-Length的HTTP POST导致的。 它在旅客4.0.39固定 。