IOError exception occurs on bunny stop

[WrErase]

Whenever I try to issue a stop for Bunny, I get a "stream closed" exception reported and it tries to "Recover from a network failure". It appears that after the connection has been closed, bunny (session.rb/close_connection) tries to send a "Goodbye" message to close the connection, triggering the IOError. In session.rb/close_connection, transport.connected? reports false.

Ruby 1.9.3p392
Bunny: 0.9.4
RabbitMQ: 3.1.3 (default config)

This is pretty much the REAME flow, minus actually sending/receiving the message:

[1] pry(main)> require 'bunny'
[2] pry(main)> ENV['BUNNY_LOG_LEVEL'] = 'debug'
[3] pry(main)> Bunny.version
=> "0.9.4"
[4] pry(main)> conn = Bunny.new;
[5] pry(main)> conn.start;
D, [2013-07-25T10:48:36.321477 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Sent protocol preamble
D, [2013-07-25T10:48:36.322296 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Sent connection.start-ok
D, [2013-07-25T10:48:36.322503 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Heartbeat interval negotiation: client = server, server = 600, result = 600
I, [2013-07-25T10:48:36.322642 #19237] INFO -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Heartbeat interval used (in seconds): 600
D, [2013-07-25T10:48:36.323258 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Sent connection.tune-ok with heartbeat interval = 600, frame_max = 131072, channel_max = 65536
D, [2013-07-25T10:48:36.323511 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Sent connection.open with vhost = /
D, [2013-07-25T10:48:36.361306 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Initializing heartbeat sender...
D, [2013-07-25T10:48:36.362582 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Session#handle_frame on 1: #<AMQ::Protocol::Channel::OpenOk:0x000000026257f8 @channel_id="">
[6] pry(main)> ch = conn.create_channel
D, [2013-07-25T10:48:42.549851 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Session#handle_frame on 2: #<AMQ::Protocol::Channel::OpenOk:0x000000027dd028 @channel_id="">
=> #<Bunny::Channel:20879380 @id=2 @connection=#<Bunny::Session:31290420 [email protected]:5672, vhost=/>>
[7] pry(main)> conn.stop
D, [2013-07-25T10:48:47.006361 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Session#handle_frame on 1: #AMQ::Protocol::Channel::CloseOk:0x00000002842d38
D, [2013-07-25T10:48:47.007378 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Session#handle_frame on 2: #AMQ::Protocol::Channel::CloseOk:0x0000000284ca90
D, [2013-07-25T10:48:47.008054 #19237] DEBUG -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Session#handle_frame on 0: #AMQ::Protocol::Connection::CloseOk:0x0000000284f588
Sending: "\x01\x00\x00\x00\x00\x00\x12\x00\n\x002\x00\xC8\aGoodbye\x00\x00\x00\x00\xCE"
E, [2013-07-25T10:48:47.009188 #19237] ERROR -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Got an exception when sending data: stream closed (IOError)
W, [2013-07-25T10:48:47.009379 #19237] WARN -- #<Bunny::Session:31290420 [email protected]:5672, vhost=/>: Recovering from a network failure...
Bunny::ClientTimeout: execution expired
from /opt/ruby-1.9.3-p392/lib/ruby/gems/1.9.1/gems/bunny-0.9.4/lib/bunny/session.rb:487:in `sleep'

[michaelklishin]

I cannot reproduce this in a script or REPL, but this may be a side effect from 6ccf742. Please provide a script that reproduces the issue.

[WrErase]

Running your new spec fails in my environment:

Ruby 1.9.3p392
Bunny: 0.9.4
RabbitMQ: 3.1.3 (default config)
Linux 3.2.0-48-virtual #74-Ubuntu SMP Thu Jun 6 20:02:55 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

Could this be something with RabbitMQ 3.1?

$ be rspec spec/higher_level_api/integration/connection_stop_spec.rb
Using Ruby 1.9.3, amq-protocol 1.7.0.pre1
E, [2013-07-25T11:44:11.746987 #5037] ERROR -- #<Bunny::Session:11620680 [email protected]:5672, vhost=/>: Got an exception when sending data: stream closed (IOError)
W, [2013-07-25T11:44:11.747233 #5037] WARN -- #<Bunny::Session:11620680 [email protected]:5672, vhost=/>: Recovering from a network failure...
F

Failures:

1. Bunny::Session can be closed
   Failure/Error: c.stop
   Bunny::ClientTimeout:
   execution expired

   ./lib/bunny/session.rb:487:in `sleep'

   ./lib/bunny/session.rb:487:in`recover_from_network_failure'

   ./lib/bunny/session.rb:466:in `handle_network_failure'

   ./lib/bunny/transport.rb:124:in`rescue in write'

   ./lib/bunny/transport.rb:104:in `write'

   ./lib/bunny/transport.rb:155:in`send_frame'

   ./lib/bunny/session.rb:373:in `close_connection'

   ./lib/bunny/session.rb:262:in`block in close'

   ./lib/bunny/session.rb:261:in `close'

   ./spec/higher_level_api/integration/connection_stop_spec.rb:10:in`block (2 levels) in <top (required)>'

Finished in 3.06 seconds
1 example, 1 failure

Failed examples:
rspec ./spec/higher_level_api/integration/connection_stop_spec.rb:4 # Bunny::Session can be closed

Simply wrapping the @transport.send_frame in close_connection with a @transport.connected? seems to fix the issue.

def close_connection(sync = true)
if @transport.connected?
@transport.send_frame(AMQ::Protocol::Connection::Close.encode(200, "Goodbye", 0, 0))
end

[michaelklishin]

The real question is why the transport is closed by the time #close_connection is executed.

[michaelklishin]

0.9.5 is out.

[michaelklishin]

Ok, it appears that running the test 2000 or so times still reveals 4-5 IOExceptions so the issue is not fully gone. I will keep investigating, since this is likely what sometimes causes CI failures for us.

Thank you for reporting it.

[michaelklishin]

@WrErase can you please give 0.9.6 a try? (by running your code and the spec). In case you're wondering what the issue was, see 1b807b1.

[WrErase]

0.9.6 looks good to me. I just ran connection_stop_spec as well as a few of my own, with no issues seen.

Thanks