cloudfoundry/dea_ng — pull request #132 by julz (2014-05-29 14:08:39+00:00)
Title: Run signal handlers in an EM thread to prevent deadlocks

Steno takes a lock when writing log messages. When a signal handler runs
it can pre-empt the code while the lock is still active. When the trap
handler then tries to log it attempts to grab the same lock, and
deadlocks. We've seen this cause hangs during shutdown when we upgrade
DEAs.

Example message from our logs below: you can see the two calls to steno from the signal handler and from reap_unreferenced_droplets that both attempt to get the same lock [in steno/io.rb#L50](https://github.com/cloudfoundry/steno/blob/master/lib/steno/sink/io.rb#L50):

~~~~
:8:in `lock': deadlock; recursive locking (ThreadError)
from :8:in `synchronize'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/sink/io.rb:50:in `add_record'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/logger.rb:138:in `block in log'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/logger.rb:138:in `each'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/logger.rb:138:in `log'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/logger.rb:27:in `block in define_log_method'
from /var/vcap/packages/dea_next/lib/dea/lifecycle/signal_handler.rb:24:in `block (2 levels) in setup'
from :8:in `call'
from :8:in `synchronize'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/sink/io.rb:50:in `add_record'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/logger.rb:138:in `block in log'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/logger.rb:138:in `each'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/logger.rb:138:in `log'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/tagged_logger.rb:46:in `log'
from /var/vcap/packages/dea_next/vendor/cache/steno-d88c70767c43/lib/steno/tagged_logger.rb:17:in `block in define_log_method'
from /var/vcap/packages/dea_next/lib/dea/droplet.rb:90:in `destroy'
from /var/vcap/packages/dea_next/lib/dea/bootstrap.rb:322:in `block in reap_unreferenced_droplets'
from /var/vcap/packages/ruby/lib/ruby/1.9.1/set.rb:222:in `block in each'
from /var/vcap/packages/ruby/lib/ruby/1.9.1/set.rb:222:in `each_key'
from /var/vcap/packages/ruby/lib/ruby/1.9.1/set.rb:222:in `each'
from /var/vcap/packages/dea_next/lib/dea/bootstrap.rb:318:in `reap_unreferenced_droplets'
from /var/vcap/packages/dea_next/lib/dea/bootstrap.rb:226:in `block in setup_sweepers'
from /var/vcap/packages/dea_next/vendor/bundle/ruby/1.9.1/gems/eventmachine-1.0.3/lib/em/timers.rb:56:in `call'
from /var/vcap/packages/dea_next/vendor/bundle/ruby/1.9.1/gems/eventmachine-1.0.3/lib/em/timers.rb:56:in `fire'
from /var/vcap/packages/dea_next/vendor/bundle/ruby/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `call'
from /var/vcap/packages/dea_next/vendor/bundle/ruby/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run_machine'
from /var/vcap/packages/dea_next/vendor/bundle/ruby/1.9.1/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run'
from /var/vcap/packages/dea_next/bin/dea:28:in `

'
~~~~

Ideally I would've just removed the log message, since signal handlers should avoid doing things that need to take locks, but there's enough logic in the signal handling that I can imagine other things log/rely on locks, so the safest solution seems to be to ask EventMachine to run the signal handler asynchronously.