Unable to initialize/recover vhost after autoheal

[Patrick-Remy]

In the last week we encountered two times, that rabbitmq's vhost keeps down after an autoheal. After the first time, we fully reinitialized a new rabbitmq cluster from scratch, and updated from 3.9.13 to latest bugfix version 3.9.15. But it happened again. As the crashing node was the holder of the queues, it broke the full cluster. We will test queue-mirroring to at least don't have the downtime.

Only a manual restart of the rabbitmq instance that had the vhost down helped to recover.

Do you have some idea what caused this?

RabbitMQ Dockerfile

FROM rabbitmq:3.9.15-management-alpine AS production

RUN apk --no-cache add tzdata

# See https://github.com/noxdafox/rabbitmq-message-deduplication/releases
ARG PLUGIN_ELIXIR_VERSION=1.12.2
ARG PLUGIN_DEDUPLICATION_VERSION=0.5.3

# Install and enable plugins
RUN wget -P $RABBITMQ_HOME/plugins/ https://github.com/noxdafox/rabbitmq-message-deduplication/releases/download/${PLUGIN_DEDUPLICATION_VERSION}/elixir-${PLUGIN_ELIXIR_VERSION}.ez \
&& wget -P $RABBITMQ_HOME/plugins/ https://github.com/noxdafox/rabbitmq-message-deduplication/releases/download/${PLUGIN_DEDUPLICATION_VERSION}/rabbitmq_message_deduplication-${PLUGIN_DEDUPLICATION_VERSION}.ez \
&& chown -R rabbitmq:rabbitmq $RABBITMQ_HOME/plugins/ \
&& rabbitmq-plugins enable rabbitmq_management rabbitmq_message_deduplication

# Add advanced.config, this needs to be enabled by setting ENV
# RABBITMQ_ADVANCED_CONFIG_FILE=/opt/rabbitmq/advanced.conf
COPY --chown=rabbitmq:rabbitmq advanced.config $RABBITMQ_HOME/

Logs of www6-rabbitmq

