Broker shutdown causes an unhandled exception in reader loop

[ssimeonov]

When there is an option connection to the broker and the broker is shutdown, the following output is generated when the level is set to :debug. Why is the "handling" of the exception allowing it to leave the thread (and terminate an application where Thread.abort_on_exception is set to true)?

Handling a connection-level exception.

AMQP class id : 0
AMQP method id: 0
Status code   : 320
Error message : CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'
Session#handle_frame on 0: #<AMQ::Protocol::Connection::Close:0x000000055d25c8 @reply_code=320, @reply_text="CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'", @class_id=0, @method_id=0>
Exception in the reader loop: Bunny::ConnectionForced: Connection-level error: CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'
Backtrace:
    /opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/session.rb:395:in `handle_frame'
    /opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/reader_loop.rb:75:in `run_once'
    /opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/reader_loop.rb:34:in `block in run_loop'
    /opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/reader_loop.rb:31:in `loop'
    /opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/reader_loop.rb:31:in `run_loop'
/usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/input-method.rb:115:in `getbyte': caught an unexpected exception in the network loop: Connection-level error: CONNECTION_FORCED - broker forced connection closure with reason 'shutdown' (Bunny::NetworkFailure)
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/input-method.rb:115:in `readline'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/input-method.rb:115:in `gets'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb.rb:139:in `block (2 levels) in eval_input'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb.rb:273:in `signal_status'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb.rb:138:in `block in eval_input'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:188:in `call'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:188:in `buf_input'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:103:in `getc'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/slex.rb:205:in `match_io'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/slex.rb:75:in `match'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:286:in `token'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:262:in `lex'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:233:in `block (2 levels) in each_top_level_statement'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:229:in `loop'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:229:in `block in each_top_level_statement'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:228:in `catch'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb/ruby-lex.rb:228:in `each_top_level_statement'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb.rb:155:in `eval_input'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb.rb:70:in `block in start'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb.rb:69:in `catch'
    from /usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/irb.rb:69:in `start'
    from /opt/internal/vendor/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/commands/console.rb:47:in `start'
    from /opt/internal/vendor/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/commands/console.rb:8:in `start'
    from /opt/internal/vendor/bundle/ruby/1.9.1/gems/railties-3.2.13/lib/rails/commands.rb:41:in `<top (required)>'
    from script/rails:6:in `require'
    from script/rails:6:in `<main>'

[michaelklishin]

Sorry, I do not understand what you are asking.

How are you shutting down RabbitMQ? Are you sure you are not getting Bunny::ConnectionForced that you can handle? What thread are you referring to, the reader loop one?

[ssimeonov]

I had a rescue Exception => e block that was getting skipped and the entire Rails console process was terminated which suggested that, despite the stack trace suggesting that the exception came on the main thread it looked like it originated on a separate thread. My code changed substantially since I created this issue and I no longer see this problem on RabbitMQ shutdown: the rescue block catches the error now.

[michaelklishin]

Good to know. This has lead me to the following thought: should we always raise exceptions when connection is forcefully closed? Presumably reconnecting in that case is not what you typically want.

[ssimeonov]

Good point. I don't think there is a perfect automated solution. I see two common use cases:

1. The shutdown is temporary: a restart needed for redeployment or settings changes, etc. In that case, a period of connection retries is probably smart but, after a certain threshold, it is likely that we are in use case (2). I have done three such restarts in the last 24 hours.
2. The shutdown is not (very) temporary and it makes sense to release clients as opposed to block them.

I would suggest having a configurable parameter: the threshold after which you raise an exception after a forced connection close.

[carlhoerberg]

require 'bunny'
begin
  conn = Bunny.new(:heartbeat_interval => 8, :automatically_recover => false)
  conn.start

  ch = conn.create_channel
  x = ch.default_exchange
  q = ch.queue("mq", :durable => true)
  q.purge

  loop do
    body = "0" * 1024
    x.publish(body, :routing_key => "mq")
    _, _, payload = q.pop
    sleep 1
  end
