RabbitMQ vhost '/' is down

[Umesh Kanase]

Yesterday we experience vhost down issue on production environment. We are on 3.8.0 version. 

"access to vhost '/' refused for user 'someuser': vhost '/' is down"

We did manual reset of RabbitMQ as suggested in below answer

https://stackoverflow.com/questions/58689551/rabbitmq-vhost-is-down-for-user-xyz-even-after-user-has-all-access

However, we are not able to understand what caused the vhost to go down. Any pointers on this will really help. I have pasted rabbitMq logs below. 

Note: We have observed false alerts of insufficient disk space in logs; but server has enough free disk space.

Appreciate your help in advance.

Below are the logs from server

----------------------------------

 Starting RabbitMQ 3.8.0 on Erlang 22.1
 Copyright (C) 2007-2019 Pivotal Software, Inc.
 Licensed under the MPL.  See https://www.rabbitmq.com/
2021-12-15 00:50:19.891 [info] <0.327.0>
 node           : rabbit@someHost
 home dir       : C:\Users\embedmpr.service
 config file(s) : c:/edmmod/data/rabbitmq/rabbitmq.conf
 cookie hash    : jk6dkRCFO10ZgmA9eBok+w==
 log(s)         : c:/edmmod/logs/rabbitmq/rab...@someHost.log
                : c:/edmmod/logs/rabbitmq/rabbit@someHost_upgrade.log
 database dir   : c:/edmmod/data/rabbitmq/db/rabbit@someHost-mnesia
