Socket Error: 104 consuming messages with task that take a long time

[pat1]

As in #418 I have problem consuming messages with task that take a long time.
I am using git master setting heartbeat_interval=0.

My code is very similar to
http://pika.readthedocs.io/en/0.10.0/examples/asynchronous_consumer_example.html
but my on_message method take some minutes to "consume" the message.

after some time consuming message I get:

INFO 2016-05-27 16:28:51,083 __main__ connect  101 : Connecting to localhost
INFO 2016-05-27 16:28:51,084 pika.adapters.base_connection _create_and_connect_to_socket  216 : Connecting to ::1:5672
INFO 2016-05-27 16:28:51,089 __main__ on_connection_open  117 : Connection opened
INFO 2016-05-27 16:28:51,089 __main__ add_on_connection_close_callback  126 : Adding connection close callback
INFO 2016-05-27 16:28:51,089 __main__ open_channel  169 : Creating a new channel
INFO 2016-05-27 16:28:51,092 __main__ on_channel_open  181 : Channel opened
INFO 2016-05-27 16:28:51,092 __main__ add_on_channel_close_callback  193 : Adding channel close callback
INFO 2016-05-27 16:28:51,092 __main__ start_consuming  223 : Issuing consumer related RPC commands
INFO 2016-05-27 16:28:51,092 __main__ add_on_cancel_callback  233 : Adding consumer cancellation callback
INFO 2016-05-27 16:28:51,102 __main__ on_message  263 : Received message # 1 from None
INFO 2016-05-27 16:43:45,104 __main__ run  72  : Done
INFO 2016-05-27 16:43:45,883 __main__ acknowledge_message  312 : Acknowledging message 1
ERROR 2016-05-27 16:43:45,884 pika.adapters.base_connection _handle_error  362 : Socket Error: 104
INFO 2016-05-27 16:43:45,884 pika.connection _on_terminate  1891: Disconnected from RabbitMQ at localhost:5672 (-1): error(104, 'Connection reset by peer')
WARNING 2016-05-27 16:43:45,885 __main__ on_channel_closed  209 : Channel 1 was closed: (-1) error(104, 'Connection reset by peer')
WARNING 2016-05-27 16:43:45,886 pika.connection close  1135: Suppressing close request on <SelectConnection CLOSED socket=None params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
WARNING 2016-05-27 16:43:45,887 __main__ on_connection_closed  144 : Connection closed, reopening in 5 seconds: (-1) error(104, 'Connection reset by peer')
INFO 2016-05-27 16:43:50,892 __main__ connect  101 : Connecting to localhost

On the log you can see function and line before meaage.
I have tried to execute my task in thread maintaining the amqp comunication in the main process with:

self._connection.ioloop.stop()
while (thread.isAlive()):
            #self._connection.ioloop.poll(write_only=True)
            #self._connection.ioloop.poll()                                                                                               
            time.sleep(3)

write_only=True was available in previous version
self._connection.ioloop.poll() create a recursion call with a lot of thread and problems
self._connection.ioloop.start()

So I don't have solution, I cannot consume messages and all is stalled.
Is possible we need a (background) poll to maintain socket and do not get new messages from queue?

[vitaly-krugl]

@pat1, if the processing takes so long, then it's not a good match for the asynchronous programming model. Asynchronous programming model works well for I/O-bound processing that uses a common ioloop for all blocking operations within a thread.

I am also surprised that with heartbeat_interval=0 you would get heartbeat timeouts. That should completely disable heartbeats. Please check the rabbitmq log to see if the connection is dropped due to heartbeat timeout or something else.

Your app is not accessing the same pika connection (and/or its channels) from more than one thread, is it? pika connections are not thread-safe, so you would expect to have trouble in that case.

The following would be really helpful for debugging:

1. your environment (os, os version, etc.)
2. rabbitmq version
3. A small, simple script that easily reproduces the lost connection. You may use time.sleep instead of your long-running processing operation.

[pat1]

Thanks for your replay.
my os is Linux (Fedora 20 386)
rpm -q python python-2.7.5-16.fc20.i686
pika git master
rpm -q rabbitmq-server rabbitmq-server-3.6.2-1.noarch

My app is not accessing the same pika connection (and/or its channels) from more than one thread.

test program:
https://gist.github.com/pat1/4017d6565501b657731560af3d2e0b9e
The log:

 [*] Waiting for messages. To exit press CTRL+C
