I'm trying to setup a Unicorn on an AWS box, but the workers just keep timing out and I don't know why.
I'm using a Ubuntu Server 14.04 LTS AMI, installing everything needed for a standard Ruby on Rails installation. Using rails new, I generate an empty app and attempting to access it the first time seems to be fast, but after that the workers just timeout continuously and takes forever to serve the webpage. Loading a standard WEBrick server does not have this problem and loads pages almost instantly. I have tried rolling back several versions of ruby and unicorn with no luck. This behavior does not occur locally in a VM.
Here is the log of the server running in debug mode
I, [2014-11-04T18:30:13.290599 #17134] INFO -- : listening on addr=0.0.0.0:5000 fd=10 I, [2014-11-04T18:30:13.362993 #17134] INFO -- : master process ready I, [2014-11-04T18:30:13.363098 #17137] INFO -- : worker=0 ready I, [2014-11-04T18:30:13.365175 #17140] INFO -- : worker=1 ready I, [2014-11-04T18:30:13.365314 #17142] INFO -- : worker=2 ready Exception 'LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:443 - cannot load such file -- rails/application_helper.rb Exception 'LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:352 - cannot load such file -- rails/application_helper.rb Exception 'LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:313 - No such file to load -- rails/application_helper Exception 'AbstractController::Helpers::MissingHelperError' at /var/lib/gems/2.1.0/gems/actionpack-4.1.7/lib/abstract_controller/helpers.rb:154 - Missing helper file helpers/rails/application_helper.rb Exception 'LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:443 - cannot load such file -- rails/welcome_helper.rb Exception 'LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:352 - cannot load such file -- rails/welcome_helper.rb Exception 'LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:313 - No such file to load -- rails/welcome_helper Exception 'AbstractController::Helpers::MissingHelperError' at /var/lib/gems/2.1.0/gems/actionpack-4.1.7/lib/abstract_controller/helpers.rb:154 - Missing helper file helpers/rails/welcome_helper.rb **** - - [04/Nov/2014 18:30:13] "GET / HTTP/1.1" 200 - 0.0693 **** - - [04/Nov/2014 18:30:14] "GET %2Ffavicon.ico HTTP/1.1" 304 - 0.0441 E, [2014-11-04T18:30:45.395879 #17134] ERROR -- : worker=0 PID:17137 timeout (31s > 30s), killing E, [2014-11-04T18:30:45.395995 #17134] ERROR -- : worker=1 PID:17140 timeout (31s > 30s), killing E, [2014-11-04T18:30:45.396072 #17134] ERROR -- : worker=2 PID:17142 timeout (31s > 30s), killing E, [2014-11-04T18:30:45.397748 #17134] ERROR -- : reaped # worker=2 E, [2014-11-04T18:30:45.397882 #17134] ERROR -- : worker=0 PID:17137 timeout (31s > 30s), killing E, [2014-11-04T18:30:45.397990 #17134] ERROR -- : worker=1 PID:17140 timeout (31s > 30s), killing E, [2014-11-04T18:30:45.401016 #17134] ERROR -- : reaped # worker=1 E, [2014-11-04T18:30:45.401177 #17134] ERROR -- : worker=0 PID:17137 timeout (31s > 30s), killing I, [2014-11-04T18:30:45.402352 #17148] INFO -- : worker=2 ready E, [2014-11-04T18:30:45.403784 #17134] ERROR -- : reaped # worker=0 I, [2014-11-04T18:30:45.405625 #17152] INFO -- : worker=1 ready I, [2014-11-04T18:30:45.406871 #17155] INFO -- : worker=0 ready Exception `EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached Exception `EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached Exception `EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached Exception `EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached Exception `EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached Exception `EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached Exception `EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached Exception `EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached Exception `LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:443 - cannot load such file -- rails/application_helper.rb Exception `LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:352 - cannot load such file -- rails/application_helper.rb Exception `LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:313 - No such file to load -- rails/application_helper Exception `AbstractController::Helpers::MissingHelperError' at /var/lib/gems/2.1.0/gems/actionpack-4.1.7/lib/abstract_controller/helpers.rb:154 - Missing helper file helpers/rails/application_helper.rb Exception `LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:443 - cannot load such file -- rails/welcome_helper.rb Exception `LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:352 - cannot load such file -- rails/welcome_helper.rb Exception `LoadError' at /var/lib/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/dependencies.rb:313 - No such file to load -- rails/welcome_helper Exception `AbstractController::Helpers::MissingHelperError' at /var/lib/gems/2.1.0/gems/actionpack-4.1.7/lib/abstract_controller/helpers.rb:154 - Missing helper file helpers/rails/welcome_helper.rb **** - - [04/Nov/2014 18:31:14] "GET / HTTP/1.1" 200 - 0.0680 Exception 'EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached Exception 'EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached E, [2014-11-04T18:31:45.465765 #17134] ERROR -- : worker=2 PID:17148 timeout (31s > 30s), killing E, [2014-11-04T18:31:45.468770 #17134] ERROR -- : reaped # worker=2 I, [2014-11-04T18:31:45.472177 #17162] INFO -- : worker=2 ready E, [2014-11-04T18:31:49.474506 #17134] ERROR -- : worker=1 PID:17152 timeout (31s > 30s), killing E, [2014-11-04T18:31:49.474633 #17134] ERROR -- : worker=0 PID:17155 timeout (31s > 30s), killing E, [2014-11-04T18:31:49.476313 #17134] ERROR -- : reaped # worker=1 E, [2014-11-04T18:31:49.476451 #17134] ERROR -- : worker=0 PID:17155 timeout (31s > 30s), killing I, [2014-11-04T18:31:49.481324 #17166] INFO -- : worker=1 ready E, [2014-11-04T18:31:49.481548 #17134] ERROR -- : reaped # worker=0 I, [2014-11-04T18:31:49.484368 #17169] INFO -- : worker=0 ready E, [2014-11-04T18:32:17.511012 #17134] ERROR -- : worker=2 PID:17162 timeout (31s > 30s), killing E, [2014-11-04T18:32:17.512733 #17134] ERROR -- : reaped # worker=2 I, [2014-11-04T18:32:17.516074 #17174] INFO -- : worker=2 ready E, [2014-11-04T18:32:21.518316 #17134] ERROR -- : worker=0 PID:17169 timeout (31s > 30s), killing E, [2014-11-04T18:32:21.520011 #17134] ERROR -- : reaped # worker=0 I, [2014-11-04T18:32:21.523230 #17177] INFO -- : worker=0 ready
And here is the Unicorn configuration file
worker_processes Integer(ENV["WEB_CONCURRENCY"] || 3) timeout 30 preload_app true before_fork do |server, worker| Signal.trap 'TERM' do puts 'Unicorn master intercepting TERM and sending myself QUIT instead' Process.kill 'QUIT', Process.pid end defined?(ActiveRecord::Base) and ActiveRecord::Base.connection.disconnect! end after_fork do |server, worker| Signal.trap 'TERM' do puts 'Unicorn worker intercepting TERM and doing nothing. Wait for master to send QUIT' end defined?(ActiveRecord::Base) and ActiveRecord::Base.establish_connection end
I did notice the EOF Error and is suspecting that this may be related to the timeouts, but I don't know for sure.
Exception `EOFError' at /var/lib/gems/2.1.0/gems/unicorn-4.8.1/lib/unicorn/http_request.rb:79 - end of file reached