ruby on rails - Heroku logs FATAL SignalException: SIGTERM

Question

I don't understand why I am getings this FATAL exception. It works just fine in localhost.

I understand that SIGTERM is simply a signal to terminate the program, and I don't believe the solution is to handle or ignore it.

When I look at the deployed website it displays as a white page. How can I fix this error so that my app can display normally?

Here are my Heroku logs:

2014-04-23T20:59:57.995734+00:00 app[web.1]:    /app/vendor/ruby-2.0.0/lib/ruby/2.0.0/webrick/server.rb:170:in `block in start'
2014-04-23T20:59:57.995789+00:00 app[web.1]:    /app/vendor/ruby-2.0.0/lib/ruby/2.0.0/webrick/server.rb:32:in `start'
2014-04-23T20:59:57.995875+00:00 app[web.1]:    /app/vendor/ruby-2.0.0/lib/ruby/2.0.0/webrick/server.rb:160:in `start'
2014-04-23T20:59:57.995933+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/handler/webrick.rb:14:in `run'
2014-04-23T20:59:57.995988+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/server.rb:264:in `start'
2014-04-23T20:59:57.996042+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.4/lib/rails/commands/server.rb:84:in `start'
2014-04-23T20:59:57.996552+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.4/lib/rails/commands.rb:71:in `<top (required)>'
2014-04-23T20:59:57.996843+00:00 app[web.1]: [2014-04-23 20:59:57] INFO  WEBrick::HTTPServer#start done.
2014-04-23T20:59:57.996932+00:00 app[web.1]: Exiting
2014-04-23T20:59:57.996466+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.4/lib/rails/commands.rb:71:in `tap'
2014-04-23T20:59:57.996333+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.4/lib/rails/commands.rb:76:in `block in <top (required)>'
2014-04-23T20:59:57.996777+00:00 app[web.1]: [2014-04-23 20:59:57] INFO  going to shutdown ...
2014-04-23T20:59:57.996607+00:00 app[web.1]:    bin/rails:4:in `require'
2014-04-23T20:59:57.996688+00:00 app[web.1]:    bin/rails:4:in `<main>'
2014-04-23T20:59:59.247265+00:00 heroku[web.1]: Process exited with status 143
2014-04-23T21:08:58.674758+00:00 heroku[web.1]: State changed from down to starting
2014-04-23T21:08:58.674486+00:00 heroku[web.1]: Unidling
2014-04-23T21:09:01.944699+00:00 heroku[web.1]: Starting process with command `bin/rails server -p 10144 -e production`
2014-04-23T21:09:04.904686+00:00 heroku[web.1]: State changed from starting to up
2014-04-23T21:09:05.944216+00:00 app[web.1]: => Booting WEBrick
2014-04-23T21:09:04.858787+00:00 app[web.1]: [2014-04-23 21:09:04] INFO  ruby 2.0.0 (2014-02-24) [x86_64-linux]
2014-04-23T21:09:04.859359+00:00 app[web.1]: [2014-04-23 21:09:04] INFO  WEBrick::HTTPServer#start: pid=2 port=10144
2014-04-23T21:09:04.858787+00:00 app[web.1]: [2014-04-23 21:09:04] INFO  WEBrick 1.3.1
2014-04-23T21:09:05.944216+00:00 app[web.1]: => Rails 4.0.4 application starting in production on http://0.0.0.0:10144
2014-04-23T21:09:05.944216+00:00 app[web.1]: => Run `rails server -h` for more startup options
2014-04-23T21:09:05.944216+00:00 app[web.1]: => Ctrl-C to shutdown server
2014-04-23T21:09:05.944216+00:00 app[web.1]: Started GET "/" for 67.169.92.237 at 2014-04-23 21:09:05 +0000
2014-04-23T21:09:05.944216+00:00 app[web.1]: Started GET "/" for 67.169.92.237 at 2014-04-23 21:09:05 +0000
2014-04-23T21:09:08.210054+00:00 app[web.1]: Processing by ApplicationController#index as HTML
2014-04-23T21:09:08.210054+00:00 app[web.1]: Processing by ApplicationController#index as HTML
2014-04-23T21:09:08.239227+00:00 app[web.1]:   Rendered application/index.html.erb within layouts/application (0.9ms)
2014-04-23T21:09:08.239227+00:00 app[web.1]:   Rendered application/index.html.erb within layouts/application (0.9ms)
2014-04-23T21:09:08.271897+00:00 heroku[router]: at=info method=GET path=/ host=artslot.herokuapp.com request_id=f5395cd5-4e00-4d9a-979d-6ad358b33a3a fwd="67.169.92.237" dyno=web.1 connect=6ms service=2367ms status=304 bytes=820
2014-04-23T21:09:08.432297+00:00 heroku[router]: at=info method=GET path=/assets/application-1c8ff196c2e39d33bb5c62b28dba7426.css host=artslot.herokuapp.com request_id=7f257454-b7d9-4c09-9ae1-133de79199e4 fwd="67.169.92.237" dyno=web.1 connect=0ms service=4ms status=304 bytes=133
2014-04-23T21:09:08.441339+00:00 heroku[router]: at=info method=GET path=/assets/application-7521f53a2cdda10ccbdb02603acc46e9.js host=artslot.herokuapp.com request_id=423e65eb-a3e8-41c3-b611-49f000601fd3 fwd="67.169.92.237" dyno=web.1 connect=1ms service=7ms status=304 bytes=133
2014-04-23T21:09:08.452496+00:00 heroku[router]: at=info method=GET path=/assets/vendor/modernizr-aee7c485b9900b5743cd0108ba6c4203.js host=artslot.herokuapp.com request_id=cad37bf0-a813-48dd-9dd5-8b1d57fb49d3 fwd="67.169.92.237" dyno=web.1 connect=6ms service=7ms status=304 bytes=133
2014-04-23T21:09:08.988730+00:00 heroku[router]: at=info method=GET path=/favicon.ico host=artslot.herokuapp.com request_id=bd9675a3-b338-4409-920a-605cfb34ab96 fwd="67.169.92.237" dyno=web.1 connect=1ms service=4ms status=304 bytes=133
2014-04-23T21:09:08.241372+00:00 app[web.1]: Completed 200 OK in 31ms (Views: 5.4ms | ActiveRecord: 0.0ms)
2014-04-23T21:09:08.241372+00:00 app[web.1]: Completed 200 OK in 31ms (Views: 5.4ms | ActiveRecord: 0.0ms)
2014-04-23T21:12:00.189756+00:00 heroku[api]: Starting process with command `bundle exec rake db:migrate` by [email protected]
2014-04-23T21:12:04.265328+00:00 heroku[run.3661]: Awaiting client
2014-04-23T21:12:04.342014+00:00 heroku[run.3661]: Starting process with command `bundle exec rake db:migrate`
2014-04-23T21:12:04.436971+00:00 heroku[run.3661]: State changed from starting to up
2014-04-23T21:12:23.595508+00:00 heroku[run.3661]: Process exited with status 0
2014-04-23T21:12:23.611644+00:00 heroku[run.3661]: State changed from up to complete
2014-04-23T21:12:42.205577+00:00 app[web.1]: Started GET "/" for 67.169.92.237 at 2014-04-23 21:12:42 +0000
2014-04-23T21:12:42.205577+00:00 app[web.1]: Started GET "/" for 67.169.92.237 at 2014-04-23 21:12:42 +0000
2014-04-23T21:12:42.217001+00:00 heroku[router]: at=info method=GET path=/ host=artslot.herokuapp.com request_id=74a0bfa8-fc4e-4743-bbcf-166e7854f087 fwd="67.169.92.237" dyno=web.1 connect=1ms service=10ms status=200 bytes=1771
2014-04-23T21:12:42.397848+00:00 heroku[router]: at=info method=GET path=/assets/vendor/modernizr-aee7c485b9900b5743cd0108ba6c4203.js host=artslot.herokuapp.com request_id=67050a5f-d2c6-4ed0-844c-e970b0d70e75 fwd="67.169.92.237" dyno=web.1 connect=1ms service=9ms status=200 bytes=11304
2014-04-23T21:12:42.400644+00:00 heroku[router]: at=info method=GET path=/assets/app
lication-1c8ff196c2e39d33bb5c62b28dba7426.css host=artslot.herokuapp.com request_id=0be05d98-f30d-49f6-a93f-28077b8466e2 fwd="67.169.92.237" dyno=web.1 connect=1ms service=14ms status=200 bytes=154145
2014-04-23T21:12:42.403702+00:00 heroku[router]: at=info method=GET path=/assets/application-7521f53a2cdda10ccbdb02603acc46e9.js host=artslot.herokuapp.com request_id=d11f58e8-56c4-4bb6-b4ec-1381cfee2689 fwd="67.169.92.237" dyno=web.1 connect=1ms service=15ms status=200 bytes=303416
2014-04-23T21:12:42.211004+00:00 app[web.1]: Completed 200 OK in 2ms (Views: 1.2ms | ActiveRecord: 0.0ms)
2014-04-23T21:12:42.211004+00:00 app[web.1]: Completed 200 OK in 2ms (Views: 1.2ms | ActiveRecord: 0.0ms)
2014-04-23T21:12:42.208919+00:00 app[web.1]: Processing by ApplicationController#index as HTML
2014-04-23T21:12:42.210188+00:00 app[web.1]:   Rendered application/index.html.erb within layouts/application (0.1ms)
2014-04-23T21:12:42.210188+00:00 app[web.1]:   Rendered application/index.html.erb within layouts/application (0.1ms)
2014-04-23T21:12:42.208919+00:00 app[web.1]: Processing by ApplicationController#index as HTML
2014-04-23T21:24:25+00:00 heroku[slug-compiler]: Slug compilation started
2014-04-23T21:24:47+00:00 heroku[slug-compiler]: Slug compilation finished
2014-04-23T21:24:47.431055+00:00 heroku[web.1]: State changed from up to starting
2014-04-23T21:24:47.151997+00:00 heroku[api]: Deploy 9b2229f by [email protected]
2014-04-23T21:24:47.152077+00:00 heroku[api]: Release v19 created by [email protected]
2014-04-23T21:24:49.977030+00:00 heroku[web.1]: Stopping all processes with SIGTERM
2014-04-23T21:24:50.541347+00:00 app[web.1]: [2014-04-23 21:24:50] FATAL SignalException: SIGTERM
2014-04-23T21:24:50.541347+00:00 app[web.1]:    /app/vendor/ruby-2.0.0/lib/ruby/2.0.0/webrick/server.rb:170:in `select'
2014-04-23T21:24:50.541347+00:00 app[web.1]:    /app/vendor/ruby-2.0.0/lib/ruby/2.0.0/webrick/server.rb:170:in `block in start'
2014-04-23T21:24:50.541600+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.4/lib/rails/commands.rb:71:in `<top (required)>'
2014-04-23T21:24:50.541347+00:00 app[web.1]:    /app/vendor/ruby-2.0.0/lib/ruby/2.0.0/webrick/server.rb:32:in `start'
2014-04-23T21:24:50.541347+00:00 app[web.1]:    /app/vendor/ruby-2.0.0/lib/ruby/2.0.0/webrick/server.rb:160:in `start'
2014-04-23T21:24:50.541347+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/handler/webrick.rb:14:in `run'
2014-04-23T21:24:50.541347+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/rack-1.5.2/lib/rack/server.rb:264:in `start'
2014-04-23T21:24:50.541347+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.4/lib/rails/commands/server.rb:84:in `start'
2014-04-23T21:24:50.541347+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.4/lib/rails/commands.rb:76:in `block in <top (required)>'
2014-04-23T21:24:50.541347+00:00 app[web.1]:    /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.4/lib/rails/commands.rb:71:in `tap'
2014-04-23T21:24:50.541600+00:00 app[web.1]:    bin/rails:4:in `require'
2014-04-23T21:24:50.541600+00:00 app[web.1]: [2014-04-23 21:24:50] INFO  going to shutdown ...
2014-04-23T21:24:50.541600+00:00 app[web.1]:    bin/rails:4:in `<main>'
2014-04-23T21:24:50.541600+00:00 app[web.1]: [2014-04-23 21:24:50] INFO  WEBrick::HTTPServer#start done.
2014-04-23T21:24:50.541600+00:00 app[web.1]: Exiting
2014-04-23T21:24:52.075006+00:00 heroku[web.1]: Starting process with command `bin/rails server -p 9064 -e production`
2014-04-23T21:24:51.773315+00:00 heroku[web.1]: Process exited with status 143
2014-04-23T21:24:57.244913+00:00 app[web.1]: [2014-04-23 21:24:57] INFO  WEBrick 1.3.1
2014-04-23T21:24:57.244913+00:00 app[web.1]: [2014-04-23 21:24:57] INFO  ruby 2.0.0 (2014-02-24) [x86_64-linux]
2014-04-23T21:24:57.244913+00:00 app[web.1]: [2014-04-23 21:24:57] INFO  WEBrick::HTTPServer#start: pid=2 port=9064
2014-04-23T21:24:57.702318+00:00 heroku[web.1]: State changed from starting to up
2014-04-23T21:29:13.588795+00:00 app[web.1]: => Booting WEBrick
2014-04-23T21:29:13.588795+00:00 app[web.1]: => Ctrl-C to shutdown server
2014-04-23T21:29:13.588795+00:00 app[web.1]: => Rails 4.0.4 application starting in production on http://0.0.0.0:9064
2014-04-23T21:29:13.588795+00:00 app[web.1]: => Run `rails server -h` for more startup options
2014-04-23T21:29:13.592113+00:00 app[web.1]: Started GET "/" for 67.169.92.237 at 2014-04-23 21:29:13 +0000
2014-04-23T21:29:13.588795+00:00 app[web.1]: Started GET "/" for 67.169.92.237 at 2014-04-23 21:29:13 +0000
2014-04-23T21:29:32.372120+00:00 app[web.1]: Processing by ApplicationController#index as HTML
2014-04-23T21:29:32.372120+00:00 app[web.1]: Processing by ApplicationController#index as HTML
2014-04-23T21:29:32.398081+00:00 app[web.1]:   Rendered application/index.html.erb within layouts/application (0.6ms)
2014-04-23T21:29:32.398081+00:00 app[web.1]:   Rendered application/index.html.erb within layouts/application (0.6ms)
2014-04-23T21:29:32.402368+00:00 heroku[router]: at=info method=GET path=/ host=artslot.herokuapp.com request_id=1992fc

Answer 1

When a dyno shuts down, for example as part of a daily restart or as part of sleeping or a new release (as you have in your example) then Heroku has to shut down the processes running in the dyno.

It does this by sending a SIGTERM to the processes.

The logs you show are consistent with this behavior.

Indeed, if I run a webrick server locally, and shut it down with SIGTERM (kill -SIGTERM <pid>), it behaves in exactly the same way.

ruby x.rb [2014-04-24 09:34:46] INFO WEBrick 1.3.1 [2014-04-24 09:34:46] INFO ruby 2.0.0 (2013-06-27) [x86_64-darwin12.4.1] [2014-04-24 09:34:46] INFO WEBrick::HTTPServer#start: pid=66968 port=1234 [2014-04-24 09:35:04] FATAL SignalException: SIGTERM /Users/jonmountjoy/.rubies/2.0.0-p247/lib/ruby/2.0.0/webrick/server.rb:170:in `select' /Users/jonmountjoy/.rubies/2.0.0-p247/lib/ruby/2.0.0/webrick/server.rb:170:in `block in start' /Users/jonmountjoy/.rubies/2.0.0-p247/lib/ruby/2.0.0/webrick/server.rb:32:in `start' /Users/jonmountjoy/.rubies/2.0.0-p247/lib/ruby/2.0.0/webrick/server.rb:160:in `start' x.rb:5:in `<main>' [2014-04-24 09:35:04] INFO going to shutdown ... [2014-04-24 09:35:04] INFO WEBrick::HTTPServer#start done.