2021-12-15 00:50:19.922 [info] <0.327.0> Running boot step pre_boot defined by app rabbit
2021-12-15 00:50:19.922 [info] <0.327.0> Running boot step rabbit_core_metrics defined by app rabbit
2021-12-15 00:50:19.922 [info] <0.327.0> Running boot step rabbit_alarm defined by app rabbit
2021-12-15 00:50:19.937 [info] <0.342.0> Memory high watermark set to 26214 MiB (27487548211 bytes) of 65535 MiB (68718870528 bytes) total
2021-12-15 00:50:19.969 [info] <0.344.0> Enabling free disk space monitoring
2021-12-15 00:50:19.969 [info] <0.344.0> Disk free limit set to 50MB
2021-12-15 00:50:19.984 [info] <0.327.0> Running boot step code_server_cache defined by app rabbit
2021-12-15 00:50:19.984 [info] <0.327.0> Running boot step file_handle_cache defined by app rabbit
2021-12-15 00:50:19.984 [info] <0.347.0> Limiting to approx 65436 file handles (58890 sockets)
2021-12-15 00:50:19.984 [info] <0.348.0> FHC read buffering:  OFF
2021-12-15 00:50:19.984 [info] <0.348.0> FHC write buffering: ON
2021-12-15 00:50:20.000 [info] <0.327.0> Running boot step worker_pool defined by app rabbit
2021-12-15 00:50:20.000 [info] <0.334.0> Will use 8 processes for default worker pool
2021-12-15 00:50:20.000 [info] <0.334.0> Starting worker pool 'worker_pool' with 8 processes in it
2021-12-15 00:50:20.000 [info] <0.327.0> Running boot step database defined by app rabbit
2021-12-15 00:50:20.000 [info] <0.327.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2021-12-15 00:50:20.000 [info] <0.327.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2021-12-15 00:50:20.062 [info] <0.327.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2021-12-15 00:50:20.062 [info] <0.327.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step database_sync defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step feature_flags defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step codec_correctness_check defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step external_infrastructure defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_registry defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_auth_mechanism_cr_demo defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_queue_location_random defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_event defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_auth_mechanism_amqplain defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_auth_mechanism_plain defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_exchange_type_direct defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_exchange_type_fanout defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_exchange_type_headers defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_exchange_type_topic defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_mirror_queue_mode_all defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_mirror_queue_mode_exactly defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_mirror_queue_mode_nodes defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_priority_queue defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Priority queues enabled, real BQ is rabbit_variable_queue
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_queue_location_client_local defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_queue_location_min_masters defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step kernel_ready defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_sysmon_minder defined by app rabbit
2021-12-15 00:50:20.062 [info] <0.327.0> Running boot step rabbit_epmd_monitor defined by app rabbit
2021-12-15 00:50:20.109 [info] <0.327.0> Running boot step guid_generator defined by app rabbit
2021-12-15 00:50:20.125 [info] <0.327.0> Running boot step rabbit_node_monitor defined by app rabbit
2021-12-15 00:50:20.125 [info] <0.380.0> Starting rabbit_node_monitor
2021-12-15 00:50:20.125 [info] <0.327.0> Running boot step delegate_sup defined by app rabbit
2021-12-15 00:50:20.125 [info] <0.327.0> Running boot step rabbit_memory_monitor defined by app rabbit
2021-12-15 00:50:20.125 [info] <0.327.0> Running boot step core_initialized defined by app rabbit
2021-12-15 00:50:20.125 [info] <0.327.0> Running boot step upgrade_queues defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_connection_tracking defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_connection_tracking_handler defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_exchange_parameters defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_mirror_queue_misc defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_policies defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_policy defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_queue_location_validator defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_quorum_memory_manager defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_vhost_limit defined by app rabbit
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_mgmt_reset_handler defined by app rabbitmq_management
2021-12-15 00:50:20.141 [info] <0.327.0> Running boot step rabbit_mgmt_db_handler defined by app rabbitmq_management_agent
2021-12-15 00:50:20.141 [info] <0.327.0> Management plugin: using rates mode 'basic'
2021-12-15 00:50:20.156 [info] <0.327.0> Running boot step recovery defined by app rabbit
2021-12-15 00:50:20.187 [info] <0.600.0> Making sure data directory 'c:/edmmod/data/rabbitmq/db/rabbit@someHost-mnesia/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists
2021-12-15 00:50:20.187 [error] <0.601.0> CRASH REPORT Process <0.601.0> with 0 neighbours crashed with reason: no match of right hand value {error,{not_a_dets_file,"c:/edmmod/data/rabbitmq/db/rabbit@someHost-mnesia/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/recovery.dets"}} in rabbit_recovery_terms:open_table/1 line 199
2021-12-15 00:50:20.187 [error] <0.600.0> Unable to recover vhost <<"/">> data. Reason {badmatch,{error,{{{badmatch,{error,{not_a_dets_file,"c:/edmmod/data/rabbitmq/db/rabbit@someHost-mnesia/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/recovery.dets"}}},[{rabbit_recovery_terms,open_table,1,[{file,"src/rabbit_recovery_terms.erl"},{line,199}]},{rabbit_recovery_terms,init,1,[{file,"src/rabbit_recovery_terms.erl"},{line,179}]},{gen_server,init_it,2,[{file,"gen_server.erl"},{line,374}]},{gen_server,init_it,6,[{file,"gen_server.erl"},{line,342}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,249}]}]},{child,undefined,rabbit_recovery_terms,{rabbit_recovery_terms,start_link,[<<"/">>]},transient,30000,worker,[rabbit_recovery_terms]}}}}
 Stacktrace [{rabbit_recovery_terms,start,1,[{file,"src/rabbit_recovery_terms.erl"},{line,47}]},{rabbit_queue_index,start,2,[{file,"src/rabbit_queue_index.erl"},{line,516}]},{rabbit_variable_queue,start,2,[{file,"src/rabbit_variable_queue.erl"},{line,480}]},{rabbit_priority_queue,start,2,[{file,"src/rabbit_priority_queue.erl"},{line,94}]},{rabbit_amqqueue,recover_classic_queues,2,[{file,"src/rabbit_amqqueue.erl"},{line,129}]},{rabbit_amqqueue,recover,1,[{file,"src/rabbit_amqqueue.erl"},{line,120}]},{rabbit_vhost,recover,1,[{file,"src/rabbit_vhost.erl"},{line,59}]},{rabbit_vhost_process,init,1,[{file,"src/rabbit_vhost_process.erl"},{line,56}]}]
