Retrieving free disk space on Linux timed out

[dyvol777]

I have RabbitMQ 3.9.16 in docker container with prometheus metrics enabled

in one moment command timed out:
2022-05-06 08:44:01.967944+00:00 [erro] <0.381.0> Command timed out: '/bin/df -kP /bitnami/rabbitmq/mnesia/rabbit@localhost'
full log: rabbit.log
i can run this command and it returns a response quickly

The problem is after that in metrics there are unknown value in metrics and prometheus can not scrape them
rabbitmq_disk_space_available_bytes unknown

In UI there are no value too

Why one timeout causes the given value to be completely broken, instead of being requeried later?

Corelated with #4140

[michaelklishin]

Without a way to reproduce, we can only guess. Starting a subprocess that calls df is not a resource intensive operation but on an overloaded system, it can time out just like any other concurrently started task. There isn't much RabbitMQ can do about that.

If the system is overloaded most of the time, it can keep failing. Free disk space monitor is considered to be an optional component: if it fails, one metric becomes unavailable and the rest of the system keeps operating. There should be other means of monitoring free disk space and
moving that data to Prometheus.

Unless you have a way to reproduce, the best we can do is to bump the timeout. How free disk space
monitoring handles exceptions has been reviewed more than once already.

[dyvol777]

after the first appearance in the logs of an entry with a timeout error, this error is no longer in the logs. but there is no metric value either.

if timeouts happen again and again, shouldn't there be a log about it?

[michaelklishin]

In theory there should be. Can you post at least some portions of the logs? Again, we do not guess in this community.

[dyvol777]

There are logs in my original post. If you need more, please tell me what exactly. but there is nothing else related to the described problem in the logs.

[dyvol777]

repeat here
rabbit.log

[michaelklishin]

2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2> 
2022-05-06 08:45:57.932159+00:00 [erro] <0.16888.2> Error in process <0.16888.2> on node rabbit@localhost with exit value:
2022-05-06 08:45:57.932159+00:00 [erro] <0.16888.2> {undef,[{supervisor2,try_again_restart,
2022-05-06 08:45:57.932159+00:00 [erro] <0.16888.2>                      [<0.380.0>,rabbit_disk_monitor,rabbit_disk_monitor],
2022-05-06 08:45:57.932159+00:00 [erro] <0.16888.2>                      []}]}

may be the culprit. "undef" here means something on the node tries to call a function that does not exist, meaning the disk monitor is not actually restarted as it should be. Which would explain the behavior.

I'd need to find a way to reproduce and then can file a specific issue. At first glance,
the function indeed was never added.

[michaelklishin]

When I say "overloaded" it does not imply any kind of impressive load, just enough to keep all cores (and maybe the disk partition the data directory is on) busy enough with the resource available.
It's pretty common to see RabbitMQ containers to be given a single core. RabbitMQ was not designed
for single core systems, so even with a few connections and active queue replicas some other parts
can be fairly deprived of CPU time.

We don't have any information about the environment or the workload here, so this was just an example.

[michaelklishin]

Coming back to this, it's not obvious to me what may run into the undef:

