RabbitMQ closing connections - Generic server rabbit_disk_monitor terminating

[ahmadabuzhir]

Hi,

During load tests we encountered rabbitMQ disconnections - with the following error:

2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> ** Generic server rabbit_disk_monitor terminating
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> ** Last message in was update
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> ** When Server state == {state,"c:/ProgramData/RabbitMQ/db/rabbit@SM-LOAD-COMPS3-mnesia",
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> 50000000,153800716288,100,10000,
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> #Ref<0.2983280143.3224633351.176111>,false,
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> true,10,120000,
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> {win32,nt},
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> not_used}
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> ** Reason for termination ==
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> ** {{badmatch,[]},
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> [{rabbit_disk_monitor,get_disk_free,3,
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> [{file,"rabbit_disk_monitor.erl"},{line,319}]},
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> {rabbit_disk_monitor,internal_update,1,
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> [{file,"rabbit_disk_monitor.erl"},{line,279}]},
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> {rabbit_disk_monitor,handle_info,2,
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> [{file,"rabbit_disk_monitor.erl"},{line,189}]},
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> {gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,1123}]},
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> {gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1200}]},
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0> {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}
2023-02-22 00:01:31.601000+02:00 [error] <0.364.0>
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> crasher:
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> initial call: rabbit_disk_monitor:init/1
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> pid: <0.364.0>
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> registered_name: rabbit_disk_monitor
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> exception error: no match of right hand side value []
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> in function rabbit_disk_monitor:get_disk_free/3 (rabbit_disk_monitor.erl, line 319)
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> in call from rabbit_disk_monitor:internal_update/1 (rabbit_disk_monitor.erl, line 279)
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> in call from rabbit_disk_monitor:handle_info/2 (rabbit_disk_monitor.erl, line 189)
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> in call from gen_server:try_dispatch/4 (gen_server.erl, line 1123)
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> in call from gen_server:handle_msg/6 (gen_server.erl, line 1200)
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> ancestors: [rabbit_disk_monitor_sup,rabbit_sup,<0.226.0>]
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> message_queue_len: 0
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> messages: []
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> links: [<0.363.0>]
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> dictionary: []
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> trap_exit: true
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> status: running
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> heap_size: 6772
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> stack_size: 28
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> reductions: 1407579
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0> neighbours:
2023-02-22 00:01:33.185000+02:00 [error] <0.364.0>
2023-02-22 00:01:45.427000+02:00 [error] <0.24569.156> closing AMQP connection

[michaelklishin]

You are misreading the log: the free disk space monitor failure is not related to a client closing connections. See the timestamps:

2023-02-22 00:01:33.185000+02:00

and then, more than 12 seconds later:

2023-02-22 00:01:45.427000+02:00 [error] <0.24569.156> closing AMQP connection

a clean client connection closure is logged.

There have been multiple free disk space monitor robustness improvements specifically for/on Windows in recent patch releases, such as #5726.

[ahmadabuzhir]

Hi @michaelklishin

Thanks for your reply - so what can be the cause for closing AMQP connection?
2023-02-22 00:01:45.427000+02:00 [error] <0.24569.156> closing AMQP connection <0.24569.156> (10.0.0.4:53266 -> 10.0.0.2:5671 - xxxService.exe):
2023-02-22 00:01:45.427000+02:00 [error] <0.24569.156> {writer,send_failed,closed}

From the Service log (which uses RabbitMQ.client) we got the following error:
2023-02-22 00:01:50,356 [62] ERROR logger - Publish attempt #1 failed at 12:01:50 AM.
RabbitMQ.Client.Exceptions.AlreadyClosedException: Already closed: The AMQP operation was interrupted: AMQP close-reason, initiated by Library, code=541, text='Unexpected Exception', classId=0, methodId=0, cause=System.Net.Sockets.SocketException (0x80004005): A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond
at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
--- End of stack trace from the previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at RabbitMQ.Client.Impl.InboundFrame.ReadFrom(Stream reader, Byte[] frameHeaderBuffer) in //projects/RabbitMQ.Client/client/impl/Frame.cs:line 225
at RabbitMQ.Client.Framing.Impl.Connection.MainLoopIteration() in //projects/RabbitMQ.Client/client/impl/Connection.cs:line 557
at RabbitMQ.Client.Framing.Impl.Connection.MainLoop() in //projects/RabbitMQ.Client/client/impl/Connection.cs:line 499
at RabbitMQ.Client.Impl.SessionBase.Transmit(OutgoingCommand& cmd) in //projects/RabbitMQ.Client/client/impl/SessionBase.cs:line 172
at RabbitMQ.Client.Impl.ModelBase.ModelSend(MethodBase method, ContentHeaderBase header, ReadOnlyMemory1 body) in /_/projects/RabbitMQ.Client/client/impl/ModelBase.cs:line 351 at RabbitMQ.Client.Framing.Impl.Model._Private_BasicPublish(String exchange, String routingKey, Boolean mandatory, IBasicProperties basicProperties, ReadOnlyMemory1 body) in //gensrc/autogenerated-api-0-9-1.cs:line 4398
at RabbitMQ.Client.Impl.ModelBase.BasicPublish(String exchange, String routingKey, Boolean mandatory, IBasicProperties basicProperties, ReadOnlyMemory1 body) in /_/projects/RabbitMQ.Client/client/impl/ModelBase.cs:line 1171 at RabbitMQ.Client.Impl.AutorecoveringModel.BasicPublish(String exchange, String routingKey, Boolean mandatory, IBasicProperties basicProperties, ReadOnlyMemory1 body) in //projects/RabbitMQ.Client/client/impl/AutorecoveringModel.cs:line 1227
at EasyNetQ.RabbitAdvancedBus.<>c__DisplayClass20_0.b__0(IModel model) in C:\projects\easynetq\Source\EasyNetQ\RabbitAdvancedBus.cs:line 293
at EasyNetQ.Producer.ClientCommandDispatcherExtensions.<>c__DisplayClass1_0.b__0(IModel model) in C:\projects\easynetq\Source\EasyNetQ\Producer\ClientCommandDispatcherExtensions.cs:line 29
at EasyNetQ.Producer.PersistentChannel.d__101.MoveNext() in C:\projects\easynetq\Source\EasyNetQ\Producer\PersistentChannel.cs:line 72 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at EasyNetQ.RabbitAdvancedBus.<PublishAsync>d__20.MoveNext() in C:\projects\easynetq\Source\EasyNetQ\RabbitAdvancedBus.cs:line 296 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at EasyNetQ.AdvancedBusExtensions.Publish(IAdvancedBus bus, IExchange exchange, String routingKey, Boolean mandatory, MessageProperties messageProperties, Byte[] body, CancellationToken cancellationToken) in C:\projects\easynetq\Source\EasyNetQ\AdvancedBusExtensions.cs:line 336 at Qognify.Rabbit.Client.Bus.BusHelper.<>c__DisplayClass31_01.b__0() in

Additionally - so what can be the cause for getting this error:
"Generic server rabbit_disk_monitor terminating" --> is it related to "abbit_disk_monitor,get_disk_free" - and what does it mean?

Thanks,

Ahmad.

[michaelklishin]

so what can be the cause for closing AMQP connection?

a client cleanly closed that connection. The closure was client-initiated.

[michaelklishin]

RabbitMQ nodes monitor free disk space on the partition/drive that hosts its data directory so that an alarm can be triggered in case the node runs low.

This is an optional feature: if free disk space monitor fails, you won't have this metric and thus an associated alarms. Nothing else changes.