When flow control is active on RabbitMQ (and connections are blocked) processing and exceptions can come out-of-order. The log file below is from Bunny in debug mode. It seems that queue.status is run at the same time as exchange.publish and actually errors out first.

00_publish.rb

      def publish(data)
        configure
        conn = Bunny.new(connection_uri).start
        channel = conn.create_channel
        queue = channel.queue(queue_name, durable: true)
        exchange = channel.direct(exchange_name, durable: true)
        log_data(data)
        exchange.publish(data, :routing_key => queue.name)
        queue_status(queue.status)
      rescue Exception => e
        handle_exception(e)
      ensure
        conn.close
      end

10_log.txt

stdout: Sent protocol preamble
stdout: Sent connection.start-ok
stdout: Heartbeat interval negotiation: client = server, server = 600, result = 600
stdout: Heartbeat interval used (in seconds): 600
stdout: Sent connection.tune-ok with heartbeat interval = 600, frame_max = 131072, channel_max = 65536
stdout: Sent connection.open with vhost = /
stdout: Initializing heartbeat sender...
stdout: Session#handle_frame on 1: #<AMQ::Protocol::Channel::OpenOk:0x0000000635da30 @channel_id="">
stdout: Session#handle_frame on 2: #<AMQ::Protocol::Channel::OpenOk:0x00000006364218 @channel_id="">
stdout: Session#handle_frame on 2: #<AMQ::Protocol::Queue::DeclareOk:0x00000006362c60 @queue="elasticsearch", @message_count=0, @consumer_count=1>
stdout: Channel#handle_frame on channel 2: #<AMQ::Protocol::Queue::DeclareOk:0x00000006362c60 @queue="elasticsearch", @message_count=0, @consumer_count=1>
stdout: Session#handle_frame on 2: #<AMQ::Protocol::Exchange::DeclareOk:0x00000006816b30>
stdout: Channel#handle_frame on channel 2: #<AMQ::Protocol::Exchange::DeclareOk:0x00000006816b30>

Exception raised while publishing to RabbitMQ River: execution expired
@@@ Exceptional error:
{
  "exception": {
    "exception_class": "Timeout::Error",
    "message": "execution expired",
    "backtrace": [
      "/usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/thread.rb:189:in `sleep'",
      "/usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/thread.rb:189:in `block in pop'",
      "<internal:prelude>:10:in `synchronize'",
      "/usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/thread.rb:184:in `pop'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/concurrent/continuation_queue.rb:25:in `block in poll'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/concurrent/continuation_queue.rb:24:in `poll'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/channel.rb:1623:in `wait_on_continuations'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/channel.rb:936:in `queue_declare'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/queue.rb:300:in `status'",
      "/opt/internal/app/models/advertiser/elastic_update/river_publisher.rb:47:in `block in queue_status'",
      "/opt/internal/app/models/advertiser/elastic_update/river_publisher.rb:52:in `call'",
      "/opt/internal/app/models/advertiser/elastic_update/river_publisher.rb:52:in `debug'",
      "/opt/internal/app/models/advertiser/elastic_update/river_publisher.rb:47:in `queue_status'",
      "/opt/internal/app/models/advertiser/elastic_update/river_publisher.rb:13:in `publish'",
      "/opt/internal/app/models/advertiser/elastic_update/keyword_updater.rb:25:in `process'",
      "/opt/internal/lib/model_view/decorating_updater.rb:12:in `process'",
      "/opt/internal/lib/model_view/rescuing_updater.rb:10:in `process'",
      "/opt/internal/lib/model_view/sink.rb:64:in `process'",
      "/opt/internal/lib/model_view/sink.rb:24:in `poll'",
      "/opt/internal/lib/model_view/bus.rb:36:in `each'",
      "/opt/internal/lib/model_view/bus.rb:36:in `poll'",
      "/opt/internal/lib/model_view/worker.rb:22:in `process_and_return'",
      "/opt/internal/lib/model_view/worker.rb:30:in `run'",
      "/opt/internal/lib/tasks/advertiser.rake:6:in `block (2 levels) in <top (required)>'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:236:in `call'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:236:in `block in execute'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:231:in `each'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:231:in `execute'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:175:in `block in invoke_with_call_chain'",
      "/usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/monitor.rb:211:in `mon_synchronize'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:168:in `invoke_with_call_chain'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:161:in `invoke'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:149:in `invoke_task'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:106:in `block (2 levels) in top_level'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:106:in `each'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:106:in `block in top_level'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:115:in `run_with_threads'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:100:in `top_level'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:78:in `block in run'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:165:in `standard_exception_handling'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:75:in `run'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/bin/rake:33:in `<top (required)>'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/bin/rake:23:in `load'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/bin/rake:23:in `<main>'"
    ],
    "occurred_at": "2013-07-25T05:57:54Z"
  },
  "rescue_block": {
    "name": ""
  }
}