2021-12-15 00:50:20.187 [error] <0.598.0> Supervisor {<0.598.0>,rabbit_vhost_sup_wrapper} had child rabbit_vhost_process started with rabbit_vhost_process:start_link(<<"/">>) at undefined exit with reason {badmatch,{error,{{{badmatch,{error,{not_a_dets_file,"c:/edmmod/data/rabbitmq/db/rabbit@someHost-mnesia/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/recovery.dets"}}},[{rabbit_recovery_terms,open_table,1,[{file,"src/rabbit_recovery_terms.erl"},{line,199}]},{rabbit_recovery_terms,init,1,[{file,"src/rabbit_recovery_terms.erl"},{line,179}]},{gen_server,init_it,2,[{file,"gen_server.erl"},{line,374}]},{gen_server,init_it,6,[{file,"gen_server.erl"},{line,342}]},{proc_lib,init_p_do_apply,3,[{...},...]}]},...}}} in context start_error
2021-12-15 00:50:20.187 [warning] <0.327.0> Unable to initialize vhost data store for vhost '/'. The vhost will be stopped for this node.  Reason: {shutdown,{failed_to_start_child,rabbit_vhost_process,{badmatch,{error,{{{badmatch,{error,{not_a_dets_file,"c:/edmmod/data/rabbitmq/db/rabbit@someHost-mnesia/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/recovery.dets"}}},[{rabbit_recovery_terms,open_table,1,[{file,"src/rabbit_recovery_terms.erl"},{line,199}]},{rabbit_recovery_terms,init,1,[{file,"src/rabbit_recovery_terms.erl"},{line,179}]},{gen_server,init_it,2,[{file,"gen_server.erl"},{line,374}]},{gen_server,init_it,6,[{file,"gen_server.erl"},{line,342}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,249}]}]},{child,undefined,rabbit_recovery_terms,{rabbit_recovery_terms,start_link,[<<"/">>]},transient,30000,worker,[rabbit_recovery_terms]}}}}}}
2021-12-15 00:50:20.187 [error] <0.600.0> CRASH REPORT Process <0.600.0> with 0 neighbours exited with reason: no match of right hand value {error,{{{badmatch,{error,{not_a_dets_file,"c:/edmmod/data/rabbitmq/db/rabbit@someHost-mnesia/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/recovery.dets"}}},[{rabbit_recovery_terms,open_table,1,[{file,"src/rabbit_recovery_terms.erl"},{line,199}]},{rabbit_recovery_terms,init,1,[{file,"src/rabbit_recovery_terms.erl"},{line,179}]},{gen_server,init_it,2,[{file,"gen_server.erl"},{line,374}]},{gen_server,init_it,6,[{file,"gen_server.erl"},{line,342}]},{proc_lib,init_p_do_apply,3,[{file,"pro..."},...]}]},...}} in gen_server2:init_it/6 line 600
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step load_definitions defined by app rabbitmq_management
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step empty_db_check defined by app rabbit
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step rabbit_looking_glass defined by app rabbit
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step rabbit_core_metrics_gc defined by app rabbit
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step background_gc defined by app rabbit
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step connection_tracking defined by app rabbit
2021-12-15 00:50:20.250 [info] <0.327.0> Setting up a table for connection tracking on this node: 'tracked_connection_on_node_rabbit@someHost'
2021-12-15 00:50:20.250 [info] <0.327.0> Setting up a table for per-vhost connection counting on this node: 'tracked_connection_per_vhost_on_node_rabbit@someHost'
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step routing_ready defined by app rabbit
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step pre_flight defined by app rabbit
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step notify_cluster defined by app rabbit
2021-12-15 00:50:20.250 [info] <0.327.0> Running boot step networking defined by app rabbit
2021-12-15 00:50:20.250 [info] <0.626.0> started TLS (SSL) listener on [::]:5671
2021-12-15 00:50:20.266 [info] <0.642.0> started TLS (SSL) listener on 0.0.0.0:5671
2021-12-15 00:50:20.266 [info] <0.327.0> Running boot step cluster_name defined by app rabbit
2021-12-15 00:50:20.266 [info] <0.327.0> Running boot step direct_client defined by app rabbit
2021-12-15 00:50:20.297 [warning] <0.650.0> Could not find handle.exe, please install from sysinternals
2021-12-15 00:50:20.328 [info] <0.692.0> Management plugin: HTTPS listener started on port 15671
2021-12-15 00:50:20.328 [info] <0.799.0> Statistics database started.
2021-12-15 00:50:20.328 [info] <0.798.0> Starting worker pool 'management_worker_pool' with 3 processes in it
2021-12-15 00:50:20.328 [notice] <0.105.0> Changed loghwm of c:/edmmod/logs/rabbitmq/rab...@someHost.log to 50
2021-12-15 00:50:20.719 [info] <0.8.0> Server startup complete; 3 plugins started.
 * rabbitmq_management
 * rabbitmq_web_dispatch
 * rabbitmq_management_agent
2021-12-15 00:50:21.922 [info] <0.818.0> accepting AMQP connection <0.818.0> ([::1]:55946 -> [::1]:5671)
2021-12-15 00:50:21.969 [error] <0.818.0> Error on AMQP connection <0.818.0> ([::1]:55946 -> [::1]:5671, vhost: 'none', user: 'someUser', state: opening), channel 0:
 {handshake_error,opening,
                 {amqp_error,internal_error,
                             "access to vhost '/' refused for user 'someUser': vhost '/' is down",
                             'connection.open'}}
