RabbitMQ Operation Timeout Exception in BasicGet

[niveddha raja]

Getting Operation Timeout in Channel.BasicGet() when receiving messages from the queue.

System.TimeoutException: The operation has timed out.
   at RabbitMQ.Util.BlockingCell.GetValue(TimeSpan timeout)
   at RabbitMQ.Client.Impl.SimpleBlockingRpcContinuation.GetReply(TimeSpan timeout)
   at RabbitMQ.Client.Impl.ModelBase.BasicGet(String queue, Boolean autoAck)
   at RabbitMQ.Client.Impl.AutorecoveringModel.BasicGet(String queue, Boolean autoAck)

When this error is occurring the message is not received in consumer and not acknowledged  and after 30 mins of default consumer timeout the below error occurs and the channel is closed.

RabbitMQ.Client.Exceptions.AlreadyClosedException: Already closed: The AMQP operation was interrupted: AMQP close-reason, initiated by Peer, code=406, text="PRECONDITION_FAILED - delivery acknowledgement on channel 1 timed out. Timeout value used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more", classId=0, methodId=0, cause=
   at RabbitMQ.Client.Impl.SessionBase.Transmit(Command cmd)
   at RabbitMQ.Client.Impl.ModelBase.ModelSend(MethodBase method, ContentHeaderBase header, Byte[] body)
   at RabbitMQ.Client.Framing.Impl.Model._Private_BasicGet(String queue, Boolean autoAck)
   at RabbitMQ.Client.Impl.ModelBase.BasicGet(String queue, Boolean autoAck)
   at RabbitMQ.Client.Impl.AutorecoveringModel.BasicGet(String queue, Boolean autoAck)
   
All the messages are processed in consumer side and acknowledgement is sent back to RabbitMQ without delay. when messages received continuously in a thread getting this operation timeout error. This is occurring in latest RabbitMQ version.

Separate channels are used for publishing and receiving of messages. Default Operation timeout is used.

RabbitMQ version - 3.8.19
C# RabbitMQ Client - 5.0.1.0

Any solution to avoid this timeout.

[Luke Bakken]

Hello,

First I have to suggest upgrading both RabbitMQ and your .NET client version. They are both very out-of-date.

Second, you should be using one of the Consume methods to retrieve messages, not BasicGet

If you can provide code to reproduce this issue, I could investigate. There's not much to work with here unfortunately.

Thanks,

Luke

[niveddha raja]

Hi Luke,

Thanks for your feedback.

I understand your suggestion to upgrade RabbitMQ and RabbitMQ .NET client library.
Just to clarify we have a large customer base using our application with these previous versions, will upgrading them to latest versions solve the timeout issue?
What versions of RabbitMQ and RabbitMQ .NET client library would you suggest to go with?

Currently used versions:

RabbitMQ - 3.8.19
RabbitMQ .NET Client Library - 5.0.1.0

[niveddha raja]

Hi,

As suggested we have upgraded our RabbitMQ(3.11.1) and RabbitMQ .NET client(6.4.0) version to the latest.
We have also modified our message receive process from BasicGet to BasicConsume as suggested.

Still we are facing the Operation timeout issue randomly where inturn message from RabbitMQ is not received in consumer side but goes to unack in RabbitMQ due to this timeout exception. After default 30 mins we are getting consumer timeout and the Channel is closed.

1. What could be the possible reason for this operation timeout to occur during receiving messages? If so what solution would you suggest to avoid this?

2. We have also tried to recreate Channel on delivery acknowledgement exception. Some case even our Connection is getting closed instead of Channel. Any comments on this?

We have a large customer base where we are facing this critical issue from many of them. So we are looking for a concrete solution and its root cause.

Any helping hands on this pls?

[Luke Bakken]

Hello,

Please note that paid support for RabbitMQ is available if this issue is truly urgent - https://www.rabbitmq.com/#support

 

