Durable queue is removed after power outage

[Fritz Schieber]

Hi,

in our HA-Cluster, we have a persistent queue with attribute durable, however when the whole cluster experiences a power loss and starts after some time up again, the queue is no longer available. 

We are using RabbitMQ 3.9.8 with the rabbitmq-server-ha.ocf resource agent. 

Is this intended behavior? Are durable queues only persistent during node- and not complete site outages? 

Thanks in advance.

BR,

Friedrich

[Luke Bakken]

Hi Friedrich,

We are using RabbitMQ 3.9.8 with the rabbitmq-server-ha.ocf resource agent.

This means you are using OpenStack, correct?

 

Is this intended behavior? Are durable queues only persistent during node- and not complete site outages?

A durable queue will remain until it is deleted. Do you have any other queues that do not recover after a power loss?

Could you please export your definitions so we can check how your policies interact with this durable queue? What is the name of the queue that did not recover?

Are there log messages that contain this queue's name?

Do any applications delete this queue? Anything else that might delete it?

Thanks -
Luke 

[Fritz Schieber]

Hi Luke,

sorry for the lack of information, I'll follow it up now.

I am not using OpenStack or any cloud virtualization - my system consists of multiple RedHat 7.9 VMs that are orchestrated via vSphere and utilize the cluster resource management pacemaker. The resource agent we are using is pretty much the same as this one with a few minor modifications: rabbitmq-server-release/rabbitmq-server-ha.ocf at master · rabbitmq/rabbitmq-server-release · GitHub

Upon a cluster restart (I power off the VMs in vSphere and power them on again to simulate the unexpected power loss), RabbitMQ tries to start up as master/standby - so one node is promoted master and the other joins the cluster. 

In the meantime I found out that our Mnesia DB seems to be flushed on every node during the cluster startup - causing all queues/definitions to be deleted... all other of our services create relevant data (exchanges/queues) on startup, but this specific service is actually not started at all on the standby site which made me notice the error.

Could you please confirm my assumption? 

Node A: 

2022-05-30T15:03:28.164+02:00 10.16.214.21 rabbit[6703] info: rabbit - Node database directory at /var/lib/rabbitmq/mnesia/rabbit@sredxappa is empty. Assuming we need to join an existing cluster or initialise from scratch...

Node B: 

2022-05-30T15:04:52.631+02:00 10.16.214.22 rabbit[32152] info: rabbit - Node database directory at /var/lib/rabbitmq/mnesia/rabbit@sredxappb is empty. Assuming we need to join an existing cluster or initialise from scratch...

This is most likely caused by resource agents call of reset_mnesia(): 

# Return a RabbitMQ node to its virgin state.
# For reset and force_reset to succeed the RabbitMQ application must have been stopped.
# If the app cannot be stopped, beam will be killed and mnesia files will be removed.
reset_mnesia()

...

The restart has been at around 15:00 - find the rabbitmq-server.logs of both servers attached below. 

I also attached the exported definitions from today. 

Thank you for the quick answer! 

Best Regards,

Friedrich

[Luke Bakken]

Hello Friedrich -

Upon a cluster restart (I power off the VMs in vSphere and power them on again to simulate the unexpected power loss), RabbitMQ tries to start up as master/standby - so one node is promoted master and the other joins the cluster. 

In the meantime I found out that our Mnesia DB seems to be flushed on every node during the cluster startup - causing all queues/definitions to be deleted...

Something in your environment is clearing the data in the Mnesia DB directory. RabbitMQ does not do this.

Node A: 

2022-05-30T15:03:28.164+02:00 10.16.214.21 rabbit[6703] info: rabbit - Node database directory at /var/lib/rabbitmq/mnesia/rabbit@sredxappa is empty. Assuming we need to join an existing cluster or initialise from scratch...

Node B: 

2022-05-30T15:04:52.631+02:00 10.16.214.22 rabbit[32152] info: rabbit - Node database directory at /var/lib/rabbitmq/mnesia/rabbit@sredxappb is empty. Assuming we need to join an existing cluster or initialise from scratch...

This is most likely caused by resource agents call of reset_mnesia(): 

# Return a RabbitMQ node to its virgin state.
# For reset and force_reset to succeed the RabbitMQ application must have been stopped.
# If the app cannot be stopped, beam will be killed and mnesia files will be removed.
reset_mnesia()

...

I have no idea why the resource agent does that, but it's not correct in your case. I don't suppose you have a log from the agent?

This isn't related but clusters should have an odd number of nodes. I'm assuming you're using two as a test scenario.

 

Thanks -
Luke

[Fritz Schieber]

Hi Luke,

we have the pacemaker cluster active with 3 nodes, but RabbitMQ is only installed on 2 of those: sredxappa and sredxappb. sredxmgmt is the 3rd node which is also available in the node_list to RabbitMQ, but should not be relevant here. (it fails to be restarted and thats it)

