passenger: standalone setup not resolving every 8th request

I’m fairly confident this is a passenger issue, as rolling back to 5.1.12 fixed it for me. It may be configuration related, so here’s a brief rundown of how things are setup here.

I’m running a Rails 5.2.1 app that’s dropping every 8th request. It doesn’t matter the HTTP method, nor the controller I’m going to, I get something like this every 8th one:

I, [2018-09-12T09:31:17.317366 #7410]  INFO -- : [8c8358df-f722-4cfd-ad13-32aa11e98517] Started GET "/testy/" for 140.232.0.192 at 2018-09-12 09:31:17 -0400
F, [2018-09-12T09:31:17.319266 #7410] FATAL -- : [8c8358df-f722-4cfd-ad13-32aa11e98517]   
F, [2018-09-12T09:31:17.319387 #7410] FATAL -- : [8c8358df-f722-4cfd-ad13-32aa11e98517] ActionController::RoutingError (No route matches [GET] "/testy"):
F, [2018-09-12T09:31:17.319429 #7410] FATAL -- : [8c8358df-f722-4cfd-ad13-32aa11e98517]   
F, [2018-09-12T09:31:17.319483 #7410] FATAL -- : [8c8358df-f722-4cfd-ad13-32aa11e98517] actionpack (5.2.1) lib/action_dispatch/middleware/debug_exceptions.rb:65:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] actionpack (5.2.1) lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] railties (5.2.1) lib/rails/rack/logger.rb:38:in `call_app'
[8c8358df-f722-4cfd-ad13-32aa11e98517] railties (5.2.1) lib/rails/rack/logger.rb:26:in `block in call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] activesupport (5.2.1) lib/active_support/tagged_logging.rb:71:in `block in tagged'
[8c8358df-f722-4cfd-ad13-32aa11e98517] activesupport (5.2.1) lib/active_support/tagged_logging.rb:28:in `tagged'
[8c8358df-f722-4cfd-ad13-32aa11e98517] activesupport (5.2.1) lib/active_support/tagged_logging.rb:71:in `tagged'
[8c8358df-f722-4cfd-ad13-32aa11e98517] railties (5.2.1) lib/rails/rack/logger.rb:26:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] actionpack (5.2.1) lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] actionpack (5.2.1) lib/action_dispatch/middleware/request_id.rb:27:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] rack (2.0.5) lib/rack/method_override.rb:22:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] rack (2.0.5) lib/rack/runtime.rb:22:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] activesupport (5.2.1) lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] actionpack (5.2.1) lib/action_dispatch/middleware/executor.rb:14:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] rack (2.0.5) lib/rack/sendfile.rb:111:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] railties (5.2.1) lib/rails/engine.rb:524:in `call'
[8c8358df-f722-4cfd-ad13-32aa11e98517] passenger (5.2.3) src/ruby_supportlib/phusion_passenger/rack/thread_handler_extension.rb:97:in `process_request'
[8c8358df-f722-4cfd-ad13-32aa11e98517] passenger (5.2.3) src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:152:in `accept_and_process_next_request'
[8c8358df-f722-4cfd-ad13-32aa11e98517] passenger (5.2.3) src/ruby_supportlib/phusion_passenger/request_handler/thread_handler.rb:113:in `main_loop'
[8c8358df-f722-4cfd-ad13-32aa11e98517] passenger (5.2.3) src/ruby_supportlib/phusion_passenger/request_handler.rb:416:in `block (3 levels) in start_threads'
[8c8358df-f722-4cfd-ad13-32aa11e98517] passenger (5.2.3) src/ruby_supportlib/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'

I have passenger running with the 5.3.4 config file: resources/templates/standalone/config.erb. The only change I’ve made to this is to add a base uri:

...
# https://www.phusionpassenger.com/library/config/standalone/intro.html#nginx-configuration-template
passenger_base_uri '/testy';
### END your own configuration options ###
...

I start up passenger with the following command:

passenger start -d -e production -p 5000 --nginx-config-template nginx.config.erb

And have an nginx server forwarding requests to it like so:

location /testy/ {
  proxy_pass http://127.0.0.1:5000/testy/;

  proxy_buffer_size 32k;
  proxy_buffering off;
  proxy_buffers 10 16k;
  proxy_busy_buffers_size 32k;

  proxy_http_version 1.1;

  proxy_set_header Host $http_host;
  proxy_set_header Upgrade $http_upgrade;
  proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
  proxy_set_header X-Forwarded-Host $host;
  proxy_set_header X-Forwarded-Proto https;
}

Any thoughts or ideas?

About this issue

  • Original URL
  • State: open
  • Created 6 years ago
  • Comments: 26 (13 by maintainers)

Most upvoted comments

I was able to reproduce the issue with a simple app that was the result of a rails generate and I think I figured out why my testing was behaving differently between local and the container orchestrator. When I was testing locally, or by manually deploying the docker container, I would hit the sub context only. I never hit the root context. When the container was deployed via dc/os the healthcheck would hit the root context before I would hit the base_uri. It looks to cache that initial request somehow? Then every request after that could get a random 404. I verified that if I repeated these steps on 5.1 it did not behave this way.