Based on the limited information you have given, you probably have a bug in your application. RabbitMQ most likely is delivering the message to your application but something in your code isn't working correctly and the message is not being acknowledged like you think it is.

We don't have any log files from you - neither from RabbitMQ nor from your application.

• What is the full .NET exception and stack trace now that you have changed your code? It can't be the same stack as what you posted in your original messag.
• What does RabbitMQ log at the same time? What is the full log file?
• Do you have code that reproduces this issue?

Thanks,

Luke

[niveddha raja]

Hi Luke,
Thanks for your feedback.

UseCase 1:
When the messages are published and received using BasicGet.
we are getting the following error in our application log:
2022-11-08 14:42:12,239 [55] ERROR x.MessageQueue.Impls.RabbitmqRxReceiver [(null)] <(null)> - failed to receive message from queue

System.TimeoutException: The operation has timed out.

   at RabbitMQ.Util.BlockingCell`1.WaitForValue(TimeSpan timeout)

   at RabbitMQ.Client.Impl.SimpleBlockingRpcContinuation.GetReply(TimeSpan timeout)
   at RabbitMQ.Client.Impl.ModelBase.BasicGet(String queue, Boolean autoAck)
   at RabbitMQ.Client.Impl.AutorecoveringModel.BasicGet(String queue, Boolean autoAck)

After 30 minutes, we are getting the following error.
2022-11-08 15:12:15,261 [55] ERROR x.MessageQueue.Impls.RabbitmqRxReceiver [(null)] <(null)> - failed to receive message from queue

RabbitMQ.Client.Exceptions.AlreadyClosedException: Already closed: The AMQP operation was interrupted: AMQP close-reason, initiated by Peer, code=406, text='PRECONDITION_FAILED - delivery acknowledgement on channel 1 timed out. Timeout value used: 1800000 ms. This timeout value can be configured, see consumers doc guide to learn more', classId=0, methodId=0

   at RabbitMQ.Client.Impl.SessionBase.Transmit(OutgoingCommand& cmd)
   at RabbitMQ.Client.Impl.ModelBase.ModelSend(MethodBase method, ContentHeaderBase header, ReadOnlyMemory`1 body)

   at RabbitMQ.Client.Framing.Impl.Model._Private_BasicGet(String queue, Boolean autoAck)
   at RabbitMQ.Client.Impl.ModelBase.BasicGet(String queue, Boolean autoAck)
   at RabbitMQ.Client.Impl.AutorecoveringModel.BasicGet(String queue, Boolean autoAck)

Have attached RabbitMQ logs during the issue occurrence.(rab...@xxxxxx.log inside RabbitMQ_log folder)

UseCase 2:
We have tried to simulate this issue using sample application. In this sample we have published and received messages continuously using separate threads for both publish and receive.

During Channel close exception we have recreated a new channel. During channel recreation at random times we also got exception and the thread which was used for receiving messages was aborted.
We did receive a connection shutdown error during observation and the following were the logs.

RabbitMQ logs (rabbit@aaaa - Shutdown& recreation connection.log):
2022-11-04 19:42:58.615000+05:30 [warning] <0.19876.0> client unexpectedly closed TCP connection
2022-11-04 19:42:58.616000+05:30 [error] <0.19880.0>     supervisor: {<0.19880.0>,rabbit_channel_sup_sup}
2022-11-04 19:42:58.616000+05:30 [error] <0.19880.0>     errorContext: shutdown_error
2022-11-04 19:42:58.616000+05:30 [error] <0.19880.0>     reason: shutdown

