Consumer for channel `Queue_02` did not stop in the expected time of 0.9s


#1

Hi,

While the rabbitmq items are been dequeued we manually made the respective channel inactive from zato(connection->channels->AMQP).

And we received the following log error in zato.

2018-10-22 11:11:21,132 - ERROR - 2733:DummyThread-323606 - zato.broker:57 - Could not handle broker msg:Bunch(ack_mode='ack', action='101001', cluster_id=1, consumer_tag_prefix='operations', data_format='json', def_id=1, def_name='AMQP_Definition', id=3, is_active=True, msg_type='0002', name='Queue_02', old_name='Queue_02', pool_size=1, prefetch_count=1, queue='Queue_02', service='queue.dequeue', service_name='queue.dequeue'), e:Traceback (most recent call last): File "/opt/zato/3.0/code/zato-broker/src/zato/broker/__init__.py", line 52, in on_broker_msg getattr(self, handler)(msg) File "/opt/zato/3.0/code/zato-server/src/zato/server/base/worker/amqp_.py", line 102, in on_broker_msg_CHANNEL_AMQP_EDIT self.amqp_api.edit_channel(msg.def_name, msg) File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/connector/__init__.py", line 362, in edit_channel self.connectors[name].edit_channel(config) File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/amqp_.py", line 448, in edit_channel self._delete_channel(config) File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/amqp_.py", line 471, in _delete_channel consumer.stop() File "/opt/zato/3.0/code/zato-server/src/zato/server/connection/amqp_.py", line 256, in stop self.name, delta)) Exception: Consumer for channelQueue_02` did not stop in the expected time of 0.9s

We had to restart the zato to for the channel to be obtained again. We are not sure of the root cause.

What could be the possible issue here?

The following is the git version been used
$ git log -1
commit e68168a3dc935234d1bd878e94512460c9939370
Author: Dariusz Suchojad <dsuch-github@m.zato.io>
Date: Thu Sep 27 14:51:55 2018 +0200
GH #847 - Simplified creation of POST parameters.

Regards,
Sai Bhargav


#2

Can you say what kind of messages were being dequeued? How big they were? How many of them?

It looks that it took more than 0.9s to stop the channel because it was not possible to interrupt the task that dequeues the messages, hence the exception.


#3

Hi @dsuch
Can you say what kind of messages were being dequeued?
JSON type messages

How big they were? How many of them?
About 200-300 character, 2 items in the queue.

Please note that there were 4 other queues which were deqeueing which had a load of about 50000 items in each.

Regards,
Sai Bhargav


#4

Is it possible for you to establish a pattern? E.g. this happens only if there are more than N messages in a given queue, each > M bytes in size?

Also, please open a ticket in GH with a feature request to add max shutdown time to channels. I think even under high load you it would be convenient to be able to specify that you want to wait, say, 1 minute for a channel to close instead of having to restart the whole server. Thanks.

By the way, in this particular case it does not matter but in the future, please make sure that you always run the latest version, yours is about two months behind with updates.


#5

Hi @dsuch

We have tried to establish a pattern but we could not achieve it but as part of this exercise what we have observed is the rabbitmq dequeue stalled after certain amount of time when there was no response to rabbitmq dequeuing item and the item was not acknowledged.
Now we tried to deactivate the AMQP channel and we could get the above mentioned error. Is there any timeout limit on the rabbitmq dequeuing item to be acknowledged or rejected?

Regards,
Sai Bhargav


#6

There is no explicit code in Zato that would require such a timeout of RabbitMQ. Whether RabbitMQ itself requires it, I do not know. If you investigate it closer and find it to be the case, please let me know, I would like to understand the root cause too.