@@@ Exceptional error:
{
  "exception": {
    "exception_class": "Bunny::ClientTimeout",
    "message": "execution expired",
    "backtrace": [
      "/usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/thread.rb:189:in `sleep'",
      "/usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/thread.rb:189:in `block in pop'",
      "<internal:prelude>:10:in `synchronize'",
      "/usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/thread.rb:184:in `pop'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/concurrent/continuation_queue.rb:25:in `block in poll'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/concurrent/continuation_queue.rb:24:in `poll'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/session.rb:845:in `wait_on_continuations'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/session.rb:357:in `close_channel'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/channel.rb:219:in `close'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/session.rb:367:in `block (2 levels) in close_all_channels'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/session.rb:367:in `block in close_all_channels'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/session.rb:366:in `each'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/session.rb:366:in `close_all_channels'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/bunny-0.9.3/lib/bunny/session.rb:259:in `close'",
      "/opt/internal/app/models/advertiser/elastic_update/river_publisher.rb:17:in `publish'",
      "/opt/internal/app/models/advertiser/elastic_update/keyword_updater.rb:25:in `process'",
      "/opt/internal/lib/model_view/decorating_updater.rb:12:in `process'",
      "/opt/internal/lib/model_view/rescuing_updater.rb:10:in `process'",
      "/opt/internal/lib/model_view/sink.rb:64:in `process'",
      "/opt/internal/lib/model_view/sink.rb:24:in `poll'",
      "/opt/internal/lib/model_view/bus.rb:36:in `each'",
      "/opt/internal/lib/model_view/bus.rb:36:in `poll'",
      "/opt/internal/lib/model_view/worker.rb:22:in `process_and_return'",
      "/opt/internal/lib/model_view/worker.rb:30:in `run'",
      "/opt/internal/lib/tasks/advertiser.rake:6:in `block (2 levels) in <top (required)>'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:236:in `call'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:236:in `block in execute'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:231:in `each'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:231:in `execute'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:175:in `block in invoke_with_call_chain'",
      "/usr/local/rvm/rubies/ruby-1.9.3-p429/lib/ruby/1.9.1/monitor.rb:211:in `mon_synchronize'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:168:in `invoke_with_call_chain'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/task.rb:161:in `invoke'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:149:in `invoke_task'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:106:in `block (2 levels) in top_level'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:106:in `each'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:106:in `block in top_level'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:115:in `run_with_threads'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:100:in `top_level'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:78:in `block in run'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:165:in `standard_exception_handling'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/lib/rake/application.rb:75:in `run'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/gems/rake-10.1.0/bin/rake:33:in `<top (required)>'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/bin/rake:23:in `load'",
      "/opt/internal/vendor/bundle/ruby/1.9.1/bin/rake:23:in `<main>'"
    ],
    "occurred_at": "2013-07-25T05:57:57Z"
  },
  "rescue_block": {
    "name": ""
  }
}