"Vhost not found" error on cluster (even though vhost exists)

[Glenn Schmidt]

I'm wondering if anyone has any ideas about the problem i'm experiencing.

1. I've set up a cluster of 2 RabbitMQ nodes, running in Docker containers (via Kubernetes).
   
2. I've created a virtual host, and a user with permission to access the virtual host.
   
3. I can see the virtual host exists, on both nodes, with rabbitmqctl list_vhosts
   
4. I can see the virtual host exists via the HTTP Management UI
   

My application was able to connect to this vhost with AMQP for a while, but then suddenly it started being ejected with the message NOT_ALLOWED - vhost /app-test not found

The RabbitMQ log confirms these errors, on both nodes. An example from one of the nodes is below.

Notice there are several successful connections to the /app_test vhost, but then later it starts reporting the 'not found' condition. When this happens, the only way I've found to make the connections succeed again is to restart one of the cluster nodes. Then both start working normally again.

08-28 01:41:12.133 [info] <0.33.0> Application lager started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:17.192 [info] <0.33.0> Application jsx started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:17.193 [info] <0.33.0> Application crypto started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.624 [info] <0.33.0> Application mnesia started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.624 [info] <0.33.0> Application os_mon started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.625 [info] <0.33.0> Application recon started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.625 [info] <0.33.0> Application cowlib started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.625 [info] <0.33.0> Application xmerl started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.625 [info] <0.33.0> Application inets started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.625 [info] <0.33.0> Application asn1 started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.625 [info] <0.33.0> Application public_key started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.626 [info] <0.33.0> Application ssl started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.626 [info] <0.33.0> Application ranch started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.626 [info] <0.33.0> Application ranch_proxy_protocol started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.632 [info] <0.33.0> Application cowboy started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.632 [info] <0.33.0> Application rabbit_common started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:24.633 [info] <0.244.0> 

 Starting RabbitMQ 3.7.7 on Erlang 20.3.8.1

 Copyright (C) 2007-2018 Pivotal Software, Inc.

 Licensed under the MPL.  See http://www.rabbitmq.com/

  ##  ##

  ##  ##      RabbitMQ 3.7.7. Copyright (C) 2007-2018 Pivotal Software, Inc.

  ##########  Licensed under the MPL.  See http://www.rabbitmq.com/

  ######  ##

  ##########  Logs: <stdout>

              Starting broker...

2018-08-28 01:41:24.634 [info] <0.244.0> 

 node           : rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local

 home dir       : /var/lib/rabbitmq

 config file(s) : /etc/rabbitmq/rabbitmq.conf

 cookie hash    : oajiqguuGI4NsszG2Yg12A==

 log(s)         : <stdout>

 database dir   : /var/lib/rabbitmq/mnesia/rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local

2018-08-28 01:41:25.155 [info] <0.250.0> Memory high watermark set to 200 MiB (209715200 bytes) of 3954 MiB (4146479104 bytes) total

2018-08-28 01:41:25.159 [info] <0.252.0> Enabling free disk space monitoring

2018-08-28 01:41:25.159 [info] <0.252.0> Disk free limit set to 50MB

2018-08-28 01:41:25.162 [info] <0.254.0> Limiting to approx 1048476 file handles (943626 sockets)

2018-08-28 01:41:25.162 [info] <0.255.0> FHC read buffering:  OFF

2018-08-28 01:41:25.162 [info] <0.255.0> FHC write buffering: ON

2018-08-28 01:41:25.277 [info] <0.244.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-08-28 01:41:25.345 [info] <0.244.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-08-28 01:41:25.375 [info] <0.244.0> Waiting for Mnesia tables for 30000 ms, 9 retries left

2018-08-28 01:41:25.375 [info] <0.244.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.

2018-08-28 01:41:25.376 [info] <0.244.0> Priority queues enabled, real BQ is rabbit_variable_queue

2018-08-28 01:41:25.391 [info] <0.318.0> Starting rabbit_node_monitor

2018-08-28 01:41:25.431 [info] <0.244.0> Management plugin: using rates mode 'basic'

2018-08-28 01:41:25.444 [info] <0.350.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local/msg_stores/vhosts/6G3S3EV8QCG8N2I9H4109J310' for vhost '/app_test' exists

2018-08-28 01:41:25.448 [info] <0.350.0> Starting message stores for vhost '/app_test'

2018-08-28 01:41:25.449 [info] <0.354.0> Message store "6G3S3EV8QCG8N2I9H4109J310/msg_store_transient": using rabbit_msg_store_ets_index to provide index

2018-08-28 01:41:25.451 [info] <0.350.0> Started message store of type transient for vhost '/app_test'

2018-08-28 01:41:25.451 [info] <0.357.0> Message store "6G3S3EV8QCG8N2I9H4109J310/msg_store_persistent": using rabbit_msg_store_ets_index to provide index

2018-08-28 01:41:25.460 [info] <0.350.0> Started message store of type persistent for vhost '/app_test'

2018-08-28 01:41:25.529 [info] <0.388.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists

2018-08-28 01:41:25.540 [info] <0.388.0> Starting message stores for vhost '/'

2018-08-28 01:41:25.540 [info] <0.392.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index

2018-08-28 01:41:25.542 [info] <0.388.0> Started message store of type transient for vhost '/'

2018-08-28 01:41:25.543 [info] <0.395.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index

2018-08-28 01:41:25.545 [info] <0.388.0> Started message store of type persistent for vhost '/'

2018-08-28 01:41:25.593 [info] <0.438.0> started TCP Listener on [::]:5672

