Unicorn worker timeout on AWS boxes

Question

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

Answer 1

So the problem appears to be that I am running the AWS instance privately (without a public IP) which is then connected to a Load Balancer. Removing the Load Balancer and accessing the instance directly resolves the issue of the workers timing out, and I don't get the performance degradation.