INFO 2016-05-27 18:53:54,438 __main__ connect  56  : Connecting to localhost
INFO 2016-05-27 18:53:54,440 pika.adapters.base_connection _create_and_connect_to_socket  216 : Connecting to ::1:5672
INFO 2016-05-27 18:53:54,445 __main__ on_connection_open  72  : Connection opened
INFO 2016-05-27 18:53:54,445 __main__ add_on_connection_close_callback  81  : Adding connection close callback
INFO 2016-05-27 18:53:54,446 __main__ open_channel  124 : Creating a new channel
INFO 2016-05-27 18:53:54,448 __main__ on_channel_open  136 : Channel opened
INFO 2016-05-27 18:53:54,448 __main__ add_on_channel_close_callback  148 : Adding channel close callback
INFO 2016-05-27 18:53:54,448 __main__ start_consuming  178 : Issuing consumer related RPC commands
INFO 2016-05-27 18:53:54,448 __main__ add_on_cancel_callback  188 : Adding consumer cancellation callback
INFO 2016-05-27 18:53:54,463 __main__ on_message  218 : Received message # 1 from None
INFO 2016-05-27 19:03:54,556 __main__ acknowledge_message  243 : Acknowledging message 1
ERROR 2016-05-27 19:03:54,557 pika.adapters.base_connection _handle_error  362 : Socket Error: 104
INFO 2016-05-27 19:03:54,558 pika.connection _on_terminate  1891: Disconnected from RabbitMQ at localhost:5672 (-1): error(104, 'Connection reset by peer')
WARNING 2016-05-27 19:03:54,559 __main__ on_channel_closed  164 : Channel 1 was closed: (-1) error(104, 'Connection reset by peer')
WARNING 2016-05-27 19:03:54,559 pika.connection close  1135: Suppressing close request on <SelectConnection CLOSED socket=None params=<ConnectionParameters host=localhost port=5672 virtual_host=/ ssl=False>>
WARNING 2016-05-27 19:03:54,560 __main__ on_connection_closed  99  : Connection closed, reopening in 5 seconds: (-1) error(104, 'Connection reset by peer')
INFO 2016-05-27 19:03:59,563 __main__ connect  56  : Connecting to localhost

[pat1]

Adding socket_timeout=1200 in ConnectionParameters do not solve the problem.
On the server:

sysctl -a |grep net.ipv4.tcp_keepalive
net.ipv4.tcp_keepalive_intvl = 75
net.ipv4.tcp_keepalive_probes = 9
net.ipv4.tcp_keepalive_time = 7200

[vitaly-krugl]

What does the network look like? Is there a proxy or similar between the client and rabbitmq broker?

[vitaly-krugl]

Also, what does the RabbitMQ log have to say about this? Please post the RabbitMQ log that shows the disconnect.

[pat1]

I have no proxy, I access rabbitmq via localhost (or public IP, do not change the result).
The rabbitmq log looks like:

=INFO REPORT==== 31-May-2016::19:41:30 ===
accepting AMQP connection <0.32634.2> ([::1]:50677 -> [::1]:5672)

=ERROR REPORT==== 31-May-2016::19:42:00 ===
closing AMQP connection <0.32634.2> ([::1]:50677 -> [::1]:5672):
{writer,send_failed,{error,timeout}}

Setting {heartbeat, 0} in /etc/rabbitmq/rabbitmq.config do not change the behavior.

[vitaly-krugl]

@pat1, the rabbitmq log doesn't look like the failure is related to heartbeat. Note that the error is reported as "send failed ... timeout" just 30 seconds after "accepted AMQP connection". A send timeout would usually mean that transmit retries were exhausted and the peer is unreachable.

This is what a heartbeat timeout log entry looks like:

=INFO REPORT==== 31-May-2016::13:30:38 ===
accepting AMQP connection <0.1559.0> (127.0.0.1:63742 -> 127.0.0.1:5672)

=ERROR REPORT==== 31-May-2016::13:33:38 ===
closing AMQP connection <0.1559.0> (127.0.0.1:63742 -> 127.0.0.1:5672):
missed heartbeats from client, timeout: 60s

[pat1]

looking at:
http://stackoverflow.com/questions/35438843/rabbitmq-error-timeout

adding

self._channel.basic_qos(prefetch_count=1)

before

self._consumer_tag = self._channel.basic_consume(self.on_message,queue)

solve the problem.
Note that I have more than 1000 messages in queue and some are not little.

I think this configuration/example should be published somewhere as template for a very common user case application.

Also a ioloop heartbeat poll method should be useful for do not disable heartbeat and execute only consumer task in thread.

You can evaluate to close this issue.

[vitaly-krugl]

@pat1, thank you for following up. My expectation would be that RMQ should be doing non-blocking I/O, and should not fail this way. This sounds to me like a bug in RMQ.

I would like to investigate and follow up on this with the RMQ team. Your code snippet https://gist.github.com/pat1/4017d6565501b657731560af3d2e0b9e contains only the consumer. Would you mind also adding a small script that populates the queue with the size and number of messages that will surely reproduce the failure? Using pika.BlockingConnection would make it super simple to do by avoiding all those callbacks. Thank you.

[eandersson]

I am seeing this in other AMQP libraries as well.

[pat1]

To be clear this do not work:
https://gist.github.com/pat1/4017d6565501b657731560af3d2e0b9e/3dc43a75c874d76ecdd1412f7b91c06febd848e1

this work:
https://gist.github.com/pat1/4017d6565501b657731560af3d2e0b9e/7246b17d7b4b883d9ff68e53dc65657cdd2eedde

@vitaly-krugl I do not have a script to populates the queue, I think you can fill it with 1000 messages of 100k size

[vitaly-krugl]

Thank you, @pat1.

[barroca]

Hello, is there any update regarding this issue? We started getting this error this week, but we didn't change anything except for the environment we run our code.

Thanks

[jmartinez-jobsity]

I'm also having this issue, even with the prefetch_count=1 solution @pat1 suggested