Bunny Not Accepting Heartbeat of 0

[mmmries]

According to the Bunny docs (http://rubybunny.info/articles/connecting.html) the default value for :heartbeat is 0 (meaning no heartbeats will take place). I'm pretty sure this configuration used to work, but with recent versions of the gem if I set :heartbeat => 0 in my config hash, bunny fails to connect.

[michaelklishin]

Any details on "fails to connect"?

[mmmries]

I get continual output like this:

E, [2014-11-07T09:45:54.204449 #20395] ERROR -- #<Bunny::Session:70347958486140 guest@po-sand-peter3:5672, vhost=/, hosts=[po-sand-peter3,po-sand-peter1,po-sand-peter2]>: Got an exception when receiving data: IO timeout when reading 7 bytes (Timeout::Error)
W, [2014-11-07T09:45:54.204535 #20395]  WARN -- #<Bunny::Session:70347958486140 guest@po-sand-peter3:5672, vhost=/, hosts=[po-sand-peter3,po-sand-peter1,po-sand-peter2]>: Recovering from a network failure...
W, [2014-11-07T09:45:55.205861 #20395]  WARN -- #<Bunny::Session:70347958486140 guest@po-sand-peter1:5672, vhost=/, hosts=[po-sand-peter3,po-sand-peter1,po-sand-peter2]>: Retrying connection on next host in line: po-sand-peter1:5672
E, [2014-11-07T09:45:55.555801 #20395] ERROR -- #<Bunny::Session:70347958486140 guest@po-sand-peter1:5672, vhost=/, hosts=[po-sand-peter3,po-sand-peter1,po-sand-peter2]>: Got an exception when receiving data: IO timeout when reading 7 bytes (Timeout::Error)
W, [2014-11-07T09:45:55.555902 #20395]  WARN -- #<Bunny::Session:70347958486140 guest@po-sand-peter1:5672, vhost=/, hosts=[po-sand-peter3,po-sand-peter1,po-sand-peter2]>: An empty frame was received while opening the connection. In RabbitMQ <= 3.1 this could mean an authentication issue.
W, [2014-11-07T09:45:55.555963 #20395]  WARN -- #<Bunny::Session:70347958486140 guest@po-sand-peter2:5672, vhost=/, hosts=[po-sand-peter3,po-sand-peter1,po-sand-peter2]>: Retrying connection on next host in line: po-sand-peter2:5672
E, [2014-11-07T09:45:55.963768 #20395] ERROR -- #<Bunny::Session:70347958486140 guest@po-sand-peter2:5672, vhost=/, hosts=[po-sand-peter3,po-sand-peter1,po-sand-peter2]>: Got an exception when receiving data: IO timeout when reading 7 bytes (Timeout::Error)
W, [2014-11-07T09:45:55.963869 #20395]  WARN -- #<Bunny::Session:70347958486140 guest@po-sand-peter2:5672, vhost=/, hosts=[po-sand-peter3,po-sand-peter1,po-sand-peter2]>: An empty frame was received while opening the connection. In RabbitMQ <= 3.1 this could mean an authentication issue.
W, [2014-11-07T09:45:55.963960 #20395]  WARN -- #<Bunny::Session:70347958486140 guest@po-sand-peter2:5672, vhost=/, hosts=[po-sand-peter3,po-sand-peter1,po-sand-peter2]>: TCP connection failed, reconnecting in 1 seconds

[michaelklishin]

And RabbitMQ log?

[michaelklishin]

I suspect this is Bunny't heartbeat thread going crazy about RabbitMQ not sending heartbeats but would be nice to see server log to clarify.

[mmmries]

My connection has the following settings:

{
  :heartbeat => 0,
  :hosts => %w( po-sand-peter1 po-sand-peter2 po-sand-peter3 ),
  :port => 5672,
  :continuation_timeout => 5000,
  :automatically_recover => true,
  :network_recovery_interval => 1,
  :recover_from_connection_close => true,
}

RabbitMQ log:

=INFO REPORT==== 7-Nov-2014::09:49:33 ===
accepting AMQP connection <0.8018.0> (127.0.0.1:39581 -> 127.0.0.1:5672)

=WARNING REPORT==== 7-Nov-2014::09:49:33 ===
closing AMQP connection <0.8018.0> (127.0.0.1:39581 -> 127.0.0.1:5672):
connection_closed_abruptly

=INFO REPORT==== 7-Nov-2014::09:49:37 ===
accepting AMQP connection <0.8022.0> (172.16.2.103:53902 -> 172.16.3.90:5672)

=WARNING REPORT==== 7-Nov-2014::09:49:37 ===
closing AMQP connection <0.8022.0> (172.16.2.103:53902 -> 172.16.3.90:5672):
connection_closed_abruptly








=INFO REPORT==== 7-Nov-2014::09:49:39 ===
accepting AMQP connection <0.8027.0> (172.16.2.103:53907 -> 172.16.3.90:5672)

=WARNING REPORT==== 7-Nov-2014::09:49:39 ===
closing AMQP connection <0.8027.0> (172.16.2.103:53907 -> 172.16.3.90:5672):
connection_closed_abruptly

[michaelklishin]

OK, thank you, seems like my hypothesis is correct. Will get to it in the next day or two.

[mmmries]

Thanks! I'm going to be doing a bunch of resiliency testing in the next few days around publishing and subscribing when I specify multiple hosts. If you're overloaded with work I'm happy to spend some time looking into these issues and making pull requests on both bunny and march_hare.

[michaelklishin]

The issue turned out to be

@transport.read_timeout = @heartbeat * 2.2

Having a read timeout of 0 is asking for trouble ;)

[midwire]

I am also having this same problem, even when setting heartbeat to a non-zero value.

➤ be irb
irb(main):001:0> require 'bunny'
=> true
irb(main):002:0> conn = Bunny.new(read_timeout: 2, heartbeat: 2)
=> #<Bunny::Session:0x007fa92538f038 @default_hosts_shuffle_strategy=#<Proc:0x007fa92538ef70@/Users/cblackburn/Code/ruby/SimpleFinance/virtual_bank/vendor/bundle/ruby/2.1.0/gems/bunny-1.6.0/lib/bunny/session.rb:133>, @opts={:read_timeout=>2, :heartbeat=>2}, @hosts=["127.0.0.1"], @host_index=1, @port=5672, @user="guest", @pass="guest", @vhost="/", @logfile=#<IO:<STDOUT>>, @threaded=true, @logger=#<Logger:0x007fa92538ee80 @progname="#<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>", @level=2, @default_formatter=#<Logger::Formatter:0x007fa92538ee58 @datetime_format=nil>, @formatter=nil, @logdev=#<Logger::LogDevice:0x007fa92538ee08 @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDOUT>>, @mutex=#<Logger::LogDevice::LogDeviceMutex:0x007fa92538ede0 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007fa92538ed90>>>>, @automatically_recover=true, @network_recovery_interval=5.0, @recover_from_connection_close=false, @continuation_timeout=4000, @status=:not_connected, @blocked=false, @client_frame_max=131072, @client_channel_max=65535, @channel_max=65535, @client_heartbeat=2, @client_properties={:capabilities=>{:publisher_confirms=>true, :consumer_cancel_notify=>true, :exchange_exchange_bindings=>true, :"basic.nack"=>true, :"connection.blocked"=>true, :authentication_failure_close=>true}, :product=>"Bunny", :platform=>"ruby 2.1.2p95 (2014-05-08 revision 45877) [x86_64-darwin13.0]", :version=>"1.6.0", :information=>"http://rubybunny.info"}, @mechanism="PLAIN", @credentials_encoder=#<Bunny::Authentication::PlainMechanismEncoder:0x007fa92538ec50 @session=#<Bunny::Session:0x007fa92538f038 ...>>, @locale="en_GB", @mutex_impl=Monitor, @channel_mutex=#<Monitor:0x007fa92538ec28 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007fa92538ebd8>>, @transport_mutex=#<Monitor:0x007fa92538ebb0 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007fa92538eb60>>, @status_mutex=#<Monitor:0x007fa92538eb38 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007fa92538eae8>>, @host_index_mutex=#<Monitor:0x007fa92538eac0 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007fa92538ea70>>, @channels={}, @origin_thread=#<Thread:0x007fa9238cb788 run>, @continuations=#<Bunny::Concurrent::ContinuationQueue:0x007fa92538ea20 @q=#<Thread::Queue:0x007fa92538e9d0>>, @transport=#<Bunny::Transport:0x007fa92538e818 @session=#<Bunny::Session:0x007fa92538f038 ...>, @session_thread=#<Thread:0x007fa9238cb788 run>, @host="127.0.0.1", @port=5672, @opts={:read_timeout=>2, :heartbeat=>2, :session_thread=>#<Thread:0x007fa9238cb788 run>}, @logger=#<Logger:0x007fa92538ee80 @progname="#<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>", @level=2, @default_formatter=#<Logger::Formatter:0x007fa92538ee58 @datetime_format=nil>, @formatter=nil, @logdev=#<Logger::LogDevice:0x007fa92538ee08 @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDOUT>>, @mutex=#<Logger::LogDevice::LogDeviceMutex:0x007fa92538ede0 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007fa92538ed90>>>>, @tls_enabled=false, @read_timeout=2, @write_timeout=5.0, @connect_timeout=5.0, @disconnect_timeout=5.0, @writes_mutex=#<Monitor:0x007fa92538e7f0 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007fa92538e7a0>>>>
irb(main):003:0> conn.start
E, [2014-11-12T08:42:15.732111 #77111] ERROR -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: Got an exception when receiving data: IO timeout when reading 7 bytes (Timeout::Error)
W, [2014-11-12T08:42:15.732305 #77111]  WARN -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: Recovering from a network failure...
W, [2014-11-12T08:42:25.733120 #77111]  WARN -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: Retrying connection on next host in line: 127.0.0.1:5672
E, [2014-11-12T08:42:27.734777 #77111] ERROR -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: Got an exception when receiving data: IO timeout when reading 7 bytes (Timeout::Error)
W, [2014-11-12T08:42:27.735048 #77111]  WARN -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: TCP connection failed, reconnecting in 5.0 seconds

W, [2014-11-12T08:42:42.736800 #77111]  WARN -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: Retrying connection on next host in line: 127.0.0.1:5672
E, [2014-11-12T08:42:44.738429 #77111] ERROR -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: Got an exception when receiving data: IO timeout when reading 7 bytes (Timeout::Error)
W, [2014-11-12T08:42:44.738702 #77111]  WARN -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: TCP connection failed, reconnecting in 5.0 seconds
W, [2014-11-12T08:42:59.739880 #77111]  WARN -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: Retrying connection on next host in line: 127.0.0.1:5672
E, [2014-11-12T08:43:01.740746 #77111] ERROR -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: Got an exception when receiving data: IO timeout when reading 7 bytes (Timeout::Error)
W, [2014-11-12T08:43:01.740976 #77111]  WARN -- #<Bunny::Session:70182225344540 [email protected]:5672, vhost=/, hosts=[127.0.0.1]>: TCP connection failed, reconnecting in 5.0 seconds

[midwire]

Server Log:

=INFO REPORT==== 12-Nov-2014::08:46:23 ===
accepting AMQP connection <0.1251.0> (127.0.0.1:61272 -> 127.0.0.1:5672)

=WARNING REPORT==== 12-Nov-2014::08:46:31 ===
closing AMQP connection <0.1251.0> (127.0.0.1:61272 -> 127.0.0.1:5672):
connection_closed_abruptly

=INFO REPORT==== 12-Nov-2014::08:46:40 ===
accepting AMQP connection <0.1259.0> (127.0.0.1:61273 -> 127.0.0.1:5672)

=WARNING REPORT==== 12-Nov-2014::08:46:48 ===
closing AMQP connection <0.1259.0> (127.0.0.1:61273 -> 127.0.0.1:5672):
connection_closed_abruptly

[michaelklishin]

2 is a really low value which may result in false positives on some networks. Certainly heartbeat value of 1 is known to trigger false positives on AWS. So please bump that to 10-20.

[midwire]

Thanks @michaelklishin. '10' works!