Application log (rabbitSample.log):
2022-11-04 19:42:58,596 [16] ERROR Rabbitmq_Ack_App.RabbitReceiverTestQueue - failed to receive message from queue
RabbitMQ.Client.Exceptions.OperationInterruptedException: The AMQP operation was interrupted: AMQP close-reason, initiated by Peer, code=406, text='PRECONDITION_FAILED - delivery acknowledgement on channel 1 timed out. Timeout value used: 300000 ms. This timeout value can be configured, see consumers doc guide to learn more', classId=0, methodId=0

   at RabbitMQ.Client.Impl.SimpleBlockingRpcContinuation.GetReply(TimeSpan timeout)
   at RabbitMQ.Client.Impl.ModelBase.BasicGet(String queue, Boolean autoAck)
   at RabbitMQ.Client.Impl.AutorecoveringModel.BasicGet(String queue, Boolean autoAck)

   at Rabbitmq_Ack_App.RabbitReceiverTestQueue.Receive() in D:\cccc\bbbbb\Rabbitmq_Ack_App\Rabbitmq_Ack_App\RabbitReceiverTestQueue.cs:line 37
2022-11-04 19:42:58,608 [14] ERROR Rabbitmq_Ack_App.Form1 - Receive Error : The AMQP operation was interrupted: AMQP close-reason, initiated by Library, code=541, text='Unexpected Exception', classId=0, methodId=0, cause=System.Collections.Generic.KeyNotFoundException: The given key was not present in the dictionary.
   at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
   at RabbitMQ.Client.Impl.SessionManager.Lookup(Int32 number)
   at RabbitMQ.Client.Framing.Impl.Connection.MainLoopIteration()
   at RabbitMQ.Client.Framing.Impl.Connection.MainLoop()   at RabbitMQ.Client.Impl.SimpleBlockingRpcContinuation.GetReply(TimeSpan timeout)
   at RabbitMQ.Client.Impl.ModelBase.ModelRpc(MethodBase method, ContentHeaderBase header, Byte[] body)
   at RabbitMQ.Client.Framing.Impl.Model._Private_ChannelOpen(String outOfBand)
   at RabbitMQ.Client.Framing.Impl.AutorecoveringConnection.CreateNonRecoveringModel()
   at RabbitMQ.Client.Framing.Impl.AutorecoveringConnection.CreateModel()
   at Rabbitmq_Ack_App.RabbitReceiver.Receive() in D:\cccc\bbbbb\Rabbitmq_Ack_App\Rabbitmq_Ack_App\RabbitReceiver.cs:line 55
   at Rabbitmq_Ack_App.Form1.ReceiveMessage() in D:\cccc\bbbbb\Rabbitmq_Ack_App\Rabbitmq_Ack_App\Form1.cs:line 90
  

Have attached the sample application and RabbitMQ logs. (Inside BasicGetSample_Case2 folder)

UseCase 3:
Have changed the code to BasicConsume in sample application and still getting error.
Have attached sample application code. (Inside BasicConsumeSample_Case3 folder)

It would be of great help if we can know the root cause for this issue. Please let us know if you need more information.

[niveddha raja]

Have attached code and logs for your reference

[Luke Bakken]

Hello -

Please note that in the logs you provided this warning appears multiple times:

2022-11-08 04:33:55.819000-08:00 [warning] <0.1027.0> client unexpectedly closed TCP connection

This means that either your client application is crashing or not shutting down the TCP connection correctly, you have a firewall closing the connection, or some other non-RabbitMQ error is causing the TCP connection to close prematurely.

I'm looking at your sample code next.

Luke

[niveddha raja]

Hi Luke,

2022-11-08 04:33:55.819000-08:00 [warning] <0.1027.0> client unexpectedly closed TCP connection. 

This observation seen in log is due to stopping of RabbitMQ service initiated manually during testing. 

Is there any findings in the sample code we have shared till now that needs to be taken care from our side?

We are also parallelly looking for paid support requirement.  We have already went through the link shared by you  https://www.rabbitmq.com/#support. we couldn't explicitly find any pricing details. It would be helpful if you could give us the link to check on the pricing details so that we can initiate the process.

[Luke Bakken]

Hello,

The support page links to this one - https://tanzu.vmware.com/rabbitmq#contact-form

Apparently you have to contact someone. I will bring your latest message here to someone's attention.