2021-12-15 00:50:21.984 [info] <0.818.0> closing AMQP connection <0.818.0> ([::1]:55946 -> [::1]:5671, vhost: 'none', user: 'someUser')
2021-12-15 00:50:30.050 [info] <0.887.0> accepting AMQP connection <0.887.0> ([::1]:55968 -> [::1]:5671)
2021-12-15 00:50:30.081 [error] <0.887.0> Error on AMQP connection <0.887.0> ([::1]:55968 -> [::1]:5671, vhost: 'none', user: 'someUser', state: opening), channel 0:
 {handshake_error,opening,
                 {amqp_error,internal_error,
                             "access to vhost '/' refused for user 'someUser': vhost '/' is down",
                             'connection.open'}}

[Frank Hwa]

On 2021/12/16 8:09 Umesh Kanase wrote:
> 2021-12-15 00:50:20.187 [error] <0.600.0> CRASH REPORT Process <0.600.0>
> with 0 neighbours exited with reason: no match of right hand value
> {error,{{{badmatch,{error,{not_a_dets_file,"c:/edmmod/data/rabbitmq/db/rabbit@someHost-mnesia/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L/recovery.dets"}}},[{rabbit_recovery_terms,open_table,1,[{file,"src/rabbit_recovery_terms.erl"},{line,199}]},{rabbit_recovery_terms,init,1,[{file,"src/rabbit_recovery_terms.erl"},{line,179}]},{gen_server,init_it,2,[{file,"gen_server.erl"},{line,374}]},{gen_server,init_it,6,[{file,"gen_server.erl"},{line,342}]},{proc_lib,init_p_do_apply,3,[{file,"pro..."},...]}]},...}}
> in gen_server2:init_it/6 line 600

As the log mentioned there seems have a storage error from the underline
filesystem.

[Umesh Kanase]

Thank you for the reply Frank. 

How this error can be avoided in the future. Based on metric information collected in the monitoring system, there was no low disk space issue on the server; still, RabbitMQ triggered the low disk space alarm. For sure, server disk space never went below 50 MB. And after sometime virtual host went down.  I have attached a complete log file from the server. 

Any pointers on how this error can be avoided or what kind of monitoring can be used to detect these kinds of error will really help.

 2021-12-14 05:08:06.078 [info] <0.340.0> Free disk space is sufficient. Free bytes: 634433536. Limit: 50000000

2021-12-14 05:08:06.078 [warning] <0.336.0> disk resource limit alarm cleared on node 'rabbit@someHost'
2021-12-14 05:08:06.078 [warning] <0.336.0> disk resource limit alarm cleared across the cluster
2021-12-14 05:08:32.796 [info] <0.340.0> Free disk space is insufficient. Free bytes: 47620096. Limit: 50000000
2021-12-14 05:08:32.796 [warning] <0.336.0> disk resource limit alarm set on node 'rabbit@someHost'.

**********************************************************
*** Publishers will be blocked until this alarm clears ***
**********************************************************
2021-12-14 05:18:34.755 [info] <0.340.0> Free disk space is sufficient. Free bytes: 664223744. Limit: 50000000
2021-12-14 05:18:34.755 [warning] <0.336.0> disk resource limit alarm cleared on node 'rabbit@someHost'
2021-12-14 05:18:34.755 [warning] <0.336.0> disk resource limit alarm cleared across the cluster
2021-12-14 05:18:53.861 [info] <0.340.0> Free disk space is insufficient. Free bytes: 41680896. Limit: 50000000
2021-12-14 05:18:53.861 [warning] <0.336.0> disk resource limit alarm set on node 'rabbit@someHost'.

Thanks,

Umesh

[Karthik KB]

Hi All,

I'm also facing this with rabbitmq. Below are the logs for rmq java client trying to connect to rabbitmq server. Is there any solution?

java.io.IOException
        at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:116)
        at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:112)
        at com.rabbitmq.client.impl.AMQChannel.exnWrappingRpc(AMQChannel.java:134)
        at com.rabbitmq.client.impl.AMQConnection.start(AMQConnection.java:388)
        at com.rabbitmq.client.impl.recovery.RecoveryAwareAMQConnectionFactory.newConnection(RecoveryAwareAMQConnectionFactory.java:62)
        at com.rabbitmq.client.impl.recovery.AutorecoveringConnection.init(AutorecoveringConnection.java:99)
        at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:911)
        at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:870)
        at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:828)
        at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:966)
        at com.cisco.queue.rabbitmq.RabbitMQConnection.getConnection(RabbitMQConnection.java:62)

.

.

.
Caused by: com.rabbitmq.client.ShutdownSignalException: connection error; protocol method: #method<connection.close>(reply-code=541, reply-text=INTERNAL_ERROR - access to vhost '/' refused for user 'rabbitmq': vhost '/' is down, class-id=10, method-id=40)