ruby-amqp/bunny — Issue #39: Race condition with subscribe timeout
Author: qpingu
Created: 2012-02-21 00:18:17+00:00
State: open

Hey everybody.

I've uncovered a rare issue caused when subscribing with a timeout. Every so often, Bunny will just freeze and never exit. The theory is that Bunny is in the processing of receiving a message when the timeout is hit (very small window), causing the follow-up unsubscribe to fail.

Here's the stack-trace when interrupting a frozen process:

/Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/client.rb:194:in `read': Interrupt
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/client.rb:194:in `send_command'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/client.rb:124:in `read'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/transport/buffer08.rb:272:in `_read'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/transport/buffer08.rb:103:in `block in read'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/transport/buffer08.rb:89:in `map'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/transport/buffer08.rb:89:in `read'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/transport/frame08.rb:61:in `block in parse'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/transport/buffer08.rb:263:in `extract'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/transport/frame08.rb:60:in `parse'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/bunny/client08.rb:158:in `next_frame'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/client.rb:117:in `next_payload'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/bunny/queue08.rb:343:in `unsubscribe'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/subscription.rb:61:in `rescue in block in start'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/subscription.rb:58:in `block in start'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/subscription.rb:56:in `loop'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/qrack/subscription.rb:56:in `start'
from /Users/lcurley/.rbenv/versions/1.9.3-p0/lib/ruby/gems/1.9.1/gems/bunny-0.7.9/lib/bunny/queue08.rb:311:in `subscribe'
from bunny.rb:39:in `block in

'
from bunny.rb:34:in `times'
from bunny.rb:34:in `

'

I was able to (randomly) reproduce the issue with this simple script:

require 'bunny'

bunny_write = Bunny.new#(:logging => true)
bunny_read = Bunny.new(:logging => true)

bunny_write.start
bunny_read.start

bunny_read.qos

direct_exchange = bunny_write.exchange('')

queue_read = bunny_read.queue('test1')
queue_write = bunny_write.queue('test1')

queue_read.purge # clear messages from previous run

NUM_MESSAGES = 1000

Thread.new do
NUM_MESSAGES.times do |i|
# publish a message to the queue
direct_exchange.publish("#{ i }", key: queue_write.name)
puts "sent #{ i }"

sleep rand
end

bunny_write.stop
end

NUM_MESSAGES.times do |i|
timeout = rand
got_message = false

# get message from the queue
queue_read.subscribe(:timeout => timeout, :message_max => 1) do |message|
got_message = true
end

puts "#{ got_message ? "recieved" : "missed" } #{ i }"
end

bunny_read.stop
bunny_write.stop

Here's the last few lines of output from this script. Keep in mind that "sent" and "received" lines aren't meant to match up.

recieved 644
I, [2012-02-18 17:35:28#94063] INFO -- send: ^A^@^A^@^@^@E^@<^@^T^@^A^Etest1729271
I, [2012-02-18 17:35:28#94063] INFO -- received: ^A^@^A^@^@^@<^@<^@^U7292712987322
sent 355
I, [2012-02-18 17:35:29#94063] INFO -- received: ^A^@^A^@^@^@L^@<^@<72927129873223
I, [2012-02-18 17:35:29#94063] INFO -- received: ^B^@^A^@^@^@)^@<^@^@^@^@^@^@^@^@^
I, [2012-02-18 17:35:29#94063] INFO -- received: ^C^@^A^@^@^@^C355Î
I, [2012-02-18 17:35:29#94063] INFO -- send: ^A^@^A^@^@^@=^@<^@^^72927129873223131
I, [2012-02-18 17:35:29#94063] INFO -- received: ^A^@^A^@^@^@<^@<^@^_7292712987322
recieved 645
I, [2012-02-18 17:35:29#94063] INFO -- send: ^A^@^A^@^@^@E^@<^@^T^@^A^Etest1797302
I, [2012-02-18 17:35:29#94063] INFO -- received: ^A^@^A^@^@^@<^@<^@^U7973022136281
sent 356
I, [2012-02-18 17:35:29#94063] INFO -- send: ^A^@^A^@^@^@=^@<^@^^79730221362814317
sent 357
sent 358
sent 359
...

The obvious solution is to set a socket timeout when creating the client, but it has to be greater than maximum timeout amount. I'm hoping the fix is more straight-forward than that.

Thanks!