2022-04-21 17:17:19.388643+02:00 [erro] <0.2230.31> ** Node 'rabbit@core-rabbitmq' not responding **
2022-04-21 17:17:19.388643+02:00 [erro] <0.2230.31> ** Removing (timedout) connection **
2022-04-21 17:17:19.388643+02:00 [erro] <0.2230.31> 
2022-04-21 17:17:19.409798+02:00 [erro] <0.29917.81> closing AMQP connection <0.29917.81> (10.110.22.0:43948 -> 10.110.57.230:5672):
2022-04-21 17:17:19.409798+02:00 [erro] <0.29917.81> {handshake_timeout,handshake}
2022-04-21 17:17:19.409836+02:00 [erro] <0.29942.81> closing AMQP connection <0.29942.81> (10.110.22.0:44112 -> 10.110.57.230:5672):
2022-04-21 17:17:19.409836+02:00 [erro] <0.29942.81> {handshake_timeout,handshake}
2022-04-21 17:17:19.410368+02:00 [erro] <0.636.0> Partial partition detected:
2022-04-21 17:17:19.410368+02:00 [erro] <0.636.0>  * We saw DOWN from rabbit@core-rabbitmq
2022-04-21 17:17:19.410368+02:00 [erro] <0.636.0>  * We can still see rabbit@www5-rabbitmq which can see rabbit@core-rabbitmq
2022-04-21 17:17:19.410368+02:00 [erro] <0.636.0> We will therefore intentionally disconnect from rabbit@www5-rabbitmq
2022-04-21 17:17:19.533507+02:00 [erro] <0.387.0> Mnesia('rabbit@www6-rabbitmq'): ** ERROR ** mnesia_event got {inconsistent_database, running_partitioned_network, 'rabbit@core-rabbitmq'}
2022-04-21 17:17:19.533507+02:00 [erro] <0.387.0> 
2022-04-21 17:17:19.667770+02:00 [erro] <0.29939.81> closing AMQP connection <0.29939.81> (10.110.22.0:44682 -> 10.110.57.230:5672):
2022-04-21 17:17:19.667770+02:00 [erro] <0.29939.81> {handshake_timeout,handshake}
2022-04-21 17:17:19.670696+02:00 [erro] <0.29956.81> closing AMQP connection <0.29956.81> (10.110.22.0:44464 -> 10.110.57.230:5672):
2022-04-21 17:17:19.670696+02:00 [erro] <0.29956.81> {handshake_timeout,handshake}
2022-04-21 17:17:19.743043+02:00 [warn] <0.30914.81> global: 'rabbit@www6-rabbitmq' failed to connect to 'rabbit@www5-rabbitmq'
2022-04-21 17:17:19.743043+02:00 [warn] <0.30914.81> 
2022-04-21 17:17:20.182699+02:00 [erro] <0.29980.81> closing AMQP connection <0.29980.81> (10.110.22.0:45572 -> 10.110.57.230:5672):
2022-04-21 17:17:20.182699+02:00 [erro] <0.29980.81> {handshake_timeout,handshake}
2022-04-21 17:17:20.439387+02:00 [erro] <0.387.0> Mnesia('rabbit@www6-rabbitmq'): ** ERROR ** mnesia_event got {inconsistent_database, running_partitioned_network, 'rabbit@www5-rabbitmq'}
2022-04-21 17:17:20.439387+02:00 [erro] <0.387.0> 
2022-04-21 17:17:20.461388+02:00 [warn] <0.636.0> Autoheal: we were selected to restart; winner is 'rabbit@www5-rabbitmq'
2022-04-21 17:17:20.536979+02:00 [warn] <0.849.0> HTTP listener registry could not find context rabbitmq_management_tls
2022-04-21 17:17:20.540034+02:00 [warn] <0.849.0> HTTP listener registry could not find context rabbitmq_prometheus_tls
2022-04-21 17:17:31.073112+02:00 [erro] <0.31870.81> Mnesia('rabbit@www6-rabbitmq'): ** ERROR ** mnesia_event got {inconsistent_database, starting_partitioned_network, 'rabbit@core-rabbitmq'}
2022-04-21 17:17:31.073112+02:00 [erro] <0.31870.81> 
2022-04-21 17:17:31.073287+02:00 [erro] <0.31870.81> Mnesia('rabbit@www6-rabbitmq'): ** ERROR ** mnesia_event got {inconsistent_database, starting_partitioned_network, 'rabbit@www5-rabbitmq'}
2022-04-21 17:17:31.073287+02:00 [erro] <0.31870.81> 

  ##  ##      RabbitMQ 3.9.15
  ##  ##
  ##########  Copyright (c) 2007-2022 VMware, Inc. or its affiliates.
  ######  ##
  ##########  Licensed under the MPL 2.0. Website: https://rabbitmq.com

  Erlang:      24.3.3 [jit]
  TLS Library: OpenSSL - OpenSSL 1.1.1n  15 Mar 2022

  Doc guides:  https://rabbitmq.com/documentation.html
  Support:     https://rabbitmq.com/contact.html
  Tutorials:   https://rabbitmq.com/getstarted.html
  Monitoring:  https://rabbitmq.com/monitoring.html

  Logs: /var/log/rabbitmq/rabbit@www6-rabbitmq_upgrade.log
        <stdout>

  Config file(s): /opt/rabbitmq/advanced.config
                  /etc/rabbitmq/conf.d/10-defaults.conf

  Starting broker...2022-04-21 17:17:31.316321+02:00 [warn] <0.31826.81> Feature flags: the previous instance of this node must have failed to write the `feature_flags` file at `/var/lib/rabbitmq/mnesia/rabbit@www6-rabbitmq-feature_flags`:
