Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

rake sneakers:run sometimes ignores SIGINT #41

Closed
abevoelker opened this issue Apr 14, 2014 · 3 comments
Closed

rake sneakers:run sometimes ignores SIGINT #41

abevoelker opened this issue Apr 14, 2014 · 3 comments

Comments

@abevoelker
Copy link
Contributor

Sometimes when running the rake task, the workers do not respond to SIGINT. I send a Ctrl+c and it says it's shutting down workers, but it doesn't. In fact I can hold Ctrl+c and it just floods the screen with "Shutting down workers" messages, but doesn't shut everything down. If I send the rake task to background with Ctrl+z and try to kill the PID, it likewise doesn't respond. I end up having to kill -9 it.

In my initializer I have :daemonize => false, in case that's relevant.

Here is the console output from a run I just had where this occurred (sorry for the weird linebreaks, copied+pasted from my console):

^C2014-04-13T22:59:48Z p-23076 t-os3pt2j64 INFO: Heartbeat: running threads [54]
2014-04-13T22:59:48Z p-23076 t-os3q5m354 INFO: Shutting down workers
2014-04-13T22:59:48Z p-23076 t-os3q5m354 DEBUG: [worker-store1:1:hhkhcb][#<ServerEngine::SignalThread:0x007f
29e3d16cd0>][store1][{:runner_config_file=>nil, :metrics=>nil, :daemonize=>false, :start_worker_delay=>0.2, 
:workers=>4, :log=>#<IO:<STDOUT>>, :pid_path=>"sneakers.pid", :timeout_job_after=>30, :prefetch=>15, :threads=>15, :dur
able=>true, :ack=>true, :heartbeat=>2, :amqp=>"amqp://foo:bar@10.0.3.6:5672", :vhost=>"/", :exchange=>"sneakers", :exchange_type=>:dir
ect, :hooks=>{}, :handler=>Sneakers::Handlers::Oneshot}] Stopping worker: unsubscribing.
2014-04-13T22:59:48Z p-23076 t-os3q5m354 DEBUG: [worker-store1:1:hhkhcb][#<ServerEngine::SignalThread:0x007f
29e3d16cd0>][store1][{:runner_config_file=>nil, :metrics=>nil, :daemonize=>false, :start_worker_delay=>0.2, 
:workers=>4, :log=>#<IO:<STDOUT>>, :pid_path=>"sneakers.pid", :timeout_job_after=>30, :prefetch=>15, :threads=>15, :dur
able=>true, :ack=>true, :heartbeat=>2, :amqp=>"amqp://foo:bar@10.0.3.6:5672", :vhost=>"/", :exchange=>"sneakers", :exchange_type=>:dir
ect, :hooks=>{}, :handler=>Sneakers::Handlers::Oneshot}] Stopping worker: I'm gone.
2014-04-13T22:59:48Z p-23076 t-os3q5m354 DEBUG: [worker-store2:1:fm59b2][#<ServerEngine::SignalThread:0x007f29e3
d16cd0>][store2][{:runner_config_file=>nil, :metrics=>nil, :daemonize=>false, :start_worker_delay=>0.2, :workers
=>4, :log=>#<IO:<STDOUT>>, :pid_path=>"sneakers.pid", :timeout_job_after=>30, :prefetch=>15, :threads=>15, :durable=>tr
ue, :ack=>true, :heartbeat=>2, :amqp=>"amqp://foo:bar@10.0.3.6:5672", :vhost=>"/", :exchange=>"sneakers", :exchange_type=>:direct, :ho
oks=>{}, :handler=>Sneakers::Handlers::Oneshot}] Stopping worker: unsubscribing.
Unexpected error Trying to send frame through a closed connection. Frame is #<AMQ::Protocol::MethodFrame:0x007f29ac0694
10 @payload="\x00<\x00\x1E bunny-1397429831000-559756359092\x00", @channel=2>, method class is AMQ::Protocol::Basic::Ca
ncel
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/bunny-1.1.9/lib/bunny/session.rb:846:in `send_frame
'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/bunny-1.1.9/lib/bunny/channel.rb:917:in `basic_canc
el'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/bunny-1.1.9/lib/bunny/consumer.rb:84:in `cancel'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/queue.rb:48:in `uns
ubscribe'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/worker.rb:93:in `st
op'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/workergroup.rb:40:i
n `block in stop'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/workergroup.rb:39:i
n `each'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/workergroup.rb:39:i
n `stop'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/serverengine-1.5.7/lib/serverengine/worker.rb:60:in
 `block (2 levels) in install_signal_handlers'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/serverengine-1.5.7/lib/serverengine/signal_thread.r
