Isso parece ser causado por HTTP POSTs sem um Content-Length. É corrigido no Passenger 4.0.39 .
Tenho tido problemas com o meu servidor nginx / Passenger, onde as solicitações parecem estar ficando presas, as solicitações subseqüentes não são concluídas, a fila está no máximo e o site começa a exibir 503s. Eu tenho que reiniciar o nginx para ir novamente.
Quando o problema está acontecendo, é isso que diz o status do passageiro:
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
Assim, cada instância do Passageiro tem uma solicitação, mas eles não estão usando a CPU e foram usados pela última vez há 4 minutos, e há mais 100 solicitações aguardando.
No log do Rails, as últimas entradas são uma série de solicitações HEAD começando de um único IP em rápida sucessão. Não tenho certeza se isso é relacionado ou um arenque vermelho.
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
No log do nginx, posso ver solicitações que devem ser enviadas ao Passenger, resultando em 499 (cancelamento do cliente) e 503. As solicitações que não são do passageiro ainda estão sendo concluídas corretamente.
Quando eu SIGABRT os processos ruby emperrados, todos eles dizem:
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>]
que parece indicar que está aguardando dados POST. Eu tenho meu tamanho de corpo post definido para 5MB. Eu poderia entender se um processo estava fazendo isso, mas todos fazendo isso ao mesmo tempo e demorando mais de uma hora para serem concluídos ... Teria que ser um cliente maluco ou malicioso.
Eu olhei para as opções de configuração do nginx para ver se eu poderia atempadamente esses pedidos. client_body_timeout parece que funcionaria pelo nome, mas eu não mudei por isso estar no padrão de 60s. Ele também diz "O tempo limite é definido apenas para um período entre duas operações de leitura sucessivas, não para a transmissão de todo o corpo da solicitação", então talvez não seja isso que eu quero de qualquer maneira.
O passageiro tem passenger_max_request_time , mas isso só está disponível em sua edição corporativa.
Software:
Opções nginx não padrão relevantes:
Isso parece ser causado por HTTP POSTs sem um Content-Length. É corrigido no Passenger 4.0.39 .