I have not yet had time to review the code. Maybe today!

Thanks

Luke

[Luke Bakken]

Hello,

I have started reviewing your sample code.

Does your production code use Windows Forms like your sample code does? Or, did you use Windows Forms for demonstration purposes?

Thanks

Luke

[niveddha raja]

Hi Luke,

We have used Windows Forms only in sample code for demonstration purpose

[Luke Bakken]

Hello,

I have reviewed this code:

https://github.com/lukebakken/dotnet-operation-timeout-dmy16_CPYuQ/tree/main/RabbitMQ_Ack_App

BasicGet is never recommended, especially in a loop, as it will waste network resources and CPU cycles. Having said that, this code runs fine on my Windows laptop.

Here is the exception you report when you run your application:

2022-11-08 14:42:12,239 [55] ERROR x.MessageQueue.Impls.RabbitmqRxReceiver [(null)] <(null)> - failed to receive message from queue

System.TimeoutException: The operation has timed out.

   at RabbitMQ.Util.BlockingCell`1.WaitForValue(TimeSpan timeout)

   at RabbitMQ.Client.Impl.SimpleBlockingRpcContinuation.GetReply(TimeSpan timeout)
   at RabbitMQ.Client.Impl.ModelBase.BasicGet(String queue, Boolean autoAck)
   at RabbitMQ.Client.Impl.AutorecoveringModel.BasicGet(String queue, Boolean autoAck)

This means that your code has called BasicGet, and has not received a reply from RabbitMQ in 20 seconds (the default continuation timeout value). Now, RabbitMQ should respond to BasicGet pretty much immediately with a message or "null". The fact that you then get the PRECONDITION_FAILED - delivery acknowledgement on channel 1 timed out. Timeout value used: 1800000 ms error suggests that the following has happened:

• RabbitMQ received the Basic.Get request and replied. This moves the message from "Ready" to "Unacked"
• The response was lost before it reached your application.
• Your application throws the timeout exception after 20 seconds, because no reply was received.
• RabbitMQ returns the channel error after 30 minutes.

The above sequence of events is pretty much the only one that explains what you report. So, start looking into the network over which your applications communicate with RabbitMQ.

You can recover from all of those exceptions, and it looks like your code does do the right steps. I did comment out some unnecessary code in my repository. Check the commit history to see what.

I am reviewing this code next:

https://github.com/lukebakken/dotnet-operation-timeout-dmy16_CPYuQ/tree/main/BasicConsume

In the future, if you are asked to submit code for review doing so via GitHub, GitLab or some other hosting service is appreciated. It took me a while to extract your code, fix build problems using Visual Studio 2022, and then push the code up to GitHub. That is time I could have been using to diagnose your issue.

Thanks,

Luke

[Luke Bakken]

Hello,

I have reviewed the BasicConsume code and am working on improving it. Keep an eye here:

https://github.com/lukebakken/dotnet-operation-timeout-dmy16_CPYuQ/tree/main/BasicConsume

One very important change I'm making is to use a separate connection for consuming and publishing. You can use the same connection but the best practice is to NOT do that: 

https://www.rabbitmq.com/production-checklist.html#apps

https://www.rabbitmq.com/connections.html#flow-control

The docs aren't as clear as they could be so I created this - https://github.com/rabbitmq/rabbitmq-website/issues/1556

[Luke Bakken]

Hello,

I made a few more changes in the BasicConsume application. There was a lot of unnecessary async/await and additional threads involved. I have not tested the code, however.

If you'd like to use that as a starting point for discussion, that would be fine.

Please review the comments I made about BasicGet and lost information in your environment. That is the most serious issue.

[niveddha raja]

Thanks for your inputs. Noted your suggestions as well.

Will Channel be closed and disposed automatically when connection shutdown event occurs?

Is there a possibility of having channel close exception error and connection shutdown error parallelly? We have got one scenario during channel exception where connection shutdown also occurs.

Thanks for your time and your help once again 🙂