b:98:in `call'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/serverengine-1.5.7/lib/serverengine/signal_thread.r
b:98:in `main'
^C2014-04-13T22:59:48Z p-23076 t-os3pt2j64 INFO: Heartbeat: running threads [54]
2014-04-13T22:59:48Z p-23076 t-os3q5m354 INFO: Shutting down workers
2014-04-13T22:59:48Z p-23076 t-os3q5m354 DEBUG: [worker-store1:1:hhkhcb][#<ServerEngine::SignalThread:0x007f
29e3d16cd0>][store1][{:runner_config_file=>nil, :metrics=>nil, :daemonize=>false, :start_worker_delay=>0.2, :workers=>4, :log=>#<IO:<STDOUT>>, :pid_path=>"sneakers.pid", :timeout_job_after=>30, :prefetch=>15, :threads=>15, :dur
able=>true, :ack=>true, :heartbeat=>2, :amqp=>"amqp://foo:bar@10.0.3.6:5672", :vhost=>"/", :exchange=>"sneakers", :exchange_type=>:dir
ect, :hooks=>{}, :handler=>Sneakers::Handlers::Oneshot}] Stopping worker: unsubscribing.
2014-04-13T22:59:48Z p-23076 t-os3q5m354 DEBUG: [worker-store1:1:hhkhcb][#<ServerEngine::SignalThread:0x007f
29e3d16cd0>][store1][{:runner_config_file=>nil, :metrics=>nil, :daemonize=>false, :start_worker_delay=>0.2, 
:workers=>4, :log=>#<IO:<STDOUT>>, :pid_path=>"sneakers.pid", :timeout_job_after=>30, :prefetch=>15, :threads=>15, :dur
able=>true, :ack=>true, :heartbeat=>2, :amqp=>"amqp://foo:bar@10.0.3.6:5672", :vhost=>"/", :exchange=>"sneakers", :exchange_type=>:dir
ect, :hooks=>{}, :handler=>Sneakers::Handlers::Oneshot}] Stopping worker: I'm gone.
2014-04-13T22:59:48Z p-23076 t-os3q5m354 DEBUG: [worker-store2:1:fm59b2][#<ServerEngine::SignalThread:0x007f29e3
d16cd0>][store2][{:runner_config_file=>nil, :metrics=>nil, :daemonize=>false, :start_worker_delay=>0.2, :workers
=>4, :log=>#<IO:<STDOUT>>, :pid_path=>"sneakers.pid", :timeout_job_after=>30, :prefetch=>15, :threads=>15, :durable=>tr
ue, :ack=>true, :heartbeat=>2, :amqp=>"amqp://foo:bar@10.0.3.6:5672", :vhost=>"/", :exchange=>"sneakers", :exchange_type=>:direct, :ho
oks=>{}, :handler=>Sneakers::Handlers::Oneshot}] Stopping worker: unsubscribing.
Unexpected error Trying to send frame through a closed connection. Frame is #<AMQ::Protocol::MethodFrame:0x007f29ac0731
18 @payload="\x00<\x00\x1E bunny-1397429831000-559756359092\x00", @channel=2>, method class is AMQ::Protocol::Basic::Ca
ncel
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/bunny-1.1.9/lib/bunny/session.rb:846:in `send_frame
'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/bunny-1.1.9/lib/bunny/channel.rb:917:in `basic_canc
el'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/bunny-1.1.9/lib/bunny/consumer.rb:84:in `cancel'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/queue.rb:48:in `uns
ubscribe'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/worker.rb:93:in `st
op'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/workergroup.rb:40:i
n `block in stop'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/workergroup.rb:39:i
n `each'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/workergroup.rb:39:i
n `stop'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/serverengine-1.5.7/lib/serverengine/worker.rb:60:in
 `block (2 levels) in install_signal_handlers'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/serverengine-1.5.7/lib/serverengine/signal_thread.r
