Can't be called from trap contex error from DaemonKit::AMQP blocks in Ruby 2

[Sephi-Chan]

Hello!

With Ruby 2, AMQP daemons doesn't react well to Ctrl-C.

DaemonKit::Application.running! do |config|
  config.trap('TERM') do
    puts 'Going down.'
  end
end

DaemonKit::AMQP.run do |connection|
  puts "I'm running..."
end

And when I run it then shut it down…

$ bin/communication_server
[daemon-kit]: DaemonKit (0.2.3) booting in development mode
[daemon-kit]: Setting up trap for USR1
[daemon-kit]: Setting up trap for USR2
[daemon-kit]: Setting up trap for HUP
[daemon-kit]: Setting up trap for INT
[daemon-kit]: Setting up trap for TERM
[daemon-kit]: DaemonKit (0.2.3) booted, now running seelies_communication_server
[daemon-kit]: AMQP.start({:user=>"guest", :pass=>"guest", :host=>"localhost", :vhost=>"/"})
I'm running...
^Clog writing failed. can't be called from trap context
[daemon-kit]: Running signal traps for INT
[daemon-kit]: Running shutdown hooks
[daemon-kit]: Shutting down seelies_communication_server
/Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:1087:in `synchronize': can't be called from trap context (ThreadError)
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:1087:in `next_tick'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/amqp-1.0.2/lib/amqp/connection.rb:63:in `stop'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/dk_amqp.rb:31:in `block in run'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/initializer.rb:346:in `call'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/initializer.rb:346:in `block in run_traps'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/initializer.rb:346:in `each'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/initializer.rb:346:in `run_traps'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/initializer.rb:354:in `block in set_trap'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `call'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run_machine'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/amqp-1.0.2/lib/amqp/connection.rb:38:in `start'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/dk_amqp.rb:36:in `run'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/dk_amqp.rb:21:in `run'
    from /Users/romaintribes/Seelies/communication_server/libexec/communication_server-daemon.rb:6:in `<top (required)>'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/activesupport-4.0.0/lib/active_support/dependencies.rb:228:in `require'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/activesupport-4.0.0/lib/active_support/dependencies.rb:228:in `block in require'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/activesupport-4.0.0/lib/active_support/dependencies.rb:213:in `load_dependency'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/activesupport-4.0.0/lib/active_support/dependencies.rb:228:in `require'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/application.rb:38:in `run'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.3/lib/daemon_kit/application.rb:21:in `exec'
    from bin/communication_server:3:in `<main>'

Searching for this error led me to this Ruby ticket (https://bugs.ruby-lang.org/issues/7917) that states the error is code-related.

Do you have any idea about how to fix it?

[marcbowes]

I had a quick read through the ticket and stack trace. It sounds like the version of AMQP you're using is trying to take a lock on a mutex while stopping. The current HEAD of ruby-amqp/amqp doesn't have the file connection.rb referenced by your stack trace. Have you tried upgrading? Can you repro this with a amqp-only repository?

[Sephi-Chan]

No more luck using the master of AQMP gem (1.1.0.pre3wip as of today).

$ bin/game_runner
[daemon-kit]: DaemonKit (0.2.1) booting in development mode
[daemon-kit]: Setting up trap for USR1
[daemon-kit]: Setting up trap for USR2
[daemon-kit]: Setting up trap for HUP
[daemon-kit]: Setting up trap for INT
[daemon-kit]: Setting up trap for TERM
[daemon-kit]: DaemonKit (0.2.1) booted, now running seelies_game_runner
Running AMQP gem version 1.1.0.pre3wip.
[daemon-kit]: AMQP.start({:user=>"guest", :pass=>"guest", :host=>"localhost", :vhost=>"/"})
^Clog writing failed. can't be called from trap context
[daemon-kit]: Running signal traps for INT
[daemon-kit]: Running shutdown hooks
[daemon-kit]: Shutting down seelies_game_runner
/Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:1087:in `synchronize': can't be called from trap context (ThreadError)
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:1087:in `next_tick'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/bundler/gems/amqp-e7e5d31685e5/lib/amqp.rb:81:in `stop'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/dk_amqp.rb:31:in `block in run'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/initializer.rb:346:in `call'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/initializer.rb:346:in `block in run_traps'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/initializer.rb:346:in `each'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/initializer.rb:346:in `run_traps'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/initializer.rb:354:in `block in set_trap'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `call'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run_machine'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/bundler/gems/amqp-e7e5d31685e5/lib/amqp.rb:56:in `start'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/dk_amqp.rb:36:in `run'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/dk_amqp.rb:21:in `run'
    from /Users/romaintribes/Seelies/game_runner/libexec/game_runner-daemon.rb:9:in `<top (required)>'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/activesupport-4.0.0/lib/active_support/dependencies.rb:228:in `require'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/activesupport-4.0.0/lib/active_support/dependencies.rb:228:in `block in require'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/activesupport-4.0.0/lib/active_support/dependencies.rb:213:in `load_dependency'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/activesupport-4.0.0/lib/active_support/dependencies.rb:228:in `require'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/application.rb:38:in `run'
    from /Users/romaintribes/.rbenv/versions/2.0.0-p247/lib/ruby/gems/2.0.0/gems/daemon-kit-0.2.1/lib/daemon_kit/application.rb:21:in `exec'
    from bin/game_runner:3:in `<main>'

I'll try with a plain old AMQP listener as soon as possible.

[marcbowes]

All we do in the trap block is to tell AMQP to shutdown. This calls EM.next_tick. You can see this here: https://github.com/ruby-amqp/amqp/blob/master/lib/amqp.rb#L81. This is going to take a lock to try and enqueue the work to shutdown.

I don't think this is a DK problem. Open a ticket with AMQP and ask them how they suggest graceful shutdown should be implemented given the 2.0 restrictions. We can then do as they suggest.

[kennethkalmer]

Just to add, I'm seeing the same thing on master with Ruby 2.0.0-p247, but with a vanilla project (while testing #73) out.

Investigating some more

[kennethkalmer]

Oh boy, looks like an issue with MRI 2.0.0, and it will be our issue to deal with - https://bugs.ruby-lang.org/issues/7917

[kennethkalmer]

Our answer lies somewhere in sidekiq/sidekiq@dfc7e35b11ba and the two commits that follow, possibly a few before too...