problems with Puma phased restarts in Rails apps

[davidhq]

I'm very often left with non-working web app after deploy with mina...

puma somehow dies...

-----> DB schema unchanged; skipping DB migration        
-----> Skipping asset precompilation        
-----> Cleaning up old releases (keeping 5)        
-----> Build finished        
-----> Moving build to releases/42        
-----> Updating the current symlink        
-----> Launching        
       Command phased-restart sent success 
-----> Done. Deployed v42        
       Elapsed time: 3.00 seconds

(here the website is down)

$ mina puma:restart
-----> Loading rbenv
Puma is not running!
[23126] Puma starting in cluster mode...
[23126] * Version 2.9.0 (ruby 2.1.2-p95), codename: Team High Five
[23126] * Min threads: 1, max threads: 16
[23126] * Environment: production
[23126] * Process workers: 2
[23126] * Preloading application
[23126] * Listening on unix:///var/www/meetcasts/shared/tmp/sockets/puma.sock
[23126] * Listening on tcp://0.0.0.0:3003
[23126] * Daemonizing...
Connection to example.com closed.
       Elapsed time: 4.00 seconds

(note the line Puma is not running)

I then have to start puma agan manually and a lot of times I have to stop and restart multiple times before it works.

Mina restarts puma via pumactl but I have also tried to replace the default command with:

kill -SIGUSR2 `ps aux | grep tcp://0.0.0.0:3003 | grep puma | awk '{ print $2 }'`

But the problem happened again. Also it happens on multiple (Rails 4.1.x) apps...

How to debug this?

[evanphx]

Is there anything in the log? There isn't anything for me to go on here. Also, what does your config look like?

[davidhq]

Nothing specific in log...

workers Integer(ENV['PUMA_WORKERS'] || 2)
threads Integer(ENV['MIN_THREADS']  || 1), Integer(ENV['MAX_THREADS'] || 16)

preload_app!

rackup      DefaultRackup
port        ENV['PORT']     || 3003
environment ENV['RACK_ENV'] || 'production'

on_worker_boot do
  # worker specific setup
  ActiveSupport.on_load(:active_record) do
    config = ActiveRecord::Base.configurations[Rails.env] ||
                Rails.application.config.database_configuration[Rails.env]
    config['pool'] = ENV['MAX_THREADS'] || 16
    ActiveRecord::Base.establish_connection(config)
  end
end

[evanphx]

Can you add stdout_redirect "log/stderr.log", "log/stderr.log", true to your config and see if anything shows up in those file? (You may need to adjust the paths to point to valid locations).

[davidhq]

Now it happened on the third project, but this one is configured a bit differenty... anyway the log might still be useful:

=== puma startup: 2014-11-09 16:37:28 +0000 ===
=== puma startup: 2014-11-09 16:37:28 +0000 ===
[26197] * Starting control server on unix:///var/www/sc/shared/tmp/sockets/pumactl.sock
[26197] - Worker 0 (pid: 26203) booted, phase: 0
[26197] - Worker 1 (pid: 26205) booted, phase: 0
[26197] * phased-restart called but not available, restarting normally.
[26197] - Gracefully shutting down workers...
[26197] * Restarting...
/home/david/.rbenv/versions/2.1.2/bin/ruby: No such file or directory -- /var/www/sc/releases/56/vendor/bundle/ruby/2.1.0/bin/puma (LoadError)

The last line is not puma's problem, but my configuration but I think the root cause is of some interest: so why phased-restart wasn't available? I have to see if this is the same reason other deploys failed.. but so far it hasn't happened on other projects.

[davidhq]

Now it happened again and indeed this is the problem: when phased restart is not possible for some reason, then other errors come, not sure why... but maybe if phased restart worked always, the other things wouldn't be important.

=== puma startup: 2014-11-09 19:55:09 +0000 ===
=== puma startup: 2014-11-09 19:55:09 +0000 ===
[25957] * Starting control server on unix:///var/www/sc/shared/tmp/sockets/pumactl.sock
[25957] - Worker 0 (pid: 25963) booted, phase: 0
[25957] - Worker 1 (pid: 25972) booted, phase: 0
[25957] * phased-restart called but not available, restarting normally.
[25957] - Gracefully shutting down workers...
[25957] * Restarting...
Exception handling servers: undefined method `join' for nil:NilClass (NoMethodError)
/home/david/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/puma-2.9.2/lib/puma/thread_pool.rb:179:in `shutdown'
/home/david/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/puma-2.9.2/lib/puma/server.rb:746:in `graceful_shutdown'
/home/david/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/puma-2.9.2/lib/puma/server.rb:312:in `handle_servers'
/home/david/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/puma-2.9.2/lib/puma/server.rb:273:in `block in run'
/home/david/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/bundler-1.7.2/lib/bundler/definition.rb:22:in `build': /var/www/sc/releases/63/Gemfile not found (Bundler::GemfileNotFound)
  from /home/david/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/bundler-1.7.2/lib/bundler.rb:154:in `definition'
  from /home/david/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/bundler-1.7.2/lib/bundler.rb:117:in `setup'
  from /home/david/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/bundler-1.7.2/lib/bundler/setup.rb:17:in `<top (required)>'
  from /home/david/.rbenv/versions/2.1.2/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
  from /home/david/.rbenv/versions/2.1.2/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'

As I said, not sure why Gemfile is not found, maybe it has to do with deployment steps... Gemfile is available now when I look but maybe in the process something happened...

[sorentwo]

You have preload_app! in your config, which you don't want to use with phased restart. There is a little about this in deployment

[davidhq]

Ugh... thank you! I feel smarter now and sorry for coming with this....

[davidhq]

@sorentwo now that I removed preload I have problems with these settings:

on_worker_boot do
  # worker specific setup
  ActiveSupport.on_load(:active_record) do
    config = ActiveRecord::Base.configurations[Rails.env] ||
                Rails.application.config.database_configuration[Rails.env]
    config['pool'] = ENV['MAX_THREADS'] || 16
    ActiveRecord::Base.establish_connection(config)
  end
end

Here:

config/puma.rb:15:in `block in _load_from': uninitialized constant Puma::Configuration::DSL::ActiveSupport (NameError)

Do I even need this and if I'd like to use it, how do I set this up without preloading the app?

[evanphx]

You don't need that code because the worker will boot the code itself.

[davidhq]

you mean the entire block or just on_worker_boot statement? A tiny bit confused... sorry

[evanphx]

everything in on_worker_boot you should remove.

[davidhq]

OK. I don't remember where I got this code from but if I remove it, will I always have a big enough db connection pool?

[evanphx]

You should have that code in an initializer instead if you want to configure the AR pool

[davidhq]

Ok, I'll use this: https://devcenter.heroku.com/articles/concurrency-and-database-connections#threaded-servers

thank you again