2018-08-28 01:41:25.607 [info] <0.244.0> Setting up a table for connection tracking on this node: 'tracked_connecti...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:25.609 [info] <0.244.0> Setting up a table for per-vhost connection counting on this node: 'tracked_connection_pe...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:25.609 [info] <0.33.0> Application rabbit started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:25.610 [info] <0.318.0> rabbit on node 'rab...@rabbitmq-1.rabbitmq.ops.svc.cluster.local' up

2018-08-28 01:41:25.610 [info] <0.33.0> Application rabbitmq_web_dispatch started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:25.610 [info] <0.33.0> Application amqp_client started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:25.630 [info] <0.33.0> Application rabbitmq_management_agent started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

2018-08-28 01:41:25.659 [info] <0.494.0> Management plugin started. Port: 15672

2018-08-28 01:41:25.659 [info] <0.600.0> Statistics database started.

2018-08-28 01:41:25.660 [info] <0.33.0> Application rabbitmq_management started on node 'rab...@rabbitmq-0.rabbitmq.ops.svc.cluster.local'

 completed with 3 plugins.

2018-08-28 01:41:26.160 [info] <0.5.0> Server startup complete; 3 plugins started.

 * rabbitmq_management

 * rabbitmq_management_agent

 * rabbitmq_web_dispatch

2018-08-28 04:25:19.992 [info] <0.366.0> Mirrored queue 'jobs' in vhost '/app_test': Adding mirror on node 'rab...@rabbitmq-1.rabbitmq.ops.svc.cluster.local': <9539.15530.20>

2018-08-28 05:54:49.947 [info] <0.4918.0> accepting AMQP connection <0.4918.0> (100.96.2.205:60152 -> 100.96.2.163:5672)

2018-08-28 05:54:49.999 [info] <0.4918.0> connection <0.4918.0> (100.96.2.205:60152 -> 100.96.2.163:5672): user 'app_test' authenticated and granted access to vhost '/app_test'

2018-08-28 05:55:25.984 [warning] <0.4918.0> closing AMQP connection <0.4918.0> (100.96.2.205:60152 -> 100.96.2.163:5672, vhost: '/app_test', user: 'app_test'):

client unexpectedly closed TCP connection

2018-08-28 06:07:26.809 [info] <0.5648.0> accepting AMQP connection <0.5648.0> (100.96.2.205:36370 -> 100.96.2.163:5672)

2018-08-28 06:07:26.895 [info] <0.5648.0> connection <0.5648.0> (100.96.2.205:36370 -> 100.96.2.163:5672): user 'app_test' authenticated and granted access to vhost '/app_test'

2018-08-28 06:07:43.589 [info] <0.5648.0> closing AMQP connection <0.5648.0> (100.96.2.205:36370 -> 100.96.2.163:5672, vhost: '/app_test', user: 'app_test')

2018-08-28 22:01:15.155 [info] <0.19965.0> accepting AMQP connection <0.19965.0> (100.96.2.211:38074 -> 100.96.2.163:5672)

2018-08-28 22:01:15.251 [info] <0.19965.0> connection <0.19965.0> (100.96.2.211:38074 -> 100.96.2.163:5672): user 'app_test' authenticated and granted access to vhost '/app_test'

2018-08-29 00:02:01.860 [info] <0.21768.0> accepting AMQP connection <0.21768.0> (100.96.2.40:48318 -> 100.96.2.163:5672)

2018-08-29 00:02:01.908 [error] <0.21768.0> Error on AMQP connection <0.21768.0> (100.96.2.40:48318 -> 100.96.2.163:5672, user: 'app_test', state: opening):

vhost /app-test not found

2018-08-29 00:02:01.908 [info] <0.21768.0> closing AMQP connection <0.21768.0> (100.96.2.40:48318 -> 100.96.2.163:5672, vhost: 'none', user: 'app_test')

2018-08-29 00:27:05.552 [info] <0.22144.0> accepting AMQP connection <0.22144.0> (100.96.2.40:56772 -> 100.96.2.163:5672)

2018-08-29 00:27:05.607 [error] <0.22144.0> Error on AMQP connection <0.22144.0> (100.96.2.40:56772 -> 100.96.2.163:5672, user: 'app_test', state: opening):

vhost /app-test not found

2018-08-29 00:27:05.608 [info] <0.22144.0> closing AMQP connection <0.22144.0> (100.96.2.40:56772 -> 100.96.2.163:5672, vhost: 'none', user: 'app_test')

2018-08-29 00:37:25.484 [info] <0.22301.0> accepting AMQP connection <0.22301.0> (100.96.2.40:60232 -> 100.96.2.163:5672)

2018-08-29 00:37:25.497 [error] <0.22301.0> Error on AMQP connection <0.22301.0> (100.96.2.40:60232 -> 100.96.2.163:5672, user: 'app_test', state: opening):

vhost /app-test not found

2018-08-29 00:37:25.498 [info] <0.22301.0> closing AMQP connection <0.22301.0> (100.96.2.40:60232 -> 100.96.2.163:5672, vhost: 'none', user: 'app_test')

[Luke Bakken]

Hi Glenn,

The successful connections are to a vhost named /app_test and the errors are for one named (or mis-named, I should say) /app-test

Note the underscore vs dash.

Thanks,

Luke

[Glenn Schmidt]

Wow, am I an idiot. I stared at those configurations, carefully comparing to make sure they were the same. And still couldn't see the underscore.

Thanks. How embarrassing.

[Luke Bakken]

Hi Glenn!

We've all done the same thing at one point. Thanks for letting us know that was the issue.

Luke