I've been having problems with my nginx/Passenger server where requests appear to be getting stuck, any subsequent requests don't complete, the queue gets up to its max, and the site starts serving out 503s. I have to restart nginx to get it going again.
When the problem is happening, this is what passenger-status says:
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
So each Passenger instance has a request, yet they are not using CPU and were last used 4 minutes ago, and there's 100 more requests waiting.
In the Rails log, the last entries are a series of HEAD requests starting from a single IP in quick succession. I'm unsure if this is related or a red herring.
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
In the nginx log, I can see requests that should go to Passenger resulting in 499 (client cancel) and 503. Non-Passenger requests are still completing correctly.
When I SIGABRT the stuck ruby processes, they all say:
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>]
which looks like it indicates that it's waiting for POST data. I have my post body size set to 5MB. I could understand if one process was doing this, but all of them doing it at the same time and taking over an hour to complete… It would have to be a screwy or malicious client.
I've looked into nginx's config options to see if I could time out these requests. client_body_timeout sounds like it would work by its name, but I haven't changed it so it should be at the default of 60s. It also says "The timeout is set only for a period between two successive read operations, not for the transmission of the whole request body", so maybe that's not what I want anyway.
Passenger has passenger_max_request_time, but this is only available in their enterprise edition.
Software:
- nginx/1.4.4
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-4) (GCC)
TLS SNI support enabled
configure arguments: –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/gems/passenger-4.0.37/ext/nginx - Passenger 4.0.37
- ruby 2.0.0p353 (2013-11-22 revision 43784) [x86_64-linux]
- Rails 4.0.3
Relevant non-default nginx options:
- keepalive_timeout 65;
- client_max_body_size 5m;
Best Answer
This appears to be caused by HTTP POSTs without a Content-Length. It's fixed in Passenger 4.0.39.