Heroku+Rails4+Unicorn Repeated Crashes With No Helpful Output in Log

Question

I run dozens of Rails app on Heroku with very similar code and almost identical config. This one particular app keep crashing immediately after startup. As if that isn't bad enough, there is literally nothing in the logs to indicate what is wrong. Here's a log sample.

2016-01-14T05:56:13.776324+00:00 heroku[api]: Set LOG_LEVEL, SECRET_TOKEN config vars by [email protected]
2016-01-14T05:56:13.776324+00:00 heroku[api]: Release v13 created by [email protected]
2016-01-14T05:56:13.913292+00:00 heroku[web.1]: State changed from crashed to starting
2016-01-14T05:56:16.422157+00:00 heroku[web.1]: Starting process with command `bundle exec unicorn -p 32001 -c ./config/unicorn.rb`
2016-01-14T05:56:20.695481+00:00 heroku[web.1]: State changed from starting to crashed
2016-01-14T05:56:20.692142+00:00 heroku[web.1]: Process exited with status 1
2016-01-14T05:56:37.932488+00:00 heroku[web.1]: State changed from crashed to starting
2016-01-14T05:56:41.228603+00:00 heroku[web.1]: Starting process with command `bundle exec unicorn -p 17696 -c ./config/unicorn.rb`
2016-01-14T05:56:47.053145+00:00 heroku[web.1]: Process exited with status 1
2016-01-14T05:56:47.077114+00:00 heroku[web.1]: State changed from starting to crashed

Here's my Procfile:

web:     bundle exec unicorn -p $PORT -c ./config/unicorn.rb
worker:  bundle exec sidekiq -C config/sidekiq.yml

Here's my unicorn.rb:

pid "tmp/pids/unicorn.pid"
stdout_path "log/unicorn.log"
stderr_path "log/unicorn-err.log"

worker_processes Integer(ENV["WEB_CONCURRENCY"] || 3)
timeout 30
preload_app true

require 'fileutils'
FileUtils.mkdir_p 'tmp/pids/' unless File.exist? 'tmp/pids/'
FileUtils.mkdir_p 'log/' unless File.exist? 'log/'

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

  if defined?(ActiveRecord::Base)
    ActiveRecord::Base.connection.disconnect!
    Rails.logger.info('Disconnected from ActiveRecord')
  end

  sleep 1
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

  if defined?(ActiveRecord::Base)
    ActiveRecord::Base.establish_connection
    Rails.logger.info('Connected to ActiveRecord')
  end
end

I don't see what I am missing.

I tried troubleshooting with heroku local using RAILS_ENV=production and the app starts up just fine.

Logging into bash on Heroku using heroku run bash allows me to start the app from the CLI on Heroku just fine.

~ $ cat Procfile 
web:     bundle exec unicorn -p $PORT -c ./config/unicorn.rb
~ $ echo $PORT
9446
~ $ bundle exec unicorn -p $PORT -c ./config/unicorn.rb
~ $

2016-01-14T07:02:30.618120+00:00 heroku[api]: Starting process with command `bash` by [email protected]
2016-01-14T07:02:33.058993+00:00 heroku[run.2370]: Awaiting client
2016-01-14T07:02:33.085689+00:00 heroku[run.2370]: Starting process with command `bash`
2016-01-14T07:02:33.501795+00:00 heroku[run.2370]: State changed from starting to up

Karl Wilbur Karl Wilbur · Accepted Answer · 2016-01-14T07:28:52

AH! I figured it out!

I was able to see the unicorn log on Heroku be going this:

~ $ less log/unicorn-err.log

So, it turned out to be a simple missing config var.

Additionally, the logging and PID locations were pulled in from an app running on Linode and shouldn't be in the Heroku config file.

It should just be this:

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

  if defined?(ActiveRecord::Base)
    ActiveRecord::Base.connection.disconnect!
    Rails.logger.info('Disconnected from ActiveRecord')
  end

  sleep 1
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

  if defined?(ActiveRecord::Base)
    ActiveRecord::Base.establish_connection
    Rails.logger.info('Connected to ActiveRecord')
  end
end

(Ref: Heroku Dev Center: Deploying Rails Applications with Unicorn)

Without redirecting output via the stdout_path and stderr_path directives, the error messages are visible from heroku logs -t.

Yet another example of me getting in my own way.

Heroku+Rails4+Unicorn Repeated Crashes With No Helpful Output in Log

1 Answers