2022-04-21 17:17:31.316401+02:00 [warn] <0.31826.81> Feature flags:   - list of previously disabled feature flags now marked as such: [empty_basic_get_metric]
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81> Unable to recover vhost <<"/">> data. Reason {badmatch,{error,not_found}}
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>  Stacktrace [{rabbit_priority_queue,expand_queue,1,
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                     [{file,"rabbit_priority_queue.erl"},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                      {line,112}]},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>              {rabbit_priority_queue,'-expand_queues/1-lc$^0/1-0-',1,
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                     [{file,"rabbit_priority_queue.erl"},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                      {line,109}]},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>              {rabbit_priority_queue,'-expand_queues/1-lc$^0/1-0-',1,
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                     [{file,"rabbit_priority_queue.erl"},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                      {line,109}]},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>              {rabbit_priority_queue,expand_queues,1,
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                     [{file,"rabbit_priority_queue.erl"},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                      {line,109}]},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>              {rabbit_priority_queue,start,2,
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                     [{file,"rabbit_priority_queue.erl"},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                      {line,84}]},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>              {rabbit_priority_queue,start,2,
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                     [{file,"rabbit_priority_queue.erl"},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                      {line,85}]},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>              {rabbit_classic_queue,recover,2,
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                    [{file,"rabbit_classic_queue.erl"},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>                                     {line,124}]},
2022-04-21 17:17:31.900164+02:00 [erro] <0.32154.81>              {timer,tc,3,[{file,"timer.erl"},{line,197}]}]
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>     supervisor: {<0.32159.81>,rabbit_vhost_sup_wrapper}
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>     errorContext: start_error
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>     reason: {badmatch,{error,not_found}}
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>     offender: [{pid,undefined},
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>                {id,rabbit_vhost_process},
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>                {mfargs,{rabbit_vhost_process,start_link,[<<"/">>]}},
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>                {restart_type,permanent},
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>                {significant,false},
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>                {shutdown,300000},
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81>                {child_type,worker}]
2022-04-21 17:17:31.900582+02:00 [erro] <0.32159.81> 
2022-04-21 17:17:31.901016+02:00 [warn] <0.31826.81> Unable to initialize vhost data store for vhost '/'. The vhost will be stopped for this node.  Reason: {shutdown,
2022-04-21 17:17:31.901016+02:00 [warn] <0.31826.81>                                                                                                         {failed_to_start_child,
2022-04-21 17:17:31.901016+02:00 [warn] <0.31826.81>                                                                                                          rabbit_vhost_process,
2022-04-21 17:17:31.901016+02:00 [warn] <0.31826.81>                                                                                                          {badmatch,
2022-04-21 17:17:31.901016+02:00 [warn] <0.31826.81>                                                                                                           {error,
2022-04-21 17:17:31.901016+02:00 [warn] <0.31826.81>                                                                                                            not_found}}}}
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>   crasher:
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     initial call: rabbit_vhost_process:init/1
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     pid: <0.32154.81>
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     registered_name: []
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     exception exit: {badmatch,{error,not_found}}
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>       in function  gen_server2:init_it/6 (gen_server2.erl, line 600)
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     ancestors: [<0.32159.81>,rabbit_vhost_sup_sup,rabbit_sup,<0.31826.81>]
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     message_queue_len: 0
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     messages: []
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     links: [<0.32159.81>]
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     dictionary: []
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     trap_exit: true
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     status: running
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     heap_size: 10958
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     stack_size: 28
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>     reductions: 27000
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81>   neighbours:
2022-04-21 17:17:31.900921+02:00 [erro] <0.32154.81> 
2022-04-21 17:17:32.098818+02:00 [warn] <0.32455.81> closing AMQP connection <0.32455.81> (10.110.22.0:58944 -> 10.110.57.230:5672):
2022-04-21 17:17:32.098818+02:00 [warn] <0.32455.81> client unexpectedly closed TCP connection
2022-04-21 17:17:32.125426+02:00 [erro] <0.32448.81> Error on AMQP connection <0.32448.81> (10.110.22.0:58978 -> 10.110.57.230:5672, vhost: 'none', user: 'xxx', state: opening), channel 0:
2022-04-21 17:17:32.125426+02:00 [erro] <0.32448.81>  {handshake_error,opening,
2022-04-21 17:17:32.125426+02:00 [erro] <0.32448.81>                  {amqp_error,internal_error,
2022-04-21 17:17:32.125426+02:00 [erro] <0.32448.81>                              "access to vhost '/' refused for user 'xxx': vhost '/' is down",

Stack trace references

rabbitmq-server/deps/rabbit/src/rabbit_priority_queue.erl

Lines 111 to 117 in 14807cf

	expand_queue(QName = #resource{name = QNameBin}) ->
	{ok, Q} = rabbit_misc:dirty_read({rabbit_durable_queue, QName}),
	case priorities(Q) of
	none -> [{QName, QName}];
	Ps -> [{QName, QName#resource{name = mutate_name_bin(P, QNameBin)}}
	|| P <- Ps]
	end.

[michaelklishin]

There is a cascade of failures, including a failed feature flag state write.

[Patrick-Remy]

Is there a chance to find the root cause from Logs? Can I provide you more useful information?

[michaelklishin]

We'd need a way to reproduce. I only have a guess as to what may be going on: if the schema table with virtual hosts takes a lot of time to sync, virtual host lookups will fail, and early on boot this can result in cascading failures. But it's only a guess and I don't know what realistically can be done about this before 4.0 when we replace the entire schema data store.

[Patrick-Remy]

This means probably if we detect the partition/reboot in the used RabbitMQ HA-Proxy and do not route high traffic to that node, to reduce vhost lookups, it could prevent the crash?
I'll give it a try to create a reproducible example.

[michaelklishin]

This is something that we see reported a couple of times a year. Might be easier to decommission the node and replace it with a newly added one, and not change the entire design to handle such cases.

[Patrick-Remy]

A recovery must be possible fully automatic. At least this week we encountered it twice and it currently means a downtime until we restart the broken rabbitmq manually.