Empty header response received from the server

[bry]

When using Hutch 0.5.1 for the consumer and message publisher, I'm getting an empty response error exception with Bunny when one of our consumers processes very large files (see below), and I am unable to catch this exception. The message is no more than 255 characters, but the csv files (>7k entries) processed and stored in the consumer are on the order of megabytes large, so the consumer takes a bit of CPU time and memory.

These are symptoms of the underlying problem, and I'd like to ask for any other reason on what could be happening in Bunny given the info below and how I could mitigate this issue (unable to catch exception).

I've taken a look at related issues with fixes here:
#115
#138
#74

The version of Bunny I'm using (>=0.10.8) should have fixes for issue 74, and 115.

Gemfile.lock
hutch (0.5.1)
bunny (>= 0.10.8)
carrot-top (> 0.0.7)
multi_json (> 1.5)

Consumer pseudocode

class SubmissionsDownloadRequestConsumer
  include Hutch::Consumer
  include Hutch::Logging
  consume 'answers.download.request'

def process(message)
  # Build CSV file (>7k lines)
  # Hutch.publish('answers.response', answers_response)
end

Exception and stacktrace

2013-11-23T01:37:47.626815+00:00 app[hutch_worker.1]: Exception in the reader loop: AMQ::Protocol::EmptyResponseError: Empty response received from the server.
2013-11-23T01:37:47.626815+00:00 app[hutch_worker.1]: Backtrace:
2013-11-23T01:37:47.626815+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/amq-protocol-1.8.0/lib/amq/protocol/frame.rb:60:in `decode_header'
2013-11-23T01:37:47.626815+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/transport.rb:205:in `read_next_frame'
2013-11-23T01:37:47.626997+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/reader_loop.rb:63:in `run_once'
2013-11-23T01:37:47.626997+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/reader_loop.rb:33:in `block in run_loop'
2013-11-23T01:37:47.626997+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/reader_loop.rb:30:in `loop'
2013-11-23T01:37:47.626997+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/reader_loop.rb:30:in `run_loop'
2013-11-23T01:37:47.626997+00:00 app[hutch_worker.1]: Recovering from a network failure...
2013-11-23T01:37:47.626997+00:00 app[hutch_worker.1]: 2013-11-23T01:37:47Z 2 INFO -- hutch shut down gracefully
2013-11-23T01:37:49.059181+00:00 heroku[hutch_worker.1]: Process exited with status 0

[michaelklishin]

Please upgrade to 1.0.x and post RabbitMQ logs. There can be a million reasons why reading from the socket
returns no data, but typically this indicates that the peer has closed its end of the socket. There have been fixes in amq-protocol since 0.10.x days, including a fix for message bodies of a multiple of exactly 128 Kb in size.

[michaelklishin]

Another reason can be that Hutch uses an unreasonably low heartbeat interval (1 second, which means peers exchange heartbeat frames roughly every 0.5 second). When reading and writing megabytes of data to the socket, there is no guarantee that heartbeat frames will make it to the peer in this brief time frame. RabbitMQ log will make it clear if that's the case.

I don't know if there is a way to force Hutch to not use such a low value. If there's no, there should be.

[michaelklishin]

You can catch the exception if you disable automatic recovery. Otherwise it is raised and handled in the I/O thread. When disabled, any I/O reader loop exceptions will be re-raised in the thread connection was created on.

If Hutch consumers are long running but cannot benefit from Bunny's network failure recovery, I consider it to be a massive issue in Hutch.

[bry]

After Hutch-Bunny upgrade

I've upgraded to Hutch-0.6.0 with hutch.gemspec containing the Bunny runtime dependency ~> 1.0.0 and I'm still getting the following exception.

Note: This is happening on our Heroku staging environment deploys with a dyno having 512MB of total memory each.

Exception and stack trace

2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: Exception in the reader loop: AMQ::Protocol::EmptyResponseError: Empty response received from the server.
2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: Backtrace:
2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/amq-protocol-1.8.0/lib/amq/protocol/frame.rb:60:in `decode_header'
2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/transport.rb:205:in `read_next_frame'
2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/reader_loop.rb:63:in `run_once'
2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/reader_loop.rb:33:in `block in run_loop'
2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/reader_loop.rb:30:in `loop'
2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: /app/vendor/bundle/ruby/1.9.1/gems/bunny-1.0.0/lib/bunny/reader_loop.rb:30:in `run_loop'
2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: Recovering from a network failure...
2013-11-25T22:18:00.124697+00:00 app[hutch_worker.1]: 2013-11-25T22:17:57Z 2 INFO -- hutch shut down gracefully

RabbitMQ logs to follow...

[carlhoerberg]

Yes, hutch uses a 1 second heartbeat, https://github.com/gocardless/hutch/blob/v0.5.1/lib/hutch/broker.rb#L48

Discussed here ruby-amqp/hutch#56

I think this issue can be closed.

[michaelklishin]

FTR, Hutch master now uses heartbeat interval of 30 by default.

[bry]

@michaelklishin @carlhoerberg This fixed the original problem, thanks so much!!