1

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;
0

This appears to be caused by HTTP POSTs without a Content-Length. It's fixed in Passenger 4.0.39.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.