rabbit_disk_monitor:get_disk_free logs an exception due to an os_mon timeout on Windows

[JanEggers]

Describe the bug

we saw this error 400 times yesterday. we try to move the service to a differt vm but it would be nice if this could be fixed.

we use version 3.12 of rabbitmq. erl otp 25.3.2 if helpfull i can upload the whole logfile.

[error] <0.8080.46> ** Generic server rabbit_disk_monitor terminating
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> ** Last message in was update
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> ** When Server state == {state,"c:/Users/iloadmin/AppData/Roaming/RabbitMQ/db/rabbit@nav2-ilo-app-mnesia",
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> 50000000,196707250176,100,10000,
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> #Ref<0.78630618.2602827778.72852>,false,true,
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> 10,120000,
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> {win32,nt},
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> not_used}
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> ** Reason for termination ==
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> ** {{timeout,{gen_server,call,[os_mon_sysinfo,get_disk_info]}},
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> [{gen_server,call,2,[{file,"gen_server.erl"},{line,370}]},
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> {rabbit_disk_monitor,get_disk_free,3,
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> [{file,"rabbit_disk_monitor.erl"},{line,314}]},
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> {rabbit_disk_monitor,internal_update,1,
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> [{file,"rabbit_disk_monitor.erl"},{line,274}]},
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> {rabbit_disk_monitor,handle_info,2,
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> [{file,"rabbit_disk_monitor.erl"},{line,184}]},
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> {gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,1123}]},
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> {gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1200}]},
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46> {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}
2023-06-29 20:28:16.496000+01:00 [error] <0.8080.46>
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> crasher:
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> initial call: rabbit_disk_monitor:init/1
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> pid: <0.8080.46>
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> registered_name: rabbit_disk_monitor
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> exception exit: {timeout,{gen_server,call,[os_mon_sysinfo,get_disk_info]}}
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> in function gen_server:call/2 (gen_server.erl, line 370)
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> in call from rabbit_disk_monitor:get_disk_free/3 (rabbit_disk_monitor.erl, line 314)
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> in call from rabbit_disk_monitor:internal_update/1 (rabbit_disk_monitor.erl, line 274)
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> in call from rabbit_disk_monitor:handle_info/2 (rabbit_disk_monitor.erl, line 184)
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> in call from gen_server:try_dispatch/4 (gen_server.erl, line 1123)
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> in call from gen_server:handle_msg/6 (gen_server.erl, line 1200)
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> ancestors: [rabbit_disk_monitor_sup,rabbit_sup,<0.227.0>]
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> message_queue_len: 0
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> messages: []
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> links: [<0.368.0>]
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> dictionary: []
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> trap_exit: false
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> status: running
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> heap_size: 6772
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> stack_size: 28
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> reductions: 24797
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46> neighbours:
2023-06-29 20:28:17.674000+01:00 [error] <0.8080.46>

Reproduction steps

just run the broker (most likely environment related)

Expected behavior

not crashing :)

Additional context

x

[michaelklishin]

RabbitMQ did not crash, a single optional process that monitors free disk space did due to an operation timeout.

The consequences, besides some log noise, is that one metric won't be available. Free disk space can be monitored by OS and infrastructure level monitoring tools.

[michaelklishin]

Starting with 3.12.2 it will be possible to deactivate free disk space monitoring on a node: #8743.

[JanEggers]

hi @michaelklishin thx for the response. Im just trying to figure out why we have latency issues and it doesnt really help when there are 600K lines in the logfile indicating errors

[michaelklishin]

#8837

[michaelklishin]

Monitoring free disk space on Windows is guaranteed to fail in some environments, the question is how it will fail, not if, and what % is affected.

Use Linux for very predictable free disk space monitoring results.

The exception in question, a timeout of 5s, indeed suggests the node might have been under more load than usual, in particular its likely was low on CPU resources, but possibly the reason could come down to disk I/O (although I doubt it).