b:98:in `call'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/serverengine-1.5.7/lib/serverengine/signal_thread.r
b:98:in `main'
^C2014-04-13T22:59:48Z p-23076 t-os3pt2j64 INFO: Heartbeat: running threads [54]
2014-04-13T22:59:48Z p-23076 t-os3q5m354 INFO: Shutting down workers
2014-04-13T22:59:48Z p-23076 t-os3q5m354 DEBUG: [worker-store1:1:hhkhcb][#<ServerEngine::SignalThread:0x007f
29e3d16cd0>][store1][{:runner_config_file=>nil, :metrics=>nil, :daemonize=>false, :start_worker_delay=>0.2, 
:workers=>4, :log=>#<IO:<STDOUT>>, :pid_path=>"sneakers.pid", :timeout_job_after=>30, :prefetch=>15, :threads=>15, :dur
able=>true, :ack=>true, :heartbeat=>2, :amqp=>"amqp://foo:bar@10.0.3.6:5672", :vhost=>"/", :exchange=>"sneakers", :exchange_type=>:dir
ect, :hooks=>{}, :handler=>Sneakers::Handlers::Oneshot}] Stopping worker: unsubscribing.
2014-04-13T22:59:48Z p-23076 t-os3q5m354 DEBUG: [worker-store1:1:hhkhcb][#<ServerEngine::SignalThread:0x007f
29e3d16cd0>][store1][{:runner_config_file=>nil, :metrics=>nil, :daemonize=>false, :start_worker_delay=>0.2, 
:workers=>4, :log=>#<IO:<STDOUT>>, :pid_path=>"sneakers.pid", :timeout_job_after=>30, :prefetch=>15, :threads=>15, :dur
able=>true, :ack=>true, :heartbeat=>2, :amqp=>"amqp://foo:bar@10.0.3.6:5672", :vhost=>"/", :exchange=>"sneakers", :exchange_type=>:dir
ect, :hooks=>{}, :handler=>Sneakers::Handlers::Oneshot}] Stopping worker: I'm gone.
2014-04-13T22:59:48Z p-23076 t-os3q5m354 DEBUG: [worker-store2:1:fm59b2][#<ServerEngine::SignalThread:0x007f29e3
d16cd0>][store2][{:runner_config_file=>nil, :metrics=>nil, :daemonize=>false, :start_worker_delay=>0.2, :workers
=>4, :log=>#<IO:<STDOUT>>, :pid_path=>"sneakers.pid", :timeout_job_after=>30, :prefetch=>15, :threads=>15, :durable=>tr
ue, :ack=>true, :heartbeat=>2, :amqp=>"amqp://foo:bar@10.0.3.6:5672", :vhost=>"/", :exchange=>"sneakers", :exchange_type=>:direct, :ho
oks=>{}, :handler=>Sneakers::Handlers::Oneshot}] Stopping worker: unsubscribing.
Unexpected error Trying to send frame through a closed connection. Frame is #<AMQ::Protocol::MethodFrame:0x007f29ac0796
08 @payload="\x00<\x00\x1E bunny-1397429831000-559756359092\x00", @channel=2>, method class is AMQ::Protocol::Basic::Ca
ncel
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/bunny-1.1.9/lib/bunny/session.rb:846:in `send_frame
'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/bunny-1.1.9/lib/bunny/channel.rb:917:in `basic_canc
el'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/bunny-1.1.9/lib/bunny/consumer.rb:84:in `cancel'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/queue.rb:48:in `uns
ubscribe'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/worker.rb:93:in `st
op'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/workergroup.rb:40:i
n `block in stop'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/workergroup.rb:39:i
n `each'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/sneakers-0.1.1.pre/lib/sneakers/workergroup.rb:39:i
n `stop'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/serverengine-1.5.7/lib/serverengine/worker.rb:60:in
 `block (2 levels) in install_signal_handlers'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/serverengine-1.5.7/lib/serverengine/signal_thread.r
b:98:in `call'
  /home/vagrant/.rbenv/versions/2.0.0-p451/lib/ruby/gems/2.0.0/gems/serverengine-1.5.7/lib/serverengine/signal_thread.r
b:98:in `main'
^Z
[1]+  Stopped                 rake sneakers:run
vagrant@precise-base:/vagrant$ ps aux | grep rake
vagrant  22926  2.6  0.4 1224600 32580 pts/1   Tl   22:57   0:04 ruby /home/vagrant/.rbenv/versions/2.0.0-p451/bin/rake
 sneakers:run
vagrant  23076  5.8  2.1 3080344 176568 pts/1  Tl   22:57   0:09 ruby /home/vagrant/.rbenv/versions/2.0.0-p451/bin/rake
 sneakers:run
vagrant  26499  0.0  0.0   8112   932 pts/1    S+   22:59   0:00 grep rake
vagrant@precise-base:/vagrant$ kill 22926
vagrant@precise-base:/vagrant$ kill 23076
vagrant@precise-base:/vagrant$ ps aux | grep rake
vagrant  22926  2.3  0.4 1224600 32584 pts/1   Tl   22:57   0:04 ruby /home/vagrant/.rbenv/versions/2.0.0-p451/bin/rake
 sneakers:run
vagrant  23076  5.1  2.1 3080344 176572 pts/1  Tl   22:57   0:09 ruby /home/vagrant/.rbenv/versions/2.0.0-p451/bin/rake
 sneakers:run
vagrant@precise-base:/vagrant$ kill -9 22926
vagrant@precise-base:/vagrant$ kill -9 23076
-bash: kill: (23076) - No such process
[1]+  Killed                  rake sneakers:run
@jondot
Copy link
Owner

jondot commented Apr 14, 2014

Hi Abe, what you're describing has to do with how Ruby 1.9 and 2.0 handle signals (it somehow changed). I have contributed a fix to server_engine that resolved a similar issue (the process management gem Sneakers relies on) in the past, and from my knowledge Sidekiq has same problems.
If this problem poped up again - I would guess it has to do with either an old gem or a new gem re-introducing the issues.

To get some more insights I would love to have a look at the Gemfile.lock you were using at the time of this issue. If you could please gist it, I'd be happy to try and help.

@abevoelker
Copy link
Contributor Author

Sure, here you go: https://gist.github.com/abevoelker/3550ea9005317d63ad27

(Gist stupidly tries to syntax highlight it as JSON, even when I try to override it w/ Text)

@abevoelker abevoelker mentioned this issue Apr 14, 2014
Closed
@kke
Copy link
Contributor

kke commented Apr 27, 2014

Just a guess, maybe you have

rescue Exception => e

somewhere? It will catch ctrl-c and SIGTERM

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@jondot @abevoelker @kke