Endpoint stops processing messages and churns CPU when broker connections are closed about nservicebus.rabbitmq

[burkhartt]

Not sure exactly how to replicate the issue, but I can give you some details about our environment. We have a WebAPI project using an in-proc NServiceBus. Then we have 3 other projects using the NServiceBus host. Of those 3, one of them, every five minutes, will generate a message that has an array of simple DTO objects containing 30,000 items in the array. It publishes that message to all service buses (so 4 handlers). The CPU spikes for several seconds--probably due to the serializer? (using XML Serializer). Once it hits the handlers, it takes about 0.01 seconds to process the message.

We are also using RabbitMQ on the same server. Typically it is able to get past the few seconds of spiking CPU, but occasionally (and it could actually be from something else ... still looking into it) I will look at the CPU on the server and all of the service bus processes are going crazy (when it is stuck at 100% for very long periods of time and I have to kill processes) then our logs are full of:

Failed to connect to Broker: 'localhost', Port: 5672 VHost: '/'. ExceptionMessage: 'None of the specified endpoints were reachable'

Disconnected from RabbitMQ Broker, reason: AMQP close-reason, initiated by Library, code=541, text="Unexpected Exception", classId=0, methodId=0, cause=System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
--- End of inner exception stack trace ---
at RabbitMQ.Client.Impl.Frame.ReadFrom(NetworkBinaryReader reader)
at RabbitMQ.Client.Impl.SocketFrameHandler_0_9.ReadFrame()
at RabbitMQ.Client.Impl.ConnectionBase.MainLoopIteration()
at RabbitMQ.Client.Impl.ConnectionBase.MainLoop() , going to reconnect

Connected to RabbitMQ. Broker: 'localhost', Port: 5672, VHost: '/'

It just keeps repeating that non-stop. And I also have the RabbitMQ web interface installed and even that has trouble communicating with the RabbitMQ server. However, the RabbitMQ server is up and running and the Erlang process is still running. And even after I kill the NServiceBus processes, RabbitMQ and the web interface are fine. So I think the NServiceBus CPU spiking is killing RabbitMQ and then it becomes frantic that it can't connect to the transport and kills the MQ even more.

That's my theory anyways.

[johnsimons]

@burkhartt how about the CPU usage for the RabbitMQ broker ? Is that one ok ?

[burkhartt]

Yes, it is normally at 4-6% throughout the day. When the CPU was spiking for NServiceBus it was down at I want to say 0.3% or something pretty low

[johnsimons]

@burkhartt do you see any other stacktraces ?
Anything related to RabbitMqDequeueStrategy ?

[burkhartt]

System.InvalidOperationException: Rabbit server is not connected.
at NServiceBus.Transports.RabbitMQ.PersistentConnection.CreateModel() in c:\BuildAgent\work\41ea81d808fdfd62\src\NServiceBus.RabbitMQ\PersistentConnection.cs:line 34
at NServiceBus.Transports.RabbitMQ.ChannelProvider.GetNewPublishChannel() in c:\BuildAgent\work\41ea81d808fdfd62\src\NServiceBus.RabbitMQ\ChannelProvider.cs:line 35
at NServiceBus.Transports.RabbitMQ.RabbitMqMessageSender.Send(TransportMessage message, SendOptions sendOptions) in c:\BuildAgent\work\41ea81d808fdfd62\src\NServiceBus.RabbitMQ\RabbitMqMessageSender.cs:line 25
at NServiceBus.Transports.DefaultMessageAuditer.Audit(SendOptions sendOptions, TransportMessage transportMessage) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Audit\DefaultMessageAuditer.cs:line 51
at NServiceBus.Transports.AuditerWrapper.Audit(SendOptions sendOptions, TransportMessage message) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Audit\DefaultMessageAuditer.cs:line 21
at NServiceBus.AuditBehavior.Invoke(IncomingContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Audit\AuditBehavior.cs:line 29
at NServiceBus.CriticalTimeBehavior.Invoke(IncomingContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Monitoring\CriticalTime\CriticalTimeBehavior.cs:line 23
at NServiceBus.Pipeline.PipelineExecutor.Execute[T](BehaviorChain`1 pipelineAction, T context) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Pipeline\PipelineExecutor.cs:line 127
at NServiceBus.Unicast.Transport.TransportReceiver.ProcessMessage(TransportMessage message) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 344
at NServiceBus.Unicast.Transport.TransportReceiver.TryProcess(TransportMessage message) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 230
at NServiceBus.Transports.RabbitMQ.RabbitMqDequeueStrategy.ConsumeMessages(Object state) in c:\BuildAgent\work\41ea81d808fdfd62\src\NServiceBus.RabbitMQ\RabbitMqDequeueStrategy.cs:line 186

[johnsimons]

I can replicate this now.
All we need to do is force a connection close:

[burkhartt]

yay!

[andreasohlund]

Fixed by 23478e5

[burkhartt]

Thank you!

[andreasohlund]

@Loupi this did fix sort out your issue as well?

[Loupi]

Yes it did.

On 2014-12-11, at 16:39, "Andreas Öhlund" [email protected] wrote:

@Loupi this did fix sort out your issue as well?

—
Reply to this email directly or view it on GitHub.