2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>   crasher:
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     initial call: rabbit_disk_monitor:init/1
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     pid: <0.381.0>
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     registered_name: rabbit_disk_monitor
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     exception error: no function clause matching
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>                      lists:reverse({error,timeout}) (lists.erl, line 147)
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>       in function  string:tokens/2 (string.erl, line 1934)
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>       in call from rabbit_disk_monitor:parse_free_unix/1 (rabbit_disk_monitor.erl, line 262)
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>       in call from rabbit_disk_monitor:internal_update/1 (rabbit_disk_monitor.erl, line 216)
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>       in call from rabbit_disk_monitor:handle_info/2 (rabbit_disk_monitor.erl, line 166)
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>       in call from gen_server:try_dispatch/4 (gen_server.erl, line 695)
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>       in call from gen_server:handle_msg/6 (gen_server.erl, line 771)
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     ancestors: [rabbit_disk_monitor_sup,rabbit_sup,<0.228.0>]
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     message_queue_len: 0
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     messages: []
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     links: [<0.380.0>]
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     dictionary: []
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     trap_exit: false
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     status: running
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     heap_size: 6772
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     stack_size: 29
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>     reductions: 11906731
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0>   neighbours:
2022-05-06 08:44:11.287533+00:00 [erro] <0.381.0> 
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>     supervisor: {local,rabbit_disk_monitor_sup}
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>     errorContext: child_terminated
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>     reason: {function_clause,
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                 [{lists,reverse,
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                      [{error,timeout}],
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                      [{file,"lists.erl"},{line,147}]},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                  {string,tokens,2,[{file,"string.erl"},{line,1934}]},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                  {rabbit_disk_monitor,parse_free_unix,1,
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                      [{file,"rabbit_disk_monitor.erl"},{line,262}]},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                  {rabbit_disk_monitor,internal_update,1,
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                      [{file,"rabbit_disk_monitor.erl"},{line,216}]},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                  {rabbit_disk_monitor,handle_info,2,
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                      [{file,"rabbit_disk_monitor.erl"},{line,166}]},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                  {gen_server,try_dispatch,4,
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                      [{file,"gen_server.erl"},{line,695}]},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                  {gen_server,handle_msg,6,
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                      [{file,"gen_server.erl"},{line,771}]},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                  {proc_lib,init_p_do_apply,3,
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                      [{file,"proc_lib.erl"},{line,226}]}]}
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>     offender: [{pid,<0.381.0>},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                {id,rabbit_disk_monitor},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                {mfargs,{rabbit_disk_monitor,start_link,[50000000]}},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                {restart_type,{transient,1}},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                {shutdown,300000},
2022-05-06 08:44:15.408493+00:00 [erro] <0.380.0>                {child_type,worker}]
2022-05-06 08:45:47.744469+00:00 [erro] <0.16819.2> Command timed out: '/bin/df -kP /bitnami/rabbitmq/mnesia/rabbit@localhost'
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>     supervisor: {local,rabbit_disk_monitor_sup}
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>     errorContext: start_error
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>     reason: {function_clause,
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                 [{lists,reverse,
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                      [{error,timeout}],
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                      [{file,"lists.erl"},{line,147}]},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                  {string,tokens,2,[{file,"string.erl"},{line,1934}]},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                  {rabbit_disk_monitor,parse_free_unix,1,
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                      [{file,"rabbit_disk_monitor.erl"},{line,262}]},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                  {rabbit_disk_monitor,internal_update,1,
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                      [{file,"rabbit_disk_monitor.erl"},{line,216}]},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                  {rabbit_disk_monitor,enable,1,
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                      [{file,"rabbit_disk_monitor.erl"},{line,358}]},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                  {rabbit_disk_monitor,init,1,
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                      [{file,"rabbit_disk_monitor.erl"},{line,129}]},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                  {gen_server,init_it,2,[{file,"gen_server.erl"},{line,423}]},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                  {gen_server,init_it,6,[{file,"gen_server.erl"},{line,390}]}]}
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>     offender: [{pid,<0.381.0>},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                {id,rabbit_disk_monitor},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                {mfargs,{rabbit_disk_monitor,start_link,[50000000]}},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                {restart_type,{transient,1}},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                {shutdown,300000},
2022-05-06 08:45:48.975015+00:00 [erro] <0.380.0>                {child_type,worker}]
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>   crasher:
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     initial call: rabbit_disk_monitor:init/1
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     pid: <0.16819.2>
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     registered_name: []
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     exception error: no function clause matching
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>                      lists:reverse({error,timeout}) (lists.erl, line 147)
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>       in function  string:tokens/2 (string.erl, line 1934)
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>       in call from rabbit_disk_monitor:parse_free_unix/1 (rabbit_disk_monitor.erl, line 262)
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>       in call from rabbit_disk_monitor:internal_update/1 (rabbit_disk_monitor.erl, line 216)
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>       in call from rabbit_disk_monitor:enable/1 (rabbit_disk_monitor.erl, line 358)
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>       in call from rabbit_disk_monitor:init/1 (rabbit_disk_monitor.erl, line 129)
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>       in call from gen_server:init_it/2 (gen_server.erl, line 423)
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>       in call from gen_server:init_it/6 (gen_server.erl, line 390)
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     ancestors: [rabbit_disk_monitor_sup,rabbit_sup,<0.228.0>]
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     message_queue_len: 0
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     messages: []
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     links: [<0.380.0>]
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     dictionary: []
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     trap_exit: false
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     status: running
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     heap_size: 4185
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     stack_size: 29
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>     reductions: 17190
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2>   neighbours:
2022-05-06 08:45:48.975168+00:00 [erro] <0.16819.2> 
2022-05-06 08:45:57.932159+00:00 [erro] <0.16888.2> Error in process <0.16888.2> on node rabbit@localhost with exit value:
2022-05-06 08:45:57.932159+00:00 [erro] <0.16888.2> {undef,[{supervisor2,try_again_restart,
2022-05-06 08:45:57.932159+00:00 [erro] <0.16888.2>                      [<0.380.0>,rabbit_disk_monitor,rabbit_disk_monitor],
2022-05-06 08:45:57.932159+00:00 [erro] <0.16888.2>                      []}]}

[dyvol777]

today we had our rabbit lagging. we debug it a lot, and the problem is that all schedulers in rabbitmq-diagnostics runtime_thread_stats command have 100% usage in ets column (what is it? didn't find any good information about that, can you explain please?) . Increasing number of schedulers solved the problem. After that problem with metric doesn't happen yet. Will observe it for a time and write about results.

[michaelklishin]

ETS is an in-memory key-value store used by the schema database, our Raft implementation and many other things. My best guess is that something was churning through connections or queues a lot.
If increasing the number of schedulers helped this generally means that the node was exhausted of the CPU resources available to it.

I don't see how this is related to this discussion, though.

[dyvol777]

After a week of observations, the problem described in the initial question did not recur. Accordingly, we can conclude that increasing the number of the scheduler solves it. The previous comment described why the decision to increase the number of schedulers was made. I hope this helps a little in finding ways to reproduce / localize the problem

[michaelklishin]

Thank you for reporting back. I still have one thing in mind that can be improved, even though it would take a CPU/scheduler resource exhaustion in order to hit the root cause (a free disk space monitor operation timeout).

[samragu]

Facing same issue with community docker image version 3.9.13. There are no resource limits set on the pods running in OpenShift and seeing this error after upgrading from 3.8.x. df command is not timing out when run manually on the pod. Any help is much appreciated
rabbitmq.log

[lukebakken]

Team RabbitMQ only tests with physical storage devices, so YMMV when using something like CEPH.

At any rate, this PR should fix your issue - #5726

It will ship in the next RabbitMQ release (3.10.8)

[michaelklishin]

By "physical storage" Luke means physical or virtual hardware with standard local filesystem that ships with the operating system.

[samragu]

Understood. However, it should not matter as to what storage is being used as long as df command output is properly parsed. Is the issue here with parsing the output of df command?

[lukebakken]

Is the issue here with parsing the output of df command?

No, your logs show {error,timeout} which means that executing df and getting its output took more than 5 seconds. Like I said, #5726 should fix this due to continually running a shell to execute df (so an intermediate shell is not necessary) as well as not having a timeout.

[samragu]

Thanks for the update. I will test with 3.10.8 when released and report back