rescue Exception => e
  puts e
  sleep 1
  retry
end

on rabbitmqctl stop_app this app outputs this and exits:

E, [2013-08-26T21:38:50.652731 #47124] ERROR -- #<Bunny::Session:70147311113360 [email protected]:5672, vhost=/>: Exception in the reader loop: AMQ::Protocol::EmptyResponseError: Empty response received from the server.
E, [2013-08-26T21:38:50.652908 #47124] ERROR -- #<Bunny::Session:70147311113360 [email protected]:5672, vhost=/>: Backtrace: 
E, [2013-08-26T21:38:50.652996 #47124] ERROR -- #<Bunny::Session:70147311113360 [email protected]:5672, vhost=/>:     /Users/carl/.rbenv/versions/2.0.0-p195/lib/ruby/gems/2.0.0/gems/amq-protocol-1.7.0/lib/amq/protocol/frame.rb:60:in `decode_header'
E, [2013-08-26T21:38:50.653054 #47124] ERROR -- #<Bunny::Session:70147311113360 [email protected]:5672, vhost=/>:     /Users/carl/.rbenv/versions/2.0.0-p195/lib/ruby/gems/2.0.0/gems/bunny-1.0.0.pre4/lib/bunny/transport.rb:216:in `read_next_frame'
E, [2013-08-26T21:38:50.653097 #47124] ERROR -- #<Bunny::Session:70147311113360 [email protected]:5672, vhost=/>:     /Users/carl/.rbenv/versions/2.0.0-p195/lib/ruby/gems/2.0.0/gems/bunny-1.0.0.pre4/lib/bunny/reader_loop.rb:63:in `run_once'
E, [2013-08-26T21:38:50.654589 #47124] ERROR -- #<Bunny::Session:70147311113360 [email protected]:5672, vhost=/>:     /Users/carl/.rbenv/versions/2.0.0-p195/lib/ruby/gems/2.0.0/gems/bunny-1.0.0.pre4/lib/bunny/reader_loop.rb:33:in `block in run_loop'
E, [2013-08-26T21:38:50.654663 #47124] ERROR -- #<Bunny::Session:70147311113360 [email protected]:5672, vhost=/>:     /Users/carl/.rbenv/versions/2.0.0-p195/lib/ruby/gems/2.0.0/gems/bunny-1.0.0.pre4/lib/bunny/reader_loop.rb:30:in `loop'
E, [2013-08-26T21:38:50.654709 #47124] ERROR -- #<Bunny::Session:70147311113360 [email protected]:5672, vhost=/>:     /Users/carl/.rbenv/versions/2.0.0-p195/lib/ruby/gems/2.0.0/gems/bunny-1.0.0.pre4/lib/bunny/reader_loop.rb:30:in `run_loop'
app.rb:32:in `write': detected a network failure: Empty response received from the server. (Bunny::NetworkFailure)
    from app.rb:32:in `puts'
    from app.rb:32:in `puts'
    from app.rb:32:in `rescue in <main>'
    from app.rb:5:in `<main>'

[michaelklishin]

@carlhoerberg what is your point? You are getting an exception because stop_app sends connection.close. I recalled we enforce an exception in that case, because there are no better options.

[carlhoerberg]

But I can't catch it?
On Aug 26, 2013 11:23 PM, "Michael Klishin" [email protected]
wrote:

@carlhoerberg https://github.com/carlhoerberg what is your point? You
are getting an exception because stop_app sends connection.closed. I
recalled we enforce an exception in that case, because there are no better
options.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/138#issuecomment-23294627
.

[michaelklishin]

It happens on a socket write attempt. Using single threaded or disabling automatic recovery will cause it to be raised on the connection thread.

[michaelklishin]

Actually, not exactly so: before connection.close is handled, the peer socket is closed which causes an empty read which is considered a network failure. It's a tricky thing to cover.