Actually I fetched the logs related to the resource agent, I just forgot to add them. Sorry for that. 

While trying to start the rmq app, the relevant timeout exceeds and a cleanup of the Mnesia DB is triggered - there it detects a corruption and resets it completely. 

2022-05-30T15:02:12.780+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: try_to_start_rmq_app(): Execute start_app with timeout: 55

2022-05-30T15:03:09.160+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: su_rabbit_cmd(): the invoked command exited 124: /usr/sbin/rabbitmqctl start_app >>/var/log/rabbitmq/startup_log 2>&1

2022-05-30T15:03:09.165+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: try_to_start_rmq_app(): start_app failed.

2022-05-30T15:03:09.171+02:00 sredxappa lrmd[] warning: WARNING: resRabbitMQ[12178]: start_rmq_server_app(): RMQ-server app can't start without Mnesia cleaning.

2022-05-30T15:03:10.465+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: get_status(): app rabbit was not found in command output: [{mnesia,"MNESIA  CXC 138 12","4.19"},

 {rabbitmq_prelaunch,"RabbitMQ prelaunch setup","3.9.8"},

 {rabbit_common,"Modules shared by rabbitmq-server and rabbitmq-erlang-client",

 {amqp10_common,"Modules shared by rabbitmq-amqp1.0 and rabbitmq-amqp1.0-client",

2022-05-30T15:03:10.470+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: reset_mnesia(): Execute reset with timeout: 55

2022-05-30T15:03:11.057+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: su_rabbit_cmd(): the invoked command exited 70: /usr/sbin/rabbitmqctl reset

2022-05-30T15:03:11.062+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: reset_mnesia(): Execute force_reset with timeout: 55

2022-05-30T15:03:11.616+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: su_rabbit_cmd(): the invoked command exited 70: /usr/sbin/rabbitmqctl force_reset

2022-05-30T15:03:11.621+02:00 sredxappa lrmd[] warning: WARNING: resRabbitMQ[12178]: reset_mnesia(): Mnesia couldn't cleaned, even by force-reset command.

2022-05-30T15:03:11.633+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: proc_stop(): Stopping beam.*rabbit@sredxappa by PID 18563

2022-05-30T15:03:19.717+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: proc_stop(): Stopped beam.*rabbit@sredxappa

2022-05-30T15:03:19.722+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: proc_stop(): Stopping beam.*rabbit@sredxappa by PID none

2022-05-30T15:03:19.749+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: proc_kill(): cannot find any processes matching the beam.*rabbit@sredxappa, considering target process to be already dead

2022-05-30T15:03:19.753+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: proc_stop(): Stopped beam.*rabbit@sredxappa

2022-05-30T15:03:19.773+02:00 sredxappa lrmd[] warning: WARNING: resRabbitMQ[12178]: reset_mnesia(): Mnesia files appear corrupted and have been removed from /var/lib/rabbitmq/mnesia/rabbit@sredxappa and /var/lib/rabbitmq/Mnesia.rabbit@sredxappa

2022-05-30T15:03:20.374+02:00 sredxappa lrmd[] info: INFO: resRabbitMQ[12178]: get_status(): failed with code 69. Command output: Error: unable to perform an operation on node 'rabbit@sredxappa'. Please see diagnostics information and suggestions below.

 * See the CLI, clustering and networking guides on https://rabbitmq.com/documentation.html to learn more

 * Consult server logs on node rabbit@sredxappa

attempted to contact: [rabbit@sredxappa]

rabbit@sredxappa:

  * epmd reports: node 'rabbit' not running at all

 * node name: 'rabbitmqcli-517-rabbit@sredxappa'

 * effective user's home directory: /var/lib/rabbitmq

After this, the startup process on Node A continues and looks good so far, at some point Node B is instructed to also be restarted: 

2022-05-30T15:04:08.321+02:00 sredxappa lrmd[] warning: WARNING: resRabbitMQ[12178]: get_monitor(): node sredxappb is not connected with us

2022-05-30T15:04:08.326+02:00 sredxappa lrmd[] warning: WARNING: resRabbitMQ[12178]: get_monitor(): Ordering node 'sredxappb' to restart

but this instructed join leads to a failure and mnesia db is reset on Node B as well: 

2022-05-30T15:04:30.008+02:00 sredxappb lrmd[] err: ERROR: resRabbitMQ[18174]: jjj_join: Failed to join the cluster. The mnesia will be reset.

2022-05-30T15:04:30.876+02:00 sredxappb lrmd[] info: INFO: resRabbitMQ[18174]: get_status(): failed with code 69. Command output: Error: unable to perform an operation on node 'rabbit@sredxappb'. Please see diagnostics information and suggestions below.

 * See the CLI, clustering and networking guides on https://rabbitmq.com/documentation.html to learn more

 * Consult server logs on node rabbit@sredxappb

attempted to contact: [rabbit@sredxappb]

rabbit@sredxappb:

  * epmd reports: node 'rabbit' not running at all

 * node name: 'rabbitmqcli-641-rabbit@sredxappb'

 * effective user's home directory: /var/lib/rabbitmq

2022-05-30T15:04:30.881+02:00 sredxappb lrmd[] warning: WARNING: resRabbitMQ[18174]: reset_mnesia(): There is no Beam process running.

2022-05-30T15:04:30.891+02:00 sredxappb lrmd[] warning: WARNING: resRabbitMQ[18174]: proc_stop(): pid param /var/run/rabbitmq/pid is not a file or a number, try match by beam.*rabbit@sredxappb

2022-05-30T15:04:30.897+02:00 sredxappb lrmd[] info: INFO: resRabbitMQ[18174]: proc_stop(): Stopping beam.*rabbit@sredxappb by PID none

2022-05-30T15:04:30.927+02:00 sredxappb lrmd[] info: INFO: resRabbitMQ[18174]: proc_kill(): cannot find any processes matching the beam.*rabbit@sredxappb, considering target process to be already dead

2022-05-30T15:04:30.933+02:00 sredxappb lrmd[] info: INFO: resRabbitMQ[18174]: proc_stop(): Stopped beam.*rabbit@sredxappb

2022-05-30T15:04:30.939+02:00 sredxappb lrmd[] info: INFO: resRabbitMQ[18174]: proc_stop(): Stopping beam.*rabbit@sredxappb by PID none

2022-05-30T15:04:30.972+02:00 sredxappb lrmd[] info: INFO: resRabbitMQ[18174]: proc_kill(): cannot find any processes matching the beam.*rabbit@sredxappb, considering target process to be already dead

2022-05-30T15:04:30.977+02:00 sredxappb lrmd[] info: INFO: resRabbitMQ[18174]: proc_stop(): Stopped beam.*rabbit@sredxappb

2022-05-30T15:04:31.000+02:00 sredxappb lrmd[] warning: WARNING: resRabbitMQ[18174]: reset_mnesia(): Mnesia files appear corrupted and have been removed from /var/lib/rabbitmq/mnesia/rabbit@sredxappb and /var/lib/rabbitmq/Mnesia.rabbit@sredxappb

2022-05-30T15:04:31.005+02:00 sredxappb lrmd[] err: ERROR: resRabbitMQ[18174]: notify: Failed to join the cluster on post-promote. The resource will be restarted.

Maybe the resource definition helps as well: 

primitive resRabbitMQ ocf:rabbitmq:rabbitmq-server-ha \
        op start timeout="360" on-fail="restart" interval="0" \
        op stop timeout="120" interval="0" \
        op monitor timeout="60" interval="27" role="Master" on-fail="restart" \
        op monitor timeout="60" interval="30" on-fail="restart" \
        op promote timeout="150" on-fail="restart" interval="0" \
        op demote timeout="120" interval="0" \
        op notify timeout="180" interval="0" \
        meta failure-timeout="60" failure-timeout="15m" migration-threshold="3" \
        params node_port="5672" policy_file="/usr/lib/rabbitmq/policy/ra_set_policy.sh" stop_epmd="true" epmd_port="5673" mnesia_base="/var/lib/rabbitmq/mnesia" enable_federation="true" allowed_cluster_nodes="sredxappa sredxmgmt sredxappb"

If you have any more ideas or requests I'll be glad to provide more information, but if this is a problem of our configuration + the usage of the rabbitmq-server-ha OCF, I understand that we might need to search the error on our end... 

BR,

Friedrich

[Luke Bakken]

Hello -

I think you need to extend the amount of time given to RabbitMQ to start up, as well as extend the timeout for the various rabbitmqctl commands that are run as part of that OCF script.

Based on the RabbitMQ log files given it does appear as though RabbitMQ is starting up but then is killed due to it taking too long.

I have zero experience with "ocf", "pacemaker", etc. If there's some way to duplicate what you're doing in a local environment (via docker compose, perhaps?) I could try to reproduce it.

Thanks -

Luke

[Fritz Schieber]

Hi,

thanks for the answer - tweaking the timings is something that we have done in the past for the CRM timeouts (start/promote) but not the internal ones that are set within the OCF (like this start app timeout of 55s) - I'll try to update those values and provide feedback. 

I am afraid to rebuild our setup is rather complicated - we've tried to reproduce the issue with slow/multiple iterations startup of RabbitMQ (that can be seen in the logs) in a smaller cluster but it seems to be something that is dependent on the load of the system. 

BR,

Friedrich