RabbitMQ 3.8.4 not starting plugins in correct order
289 views
Skip to first unread message
Markus
Jun 2, 2020, 5:14:24 AM6/2/20
to rabbitmq-users
Hi,
I used RabbitMQ 3.8.3 with the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange (custom plugin) plugins enabled. RabbitMQ started fine and the clients were able to connect to RabbitMQ using secured connections. Here is the startup log of RabbitMQ 3.8.3:
2020-05-20 08:03:58.327 [info] <0.323.0>
Starting RabbitMQ 3.8.3 on Erlang 22.2.8
Copyright (c) 2007-2020 Pivotal Software, Inc.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-20 08:03:58.339 [info] <0.323.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rab...@hostname.log
: /var/log/rabbitmq/rabbit@hostname_upgrade.log
database dir : /var/lib/rabbitmq/mnesia/rabbit@hostname
2020-05-20 08:03:58.361 [info] <0.323.0> Running boot step pre_boot defined by app rabbit
2020-05-20 08:03:58.361 [info] <0.323.0> Running boot step rabbit_core_metrics defined by app rabbit
2020-05-20 08:03:58.361 [info] <0.323.0> Running boot step rabbit_alarm defined by app rabbit
2020-05-20 08:03:58.386 [info] <0.340.0> Memory high watermark set to 5475 MiB (5740980224 bytes) of 7821 MiB (8201400320 bytes) total
2020-05-20 08:03:58.397 [info] <0.353.0> Enabling free disk space monitoring
2020-05-20 08:03:58.399 [info] <0.353.0> Disk free limit set to 12302MB
2020-05-20 08:03:58.404 [info] <0.323.0> Running boot step code_server_cache defined by app rabbit
2020-05-20 08:03:58.404 [info] <0.323.0> Running boot step file_handle_cache defined by app rabbit
2020-05-20 08:03:58.404 [info] <0.356.0> Limiting to approx 1048479 file handles (943629 sockets)
2020-05-20 08:03:58.404 [info] <0.357.0> FHC read buffering: OFF
2020-05-20 08:03:58.404 [info] <0.357.0> FHC write buffering: ON
2020-05-20 08:03:58.407 [info] <0.323.0> Running boot step worker_pool defined by app rabbit
2020-05-20 08:03:58.407 [info] <0.327.0> Will use 1 processes for default worker pool
2020-05-20 08:03:58.407 [info] <0.327.0> Starting worker pool 'worker_pool' with 1 processes in it
2020-05-20 08:03:58.407 [info] <0.323.0> Running boot step database defined by app rabbit
2020-05-20 08:03:58.411 [info] <0.323.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-20 08:03:58.411 [info] <0.323.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-20 08:03:58.438 [info] <0.323.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-20 08:03:58.438 [info] <0.323.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.
2020-05-20 08:03:58.438 [info] <0.323.0> Running boot step database_sync defined by app rabbit
2020-05-20 08:03:58.438 [info] <0.323.0> Running boot step feature_flags defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step codec_correctness_check defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step external_infrastructure defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_registry defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_auth_mechanism_cr_demo defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_queue_location_random defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_event defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_auth_mechanism_amqplain defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_auth_mechanism_plain defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_exchange_type_direct defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_exchange_type_fanout defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_exchange_type_headers defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_exchange_type_topic defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_mirror_queue_mode_all defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_mirror_queue_mode_exactly defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_mirror_queue_mode_nodes defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_priority_queue defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Priority queues enabled, real BQ is rabbit_variable_queue
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_queue_location_client_local defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_queue_location_min_masters defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_auth_mechanism_ssl defined by app rabbitmq_auth_mechanism_ssl
2020-05-20 08:03:58.441 [info] <0.323.0> Running boot step presence_exchange defined by app rabbitmq_presence_exchange
2020-05-20 08:03:58.441 [info] <0.323.0> Running boot step kernel_ready defined by app rabbit
2020-05-20 08:03:58.441 [info] <0.323.0> Running boot step rabbit_sysmon_minder defined by app rabbit
2020-05-20 08:03:58.441 [info] <0.323.0> Running boot step rabbit_epmd_monitor defined by app rabbit
2020-05-20 08:03:59.622 [info] <0.376.0> epmd monitor knows us, inter-node communication (distribution) port: 25672
2020-05-20 08:03:59.622 [info] <0.323.0> Running boot step guid_generator defined by app rabbit
2020-05-20 08:03:59.624 [info] <0.323.0> Running boot step rabbit_node_monitor defined by app rabbit
2020-05-20 08:03:59.625 [info] <0.383.0> Starting rabbit_node_monitor
2020-05-20 08:03:59.625 [info] <0.323.0> Running boot step delegate_sup defined by app rabbit
2020-05-20 08:03:59.625 [info] <0.323.0> Running boot step rabbit_memory_monitor defined by app rabbit
2020-05-20 08:03:59.625 [info] <0.323.0> Running boot step core_initialized defined by app rabbit
2020-05-20 08:03:59.625 [info] <0.323.0> Running boot step upgrade_queues defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_connection_tracking defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_connection_tracking_handler defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_exchange_parameters defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_mirror_queue_misc defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_policies defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_policy defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_queue_location_validator defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_quorum_memory_manager defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_vhost_limit defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_mgmt_reset_handler defined by app rabbitmq_management
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_mgmt_db_handler defined by app rabbitmq_management_agent
2020-05-20 08:03:59.652 [info] <0.323.0> Management plugin: using rates mode 'basic'
2020-05-20 08:03:59.653 [info] <0.323.0> Running boot step recovery defined by app rabbit
2020-05-20 08:03:59.654 [error] emulator Discarding message {'$gen_cast',{force_event_refresh,#Ref<0.2804487487.1400897537.156995>}} from <0.323.0> to <0.472.0> in an old incarnation (2) of this node (1)
2020-05-20 08:03:59.654 [error] emulator Discarding message {'$gen_cast',{force_event_refresh,#Ref<0.2804487487.1400897537.156995>}} from <0.323.0> to <0.475.0> in an old incarnation (2) of this node (1)
2020-05-20 08:03:59.654 [error] emulator Discarding message {'$gen_cast',{force_event_refresh,#Ref<0.2804487487.1400897537.156995>}} from <0.323.0> to <0.478.0> in an old incarnation (2) of this node (1)
2020-05-20 08:03:59.654 [error] emulator Discarding message {'$gen_cast',{force_event_refresh,#Ref<0.2804487487.1400897537.156995>}} from <0.323.0> to <0.481.0> in an old incarnation (2) of this node (1)
2020-05-20 08:03:59.656 [info] <0.422.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@hostname/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists
2020-05-20 08:03:59.674 [info] <0.422.0> Starting message stores for vhost '/'
2020-05-20 08:03:59.674 [info] <0.426.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index
2020-05-20 08:03:59.690 [info] <0.422.0> Started message store of type transient for vhost '/'
2020-05-20 08:03:59.690 [info] <0.429.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
2020-05-20 08:03:59.694 [info] <0.422.0> Started message store of type persistent for vhost '/'
2020-05-20 08:03:59.697 [info] <0.457.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@hostname/msg_stores/vhosts/7URI57TLWN6KTJ9UO7C8LCWL1' for vhost 'x' exists
2020-05-20 08:03:59.702 [info] <0.457.0> Starting message stores for vhost 'x'
2020-05-20 08:03:59.702 [info] <0.461.0> Message store "7URI57TLWN6KTJ9UO7C8LCWL1/msg_store_transient": using rabbit_msg_store_ets_index to provide index
2020-05-20 08:03:59.707 [info] <0.457.0> Started message store of type transient for vhost 'x'
2020-05-20 08:03:59.707 [info] <0.464.0> Message store "7URI57TLWN6KTJ9UO7C8LCWL1/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
2020-05-20 08:03:59.711 [info] <0.457.0> Started message store of type persistent for vhost 'x'
2020-05-20 08:03:59.729 [info] <0.323.0> Running boot step load_core_definitions defined by app rabbit
2020-05-20 08:03:59.729 [info] <0.323.0> Running boot step empty_db_check defined by app rabbit
2020-05-20 08:03:59.729 [info] <0.323.0> Running boot step rabbit_looking_glass defined by app rabbit
2020-05-20 08:03:59.729 [info] <0.323.0> Running boot step rabbit_core_metrics_gc defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step background_gc defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step connection_tracking defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Setting up a table for connection tracking on this node: tracked_connection_on_node_rabbit@hostname
2020-05-20 08:03:59.730 [info] <0.323.0> Setting up a table for per-vhost connection counting on this node: tracked_connection_per_vhost_on_node_rabbit@hostname
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step routing_ready defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step pre_flight defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step notify_cluster defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step rabbit_trust_store defined by app rabbitmq_trust_store
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step networking defined by app rabbit
2020-05-20 08:04:02.043 [info] <0.533.0> started TLS (SSL) listener on [::]:5671
2020-05-20 08:04:03.143 [info] <0.323.0> Running boot step cluster_name defined by app rabbit
2020-05-20 08:04:03.143 [info] <0.323.0> Running boot step direct_client defined by app rabbit
2020-05-20 08:04:03.143 [info] <0.323.0> Running boot step os_signal_handler defined by app rabbit
2020-05-20 08:04:03.143 [info] <0.537.0> Swapping OS signal event handler (erl_signal_server) for our own
2020-05-20 08:04:03.246 [error] <0.543.0> Unable to load certificate list for provider rabbit_trust_store_http_provider, reason: {http_error,404,<<"<html><head><title>Error</title></head><body>Not Found</body></html>">>}
2020-05-20 08:04:04.312 [info] <0.602.0> Management plugin: HTTP (non-TLS) listener started on port 15671
2020-05-20 08:04:04.312 [info] <0.709.0> Statistics database started.
2020-05-20 08:04:04.312 [info] <0.708.0> Starting worker pool 'management_worker_pool' with 3 processes in it
2020-05-20 08:04:04.409 [notice] <0.107.0> Changed loghwm of /var/log/rabbitmq/rab...@hostname.log to 50
2020-05-20 08:04:04.751 [info] <0.8.0> Server startup complete; 6 plugins started.
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
2020-05-20 08:04:08.247 [error] <0.543.0> Trust store will attempt to refresh certificates...
2020-05-20 08:04:13.378 [error] <0.543.0> Trust store will attempt to refresh certificates...
After updating to RabbitMQ 3.8.4, clients were not able to connect anymore. After checking the logs I detected that there was a crash and additionally, the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange plugins started last. Here are the logs of RabbitMQ 3.8.4:
2020-05-27 10:35:58.896 [info] <0.267.0>
Starting RabbitMQ 3.8.4 on Erlang 22.2.8
Copyright (c) 2007-2020 VMware, Inc. or its affiliates.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-27 10:35:58.945 [info] <0.267.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rab...@hostname.log
: /var/log/rabbitmq/rabbit@hostname_upgrade.log
database dir : /var/lib/rabbitmq/mnesia/rabbit@hostname
2020-05-27 10:35:58.953 [info] <0.267.0> Running boot step pre_boot defined by app rabbit
2020-05-27 10:35:58.953 [info] <0.267.0> Running boot step rabbit_core_metrics defined by app rabbit
2020-05-27 10:35:58.953 [info] <0.267.0> Running boot step rabbit_alarm defined by app rabbit
2020-05-27 10:35:58.963 [info] <0.415.0> Memory high watermark set to 5475 MiB (5740980224 bytes) of 7821 MiB (8201400320 bytes) total
2020-05-27 10:35:58.969 [info] <0.417.0> Enabling free disk space monitoring
2020-05-27 10:35:58.970 [info] <0.417.0> Disk free limit set to 12302MB
2020-05-27 10:35:58.976 [info] <0.267.0> Running boot step code_server_cache defined by app rabbit
2020-05-27 10:35:58.976 [info] <0.267.0> Running boot step file_handle_cache defined by app rabbit
2020-05-27 10:35:58.976 [info] <0.420.0> Limiting to approx 1048479 file handles (943629 sockets)
2020-05-27 10:35:58.977 [info] <0.421.0> FHC read buffering: OFF
2020-05-27 10:35:58.977 [info] <0.421.0> FHC write buffering: ON
2020-05-27 10:35:58.981 [info] <0.267.0> Running boot step worker_pool defined by app rabbit
2020-05-27 10:35:58.981 [info] <0.386.0> Will use 1 processes for default worker pool
2020-05-27 10:35:58.981 [info] <0.386.0> Starting worker pool 'worker_pool' with 1 processes in it
2020-05-27 10:35:58.981 [info] <0.267.0> Running boot step database defined by app rabbit
2020-05-27 10:35:58.990 [info] <0.267.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-27 10:35:58.991 [info] <0.267.0> Successfully synced tables from a peer
2020-05-27 10:35:58.991 [info] <0.267.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-27 10:35:58.991 [info] <0.267.0> Successfully synced tables from a peer
2020-05-27 10:35:59.009 [info] <0.267.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-27 10:35:59.009 [info] <0.267.0> Successfully synced tables from a peer
2020-05-27 10:35:59.010 [info] <0.267.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.
2020-05-27 10:35:59.010 [info] <0.267.0> Running boot step database_sync defined by app rabbit
2020-05-27 10:35:59.010 [info] <0.267.0> Running boot step feature_flags defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step codec_correctness_check defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step external_infrastructure defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_registry defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step ja defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_queue_location_random defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_event defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_auth_mechanism_amqplain defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_auth_mechanism_plain defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_exchange_type_direct defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_exchange_type_fanout defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_exchange_type_headers defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_exchange_type_topic defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_mirror_queue_mode_all defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_mirror_queue_mode_exactly defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_mirror_queue_mode_nodes defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_priority_queue defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Priority queues enabled, real BQ is rabbit_variable_queue
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_queue_location_client_local defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_queue_location_min_masters defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step kernel_ready defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_sysmon_minder defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_epmd_monitor defined by app rabbit
2020-05-27 10:36:00.179 [info] <0.440.0> epmd monitor knows us, inter-node communication (distribution) port: 25672
2020-05-27 10:36:00.179 [info] <0.267.0> Running boot step guid_generator defined by app rabbit
2020-05-27 10:36:00.184 [info] <0.267.0> Running boot step rabbit_node_monitor defined by app rabbit
2020-05-27 10:36:00.184 [info] <0.446.0> Starting rabbit_node_monitor
2020-05-27 10:36:00.184 [info] <0.267.0> Running boot step delegate_sup defined by app rabbit
2020-05-27 10:36:00.185 [info] <0.267.0> Running boot step rabbit_memory_monitor defined by app rabbit
2020-05-27 10:36:00.185 [info] <0.267.0> Running boot step core_initialized defined by app rabbit
2020-05-27 10:36:00.185 [info] <0.267.0> Running boot step upgrade_queues defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_connection_tracking defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_connection_tracking_handler defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_exchange_parameters defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_mirror_queue_misc defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_policies defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step rabbit_policy defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step rabbit_queue_location_validator defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step rabbit_quorum_memory_manager defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step rabbit_vhost_limit defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step recovery defined by app rabbit
2020-05-27 10:36:00.214 [info] <0.481.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@hostname/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists
2020-05-27 10:36:00.228 [info] <0.481.0> Starting message stores for vhost '/'
2020-05-27 10:36:00.229 [info] <0.485.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index
2020-05-27 10:36:00.232 [info] <0.481.0> Started message store of type transient for vhost '/'
2020-05-27 10:36:00.232 [info] <0.489.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
2020-05-27 10:36:00.235 [info] <0.481.0> Started message store of type persistent for vhost '/'
2020-05-27 10:36:00.238 [info] <0.517.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@hostname/msg_stores/vhosts/7URI57TLWN6KTJ9UO7C8LCWL1' for vhost 'x' exists
2020-05-27 10:36:00.243 [info] <0.517.0> Starting message stores for vhost 'x'
2020-05-27 10:36:00.244 [info] <0.521.0> Message store "7URI57TLWN6KTJ9UO7C8LCWL1/msg_store_transient": using rabbit_msg_store_ets_index to provide index
2020-05-27 10:36:00.247 [info] <0.517.0> Started message store of type transient for vhost 'x'
2020-05-27 10:36:00.248 [info] <0.525.0> Message store "7URI57TLWN6KTJ9UO7C8LCWL1/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
2020-05-27 10:36:00.251 [info] <0.517.0> Started message store of type persistent for vhost 'x'
2020-05-27 10:36:00.263 [warning] <0.558.0> Could not find exchange type x-presence.
2020-05-27 10:36:00.263 [warning] <0.517.0> Could not find exchange type x-presence.
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step definition_import_worker_pool defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.386.0> Starting worker pool 'definition_import_pool' with 1 processes in it
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step load_core_definitions defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step empty_db_check defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step rabbit_looking_glass defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step rabbit_core_metrics_gc defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step background_gc defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step connection_tracking defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Setting up a table for connection tracking on this node: tracked_connection_on_node_rabbit@hostname
2020-05-27 10:36:00.268 [info] <0.267.0> Setting up a table for per-vhost connection counting on this node: tracked_connection_per_vhost_on_node_rabbit@hostname
2020-05-27 10:36:00.268 [info] <0.267.0> Running boot step routing_ready defined by app rabbit
2020-05-27 10:36:00.268 [info] <0.267.0> Running boot step pre_flight defined by app rabbit
2020-05-27 10:36:00.268 [info] <0.267.0> Running boot step notify_cluster defined by app rabbit
2020-05-27 10:36:00.268 [info] <0.267.0> Running boot step networking defined by app rabbit
2020-05-27 10:36:02.723 [error] <0.585.0> Failed to start Ranch listener {acceptor,{0,0,0,0,0,0,0,0},5671} in ranch_ssl:listen([{cacerts,'...'},{key,'...'},{cert,'...'},{ip,{0,0,0,0,0,0,0,0}},{port,5671},inet6,{backlog,128},{nodelay,true},{linger,{true,0}},{exit_on_close,false},{versions,['tlsv1.1','tlsv1.2']},{reuse_sessions,false},{keyfile,"/etc/rabbitmq/ssl/server/key.pem"},{certfile,"/etc/rabbitmq/ssl/server/cert.pem"},{fail_if_no_peer_cert,true},{verify,verify_peer}]) for reason {options,{cacertfile,[]}} (unknown POSIX error)
2020-05-27 10:36:02.730 [info] <0.267.0> Running boot step cluster_name defined by app rabbit
2020-05-27 10:36:02.726 [error] <0.585.0> CRASH REPORT Process <0.585.0> with 0 neighbours exited with reason: {listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}} in ranch_acceptors_sup:listen_error/5 line 66
2020-05-27 10:36:02.731 [info] <0.267.0> Running boot step direct_client defined by app rabbit
2020-05-27 10:36:02.732 [error] <0.583.0> Supervisor {<0.583.0>,ranch_listener_sup} had child ranch_acceptors_sup started with ranch_acceptors_sup:start_link({acceptor,{0,0,0,0,0,0,0,0},5671}, ranch_ssl) at undefined exit with reason {listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}} in context start_error
2020-05-27 10:36:02.733 [error] <0.582.0> Supervisor {<0.582.0>,tcp_listener_sup} had child {ranch_listener_sup,{acceptor,{0,0,0,0,0,0,0,0},5671}} started with ranch_listener_sup:start_link({acceptor,{0,0,0,0,0,0,0,0},5671}, ranch_ssl, #{connection_type => supervisor,handshake_timeout => 5000,max_connections => infinity,num_acceptors => ...,...}, rabbit_connection_sup, []) at undefined exit with reason {shutdown,{failed_to_start_child,ranch_acceptors_sup,{listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}}}} in context start_error
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: list of feature flags found:
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] drop_unroutable_metric
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] empty_basic_get_metric
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] implicit_default_bindings
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] quorum_queue
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] virtual_host_metadata
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: feature flag states written to disk: yes
2020-05-27 10:36:03.567 [info] <0.587.0> Running boot step rabbit_mgmt_db_handler defined by app rabbitmq_management_agent
2020-05-27 10:36:03.567 [info] <0.587.0> Management plugin: using rates mode 'basic'
2020-05-27 10:36:03.646 [info] <0.587.0> Running boot step rabbit_mgmt_reset_handler defined by app rabbitmq_management
2020-05-27 10:36:04.858 [info] <0.654.0> Management plugin: HTTP (non-TLS) listener started on port 15671
2020-05-27 10:36:04.858 [info] <0.761.0> Statistics database started.
2020-05-27 10:36:04.858 [info] <0.760.0> Starting worker pool 'management_worker_pool' with 3 processes in it
2020-05-27 10:36:04.874 [info] <0.587.0> Running boot step rabbit_trust_store defined by app rabbitmq_trust_store
2020-05-27 10:36:06.917 [info] <0.587.0> Running boot step rabbit_auth_mechanism_ssl defined by app rabbitmq_auth_mechanism_ssl
2020-05-27 10:36:06.933 [info] <0.587.0> Running boot step presence_exchange defined by app rabbitmq_presence_exchange
2020-05-27 10:36:06.964 [notice] <0.276.0> Changed loghwm of /var/log/rabbitmq/rab...@hostname.log to 5000
2020-05-27 10:36:07.356 [info] <0.587.0> Server startup complete; 6 plugins started.
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
The crash report looks as follows:
2020-05-27 10:36:02 =ERROR REPORT====
Failed to start Ranch listener {acceptor,{0,0,0,0,0,0,0,0},5671} in ranch_ssl:listen([{cacerts,'...'},{key,'...'},{cert,'...'},{ip,{0,0,0,0,0,0,0,0}},{port,5671},inet6,{backlog,128},
{nodelay,true},{linger,{true,0}},{exit_on_close,false},{versions,['tlsv1.1','tlsv1.2']},{reuse_sessions,false},{keyfile,"/etc/rabbitmq/ssl/server/key.pem"},{certfile,"/etc/rabbitmq/s
sl/server/cert.pem"},{fail_if_no_peer_cert,true},{verify,verify_peer}]) for reason {options,{cacertfile,[]}} (unknown POSIX error)
2020-05-27 10:36:02 =CRASH REPORT====
crasher:
initial call: supervisor:ranch_acceptors_sup/1
pid: <0.585.0>
registered_name: []
exception exit: {{listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}},[{ranch_acceptors_sup,listen_error,5,[{file,"src/ranch_acceptors_sup.erl"},{line,66}]}
,{ranch_acceptors_sup,init,1,[{file,"src/ranch_acceptors_sup.erl"},{line,44}]},{supervisor,init,1,[{file,"supervisor.erl"},{line,295}]},{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}]}]}
ancestors: [<0.583.0>,<0.582.0>,rabbit_sup,<0.267.0>]
message_queue_len: 0
messages: []
links: [<0.583.0>]
dictionary: [{logger,error_logger}]
trap_exit: true
status: running
heap_size: 1598
stack_size: 27
reductions: 12491
neighbours:
2020-05-27 10:36:02 =SUPERVISOR REPORT====
Supervisor: {<0.583.0>,ranch_listener_sup}
Context: start_error
Reason: {listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}}
Offender: [{pid,undefined},{id,ranch_acceptors_sup},{mfargs,{ranch_acceptors_sup,start_link,[{acceptor,{0,0,0,0,0,0,0,0},5671},ranch_ssl]}},{restart_type,permanent},{shutdown,
infinity},{child_type,supervisor}]
2020-05-27 10:36:02 =SUPERVISOR REPORT====
Supervisor: {<0.582.0>,tcp_listener_sup}
Context: start_error
Reason: {shutdown,{failed_to_start_child,ranch_acceptors_sup,{listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}}}}
Offender: [{pid,undefined},{id,{ranch_listener_sup,{acceptor,{0,0,0,0,0,0,0,0},5671}}},{mfargs,{ranch_listener_sup,start_link,[{acceptor,{0,0,0,0,0,0,0,0},5671},ranch_ssl,#{co
nnection_type => supervisor,handshake_timeout => 5000,max_connections => infinity,num_acceptors => 10,socket_opts => [{ip,{0,0,0,0,0,0,0,0}},{port,5671},inet6,{backlog,128},{nodelay,
true},{linger,{true,0}},{exit_on_close,false},{versions,['tlsv1.1','tlsv1.2']},{reuse_sessions,false},{keyfile,"/etc/rabbitmq/ssl/server/key.pem"},{certfile,"/etc/rabbitmq/ssl/server
/cert.pem"},{fail_if_no_peer_cert,true},{verify,verify_peer}]},rabbit_connection_sup,[]]}},{restart_type,permanent},{shutdown,infinity},{child_type,supervisor}]
After downgrading to RabbitMQ 3.8.3 everything works as expected.
Best regards
I used RabbitMQ 3.8.3 with the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange (custom plugin) plugins enabled. RabbitMQ started fine and the clients were able to connect to RabbitMQ using secured connections. Here is the startup log of RabbitMQ 3.8.3:
2020-05-20 08:03:58.327 [info] <0.323.0>
Starting RabbitMQ 3.8.3 on Erlang 22.2.8
Copyright (c) 2007-2020 Pivotal Software, Inc.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-20 08:03:58.339 [info] <0.323.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rab...@hostname.log
: /var/log/rabbitmq/rabbit@hostname_upgrade.log
database dir : /var/lib/rabbitmq/mnesia/rabbit@hostname
2020-05-20 08:03:58.361 [info] <0.323.0> Running boot step pre_boot defined by app rabbit
2020-05-20 08:03:58.361 [info] <0.323.0> Running boot step rabbit_core_metrics defined by app rabbit
2020-05-20 08:03:58.361 [info] <0.323.0> Running boot step rabbit_alarm defined by app rabbit
2020-05-20 08:03:58.386 [info] <0.340.0> Memory high watermark set to 5475 MiB (5740980224 bytes) of 7821 MiB (8201400320 bytes) total
2020-05-20 08:03:58.397 [info] <0.353.0> Enabling free disk space monitoring
2020-05-20 08:03:58.399 [info] <0.353.0> Disk free limit set to 12302MB
2020-05-20 08:03:58.404 [info] <0.323.0> Running boot step code_server_cache defined by app rabbit
2020-05-20 08:03:58.404 [info] <0.323.0> Running boot step file_handle_cache defined by app rabbit
2020-05-20 08:03:58.404 [info] <0.356.0> Limiting to approx 1048479 file handles (943629 sockets)
2020-05-20 08:03:58.404 [info] <0.357.0> FHC read buffering: OFF
2020-05-20 08:03:58.404 [info] <0.357.0> FHC write buffering: ON
2020-05-20 08:03:58.407 [info] <0.323.0> Running boot step worker_pool defined by app rabbit
2020-05-20 08:03:58.407 [info] <0.327.0> Will use 1 processes for default worker pool
2020-05-20 08:03:58.407 [info] <0.327.0> Starting worker pool 'worker_pool' with 1 processes in it
2020-05-20 08:03:58.407 [info] <0.323.0> Running boot step database defined by app rabbit
2020-05-20 08:03:58.411 [info] <0.323.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-20 08:03:58.411 [info] <0.323.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-20 08:03:58.438 [info] <0.323.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-20 08:03:58.438 [info] <0.323.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.
2020-05-20 08:03:58.438 [info] <0.323.0> Running boot step database_sync defined by app rabbit
2020-05-20 08:03:58.438 [info] <0.323.0> Running boot step feature_flags defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step codec_correctness_check defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step external_infrastructure defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_registry defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_auth_mechanism_cr_demo defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_queue_location_random defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_event defined by app rabbit
2020-05-20 08:03:58.439 [info] <0.323.0> Running boot step rabbit_auth_mechanism_amqplain defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_auth_mechanism_plain defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_exchange_type_direct defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_exchange_type_fanout defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_exchange_type_headers defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_exchange_type_topic defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_mirror_queue_mode_all defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_mirror_queue_mode_exactly defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_mirror_queue_mode_nodes defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_priority_queue defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Priority queues enabled, real BQ is rabbit_variable_queue
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_queue_location_client_local defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_queue_location_min_masters defined by app rabbit
2020-05-20 08:03:58.440 [info] <0.323.0> Running boot step rabbit_auth_mechanism_ssl defined by app rabbitmq_auth_mechanism_ssl
2020-05-20 08:03:58.441 [info] <0.323.0> Running boot step presence_exchange defined by app rabbitmq_presence_exchange
2020-05-20 08:03:58.441 [info] <0.323.0> Running boot step kernel_ready defined by app rabbit
2020-05-20 08:03:58.441 [info] <0.323.0> Running boot step rabbit_sysmon_minder defined by app rabbit
2020-05-20 08:03:58.441 [info] <0.323.0> Running boot step rabbit_epmd_monitor defined by app rabbit
2020-05-20 08:03:59.622 [info] <0.376.0> epmd monitor knows us, inter-node communication (distribution) port: 25672
2020-05-20 08:03:59.622 [info] <0.323.0> Running boot step guid_generator defined by app rabbit
2020-05-20 08:03:59.624 [info] <0.323.0> Running boot step rabbit_node_monitor defined by app rabbit
2020-05-20 08:03:59.625 [info] <0.383.0> Starting rabbit_node_monitor
2020-05-20 08:03:59.625 [info] <0.323.0> Running boot step delegate_sup defined by app rabbit
2020-05-20 08:03:59.625 [info] <0.323.0> Running boot step rabbit_memory_monitor defined by app rabbit
2020-05-20 08:03:59.625 [info] <0.323.0> Running boot step core_initialized defined by app rabbit
2020-05-20 08:03:59.625 [info] <0.323.0> Running boot step upgrade_queues defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_connection_tracking defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_connection_tracking_handler defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_exchange_parameters defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_mirror_queue_misc defined by app rabbit
2020-05-20 08:03:59.651 [info] <0.323.0> Running boot step rabbit_policies defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_policy defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_queue_location_validator defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_quorum_memory_manager defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_vhost_limit defined by app rabbit
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_mgmt_reset_handler defined by app rabbitmq_management
2020-05-20 08:03:59.652 [info] <0.323.0> Running boot step rabbit_mgmt_db_handler defined by app rabbitmq_management_agent
2020-05-20 08:03:59.652 [info] <0.323.0> Management plugin: using rates mode 'basic'
2020-05-20 08:03:59.653 [info] <0.323.0> Running boot step recovery defined by app rabbit
2020-05-20 08:03:59.654 [error] emulator Discarding message {'$gen_cast',{force_event_refresh,#Ref<0.2804487487.1400897537.156995>}} from <0.323.0> to <0.472.0> in an old incarnation (2) of this node (1)
2020-05-20 08:03:59.654 [error] emulator Discarding message {'$gen_cast',{force_event_refresh,#Ref<0.2804487487.1400897537.156995>}} from <0.323.0> to <0.475.0> in an old incarnation (2) of this node (1)
2020-05-20 08:03:59.654 [error] emulator Discarding message {'$gen_cast',{force_event_refresh,#Ref<0.2804487487.1400897537.156995>}} from <0.323.0> to <0.478.0> in an old incarnation (2) of this node (1)
2020-05-20 08:03:59.654 [error] emulator Discarding message {'$gen_cast',{force_event_refresh,#Ref<0.2804487487.1400897537.156995>}} from <0.323.0> to <0.481.0> in an old incarnation (2) of this node (1)
2020-05-20 08:03:59.656 [info] <0.422.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@hostname/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists
2020-05-20 08:03:59.674 [info] <0.422.0> Starting message stores for vhost '/'
2020-05-20 08:03:59.674 [info] <0.426.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index
2020-05-20 08:03:59.690 [info] <0.422.0> Started message store of type transient for vhost '/'
2020-05-20 08:03:59.690 [info] <0.429.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
2020-05-20 08:03:59.694 [info] <0.422.0> Started message store of type persistent for vhost '/'
2020-05-20 08:03:59.697 [info] <0.457.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@hostname/msg_stores/vhosts/7URI57TLWN6KTJ9UO7C8LCWL1' for vhost 'x' exists
2020-05-20 08:03:59.702 [info] <0.457.0> Starting message stores for vhost 'x'
2020-05-20 08:03:59.702 [info] <0.461.0> Message store "7URI57TLWN6KTJ9UO7C8LCWL1/msg_store_transient": using rabbit_msg_store_ets_index to provide index
2020-05-20 08:03:59.707 [info] <0.457.0> Started message store of type transient for vhost 'x'
2020-05-20 08:03:59.707 [info] <0.464.0> Message store "7URI57TLWN6KTJ9UO7C8LCWL1/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
2020-05-20 08:03:59.711 [info] <0.457.0> Started message store of type persistent for vhost 'x'
2020-05-20 08:03:59.729 [info] <0.323.0> Running boot step load_core_definitions defined by app rabbit
2020-05-20 08:03:59.729 [info] <0.323.0> Running boot step empty_db_check defined by app rabbit
2020-05-20 08:03:59.729 [info] <0.323.0> Running boot step rabbit_looking_glass defined by app rabbit
2020-05-20 08:03:59.729 [info] <0.323.0> Running boot step rabbit_core_metrics_gc defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step background_gc defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step connection_tracking defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Setting up a table for connection tracking on this node: tracked_connection_on_node_rabbit@hostname
2020-05-20 08:03:59.730 [info] <0.323.0> Setting up a table for per-vhost connection counting on this node: tracked_connection_per_vhost_on_node_rabbit@hostname
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step routing_ready defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step pre_flight defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step notify_cluster defined by app rabbit
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step rabbit_trust_store defined by app rabbitmq_trust_store
2020-05-20 08:03:59.730 [info] <0.323.0> Running boot step networking defined by app rabbit
2020-05-20 08:04:02.043 [info] <0.533.0> started TLS (SSL) listener on [::]:5671
2020-05-20 08:04:03.143 [info] <0.323.0> Running boot step cluster_name defined by app rabbit
2020-05-20 08:04:03.143 [info] <0.323.0> Running boot step direct_client defined by app rabbit
2020-05-20 08:04:03.143 [info] <0.323.0> Running boot step os_signal_handler defined by app rabbit
2020-05-20 08:04:03.143 [info] <0.537.0> Swapping OS signal event handler (erl_signal_server) for our own
2020-05-20 08:04:03.246 [error] <0.543.0> Unable to load certificate list for provider rabbit_trust_store_http_provider, reason: {http_error,404,<<"<html><head><title>Error</title></head><body>Not Found</body></html>">>}
2020-05-20 08:04:04.312 [info] <0.602.0> Management plugin: HTTP (non-TLS) listener started on port 15671
2020-05-20 08:04:04.312 [info] <0.709.0> Statistics database started.
2020-05-20 08:04:04.312 [info] <0.708.0> Starting worker pool 'management_worker_pool' with 3 processes in it
2020-05-20 08:04:04.409 [notice] <0.107.0> Changed loghwm of /var/log/rabbitmq/rab...@hostname.log to 50
2020-05-20 08:04:04.751 [info] <0.8.0> Server startup complete; 6 plugins started.
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
2020-05-20 08:04:08.247 [error] <0.543.0> Trust store will attempt to refresh certificates...
2020-05-20 08:04:13.378 [error] <0.543.0> Trust store will attempt to refresh certificates...
After updating to RabbitMQ 3.8.4, clients were not able to connect anymore. After checking the logs I detected that there was a crash and additionally, the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange plugins started last. Here are the logs of RabbitMQ 3.8.4:
2020-05-27 10:35:58.896 [info] <0.267.0>
Starting RabbitMQ 3.8.4 on Erlang 22.2.8
Copyright (c) 2007-2020 VMware, Inc. or its affiliates.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-27 10:35:58.945 [info] <0.267.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rab...@hostname.log
: /var/log/rabbitmq/rabbit@hostname_upgrade.log
database dir : /var/lib/rabbitmq/mnesia/rabbit@hostname
2020-05-27 10:35:58.953 [info] <0.267.0> Running boot step pre_boot defined by app rabbit
2020-05-27 10:35:58.953 [info] <0.267.0> Running boot step rabbit_core_metrics defined by app rabbit
2020-05-27 10:35:58.953 [info] <0.267.0> Running boot step rabbit_alarm defined by app rabbit
2020-05-27 10:35:58.963 [info] <0.415.0> Memory high watermark set to 5475 MiB (5740980224 bytes) of 7821 MiB (8201400320 bytes) total
2020-05-27 10:35:58.969 [info] <0.417.0> Enabling free disk space monitoring
2020-05-27 10:35:58.970 [info] <0.417.0> Disk free limit set to 12302MB
2020-05-27 10:35:58.976 [info] <0.267.0> Running boot step code_server_cache defined by app rabbit
2020-05-27 10:35:58.976 [info] <0.267.0> Running boot step file_handle_cache defined by app rabbit
2020-05-27 10:35:58.976 [info] <0.420.0> Limiting to approx 1048479 file handles (943629 sockets)
2020-05-27 10:35:58.977 [info] <0.421.0> FHC read buffering: OFF
2020-05-27 10:35:58.977 [info] <0.421.0> FHC write buffering: ON
2020-05-27 10:35:58.981 [info] <0.267.0> Running boot step worker_pool defined by app rabbit
2020-05-27 10:35:58.981 [info] <0.386.0> Will use 1 processes for default worker pool
2020-05-27 10:35:58.981 [info] <0.386.0> Starting worker pool 'worker_pool' with 1 processes in it
2020-05-27 10:35:58.981 [info] <0.267.0> Running boot step database defined by app rabbit
2020-05-27 10:35:58.990 [info] <0.267.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-27 10:35:58.991 [info] <0.267.0> Successfully synced tables from a peer
2020-05-27 10:35:58.991 [info] <0.267.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-27 10:35:58.991 [info] <0.267.0> Successfully synced tables from a peer
2020-05-27 10:35:59.009 [info] <0.267.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2020-05-27 10:35:59.009 [info] <0.267.0> Successfully synced tables from a peer
2020-05-27 10:35:59.010 [info] <0.267.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.
2020-05-27 10:35:59.010 [info] <0.267.0> Running boot step database_sync defined by app rabbit
2020-05-27 10:35:59.010 [info] <0.267.0> Running boot step feature_flags defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step codec_correctness_check defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step external_infrastructure defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_registry defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step ja defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_queue_location_random defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_event defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_auth_mechanism_amqplain defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_auth_mechanism_plain defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_exchange_type_direct defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_exchange_type_fanout defined by app rabbit
2020-05-27 10:35:59.011 [info] <0.267.0> Running boot step rabbit_exchange_type_headers defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_exchange_type_topic defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_mirror_queue_mode_all defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_mirror_queue_mode_exactly defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_mirror_queue_mode_nodes defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_priority_queue defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Priority queues enabled, real BQ is rabbit_variable_queue
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_queue_location_client_local defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_queue_location_min_masters defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step kernel_ready defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_sysmon_minder defined by app rabbit
2020-05-27 10:35:59.012 [info] <0.267.0> Running boot step rabbit_epmd_monitor defined by app rabbit
2020-05-27 10:36:00.179 [info] <0.440.0> epmd monitor knows us, inter-node communication (distribution) port: 25672
2020-05-27 10:36:00.179 [info] <0.267.0> Running boot step guid_generator defined by app rabbit
2020-05-27 10:36:00.184 [info] <0.267.0> Running boot step rabbit_node_monitor defined by app rabbit
2020-05-27 10:36:00.184 [info] <0.446.0> Starting rabbit_node_monitor
2020-05-27 10:36:00.184 [info] <0.267.0> Running boot step delegate_sup defined by app rabbit
2020-05-27 10:36:00.185 [info] <0.267.0> Running boot step rabbit_memory_monitor defined by app rabbit
2020-05-27 10:36:00.185 [info] <0.267.0> Running boot step core_initialized defined by app rabbit
2020-05-27 10:36:00.185 [info] <0.267.0> Running boot step upgrade_queues defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_connection_tracking defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_connection_tracking_handler defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_exchange_parameters defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_mirror_queue_misc defined by app rabbit
2020-05-27 10:36:00.210 [info] <0.267.0> Running boot step rabbit_policies defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step rabbit_policy defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step rabbit_queue_location_validator defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step rabbit_quorum_memory_manager defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step rabbit_vhost_limit defined by app rabbit
2020-05-27 10:36:00.211 [info] <0.267.0> Running boot step recovery defined by app rabbit
2020-05-27 10:36:00.214 [info] <0.481.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@hostname/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists
2020-05-27 10:36:00.228 [info] <0.481.0> Starting message stores for vhost '/'
2020-05-27 10:36:00.229 [info] <0.485.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index
2020-05-27 10:36:00.232 [info] <0.481.0> Started message store of type transient for vhost '/'
2020-05-27 10:36:00.232 [info] <0.489.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
2020-05-27 10:36:00.235 [info] <0.481.0> Started message store of type persistent for vhost '/'
2020-05-27 10:36:00.238 [info] <0.517.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@hostname/msg_stores/vhosts/7URI57TLWN6KTJ9UO7C8LCWL1' for vhost 'x' exists
2020-05-27 10:36:00.243 [info] <0.517.0> Starting message stores for vhost 'x'
2020-05-27 10:36:00.244 [info] <0.521.0> Message store "7URI57TLWN6KTJ9UO7C8LCWL1/msg_store_transient": using rabbit_msg_store_ets_index to provide index
2020-05-27 10:36:00.247 [info] <0.517.0> Started message store of type transient for vhost 'x'
2020-05-27 10:36:00.248 [info] <0.525.0> Message store "7URI57TLWN6KTJ9UO7C8LCWL1/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
2020-05-27 10:36:00.251 [info] <0.517.0> Started message store of type persistent for vhost 'x'
2020-05-27 10:36:00.263 [warning] <0.558.0> Could not find exchange type x-presence.
2020-05-27 10:36:00.263 [warning] <0.517.0> Could not find exchange type x-presence.
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step definition_import_worker_pool defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.386.0> Starting worker pool 'definition_import_pool' with 1 processes in it
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step load_core_definitions defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step empty_db_check defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step rabbit_looking_glass defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step rabbit_core_metrics_gc defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step background_gc defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Running boot step connection_tracking defined by app rabbit
2020-05-27 10:36:00.267 [info] <0.267.0> Setting up a table for connection tracking on this node: tracked_connection_on_node_rabbit@hostname
2020-05-27 10:36:00.268 [info] <0.267.0> Setting up a table for per-vhost connection counting on this node: tracked_connection_per_vhost_on_node_rabbit@hostname
2020-05-27 10:36:00.268 [info] <0.267.0> Running boot step routing_ready defined by app rabbit
2020-05-27 10:36:00.268 [info] <0.267.0> Running boot step pre_flight defined by app rabbit
2020-05-27 10:36:00.268 [info] <0.267.0> Running boot step notify_cluster defined by app rabbit
2020-05-27 10:36:00.268 [info] <0.267.0> Running boot step networking defined by app rabbit
2020-05-27 10:36:02.723 [error] <0.585.0> Failed to start Ranch listener {acceptor,{0,0,0,0,0,0,0,0},5671} in ranch_ssl:listen([{cacerts,'...'},{key,'...'},{cert,'...'},{ip,{0,0,0,0,0,0,0,0}},{port,5671},inet6,{backlog,128},{nodelay,true},{linger,{true,0}},{exit_on_close,false},{versions,['tlsv1.1','tlsv1.2']},{reuse_sessions,false},{keyfile,"/etc/rabbitmq/ssl/server/key.pem"},{certfile,"/etc/rabbitmq/ssl/server/cert.pem"},{fail_if_no_peer_cert,true},{verify,verify_peer}]) for reason {options,{cacertfile,[]}} (unknown POSIX error)
2020-05-27 10:36:02.730 [info] <0.267.0> Running boot step cluster_name defined by app rabbit
2020-05-27 10:36:02.726 [error] <0.585.0> CRASH REPORT Process <0.585.0> with 0 neighbours exited with reason: {listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}} in ranch_acceptors_sup:listen_error/5 line 66
2020-05-27 10:36:02.731 [info] <0.267.0> Running boot step direct_client defined by app rabbit
2020-05-27 10:36:02.732 [error] <0.583.0> Supervisor {<0.583.0>,ranch_listener_sup} had child ranch_acceptors_sup started with ranch_acceptors_sup:start_link({acceptor,{0,0,0,0,0,0,0,0},5671}, ranch_ssl) at undefined exit with reason {listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}} in context start_error
2020-05-27 10:36:02.733 [error] <0.582.0> Supervisor {<0.582.0>,tcp_listener_sup} had child {ranch_listener_sup,{acceptor,{0,0,0,0,0,0,0,0},5671}} started with ranch_listener_sup:start_link({acceptor,{0,0,0,0,0,0,0,0},5671}, ranch_ssl, #{connection_type => supervisor,handshake_timeout => 5000,max_connections => infinity,num_acceptors => ...,...}, rabbit_connection_sup, []) at undefined exit with reason {shutdown,{failed_to_start_child,ranch_acceptors_sup,{listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}}}} in context start_error
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: list of feature flags found:
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] drop_unroutable_metric
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] empty_basic_get_metric
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] implicit_default_bindings
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] quorum_queue
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: [ ] virtual_host_metadata
2020-05-27 10:36:03.378 [info] <0.587.0> Feature flags: feature flag states written to disk: yes
2020-05-27 10:36:03.567 [info] <0.587.0> Running boot step rabbit_mgmt_db_handler defined by app rabbitmq_management_agent
2020-05-27 10:36:03.567 [info] <0.587.0> Management plugin: using rates mode 'basic'
2020-05-27 10:36:03.646 [info] <0.587.0> Running boot step rabbit_mgmt_reset_handler defined by app rabbitmq_management
2020-05-27 10:36:04.858 [info] <0.654.0> Management plugin: HTTP (non-TLS) listener started on port 15671
2020-05-27 10:36:04.858 [info] <0.761.0> Statistics database started.
2020-05-27 10:36:04.858 [info] <0.760.0> Starting worker pool 'management_worker_pool' with 3 processes in it
2020-05-27 10:36:04.874 [info] <0.587.0> Running boot step rabbit_trust_store defined by app rabbitmq_trust_store
2020-05-27 10:36:06.917 [info] <0.587.0> Running boot step rabbit_auth_mechanism_ssl defined by app rabbitmq_auth_mechanism_ssl
2020-05-27 10:36:06.933 [info] <0.587.0> Running boot step presence_exchange defined by app rabbitmq_presence_exchange
2020-05-27 10:36:06.964 [notice] <0.276.0> Changed loghwm of /var/log/rabbitmq/rab...@hostname.log to 5000
2020-05-27 10:36:07.356 [info] <0.587.0> Server startup complete; 6 plugins started.
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
The crash report looks as follows:
2020-05-27 10:36:02 =ERROR REPORT====
Failed to start Ranch listener {acceptor,{0,0,0,0,0,0,0,0},5671} in ranch_ssl:listen([{cacerts,'...'},{key,'...'},{cert,'...'},{ip,{0,0,0,0,0,0,0,0}},{port,5671},inet6,{backlog,128},
{nodelay,true},{linger,{true,0}},{exit_on_close,false},{versions,['tlsv1.1','tlsv1.2']},{reuse_sessions,false},{keyfile,"/etc/rabbitmq/ssl/server/key.pem"},{certfile,"/etc/rabbitmq/s
sl/server/cert.pem"},{fail_if_no_peer_cert,true},{verify,verify_peer}]) for reason {options,{cacertfile,[]}} (unknown POSIX error)
2020-05-27 10:36:02 =CRASH REPORT====
crasher:
initial call: supervisor:ranch_acceptors_sup/1
pid: <0.585.0>
registered_name: []
exception exit: {{listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}},[{ranch_acceptors_sup,listen_error,5,[{file,"src/ranch_acceptors_sup.erl"},{line,66}]}
,{ranch_acceptors_sup,init,1,[{file,"src/ranch_acceptors_sup.erl"},{line,44}]},{supervisor,init,1,[{file,"supervisor.erl"},{line,295}]},{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}]}]}
ancestors: [<0.583.0>,<0.582.0>,rabbit_sup,<0.267.0>]
message_queue_len: 0
messages: []
links: [<0.583.0>]
dictionary: [{logger,error_logger}]
trap_exit: true
status: running
heap_size: 1598
stack_size: 27
reductions: 12491
neighbours:
2020-05-27 10:36:02 =SUPERVISOR REPORT====
Supervisor: {<0.583.0>,ranch_listener_sup}
Context: start_error
Reason: {listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}}
Offender: [{pid,undefined},{id,ranch_acceptors_sup},{mfargs,{ranch_acceptors_sup,start_link,[{acceptor,{0,0,0,0,0,0,0,0},5671},ranch_ssl]}},{restart_type,permanent},{shutdown,
infinity},{child_type,supervisor}]
2020-05-27 10:36:02 =SUPERVISOR REPORT====
Supervisor: {<0.582.0>,tcp_listener_sup}
Context: start_error
Reason: {shutdown,{failed_to_start_child,ranch_acceptors_sup,{listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}}}}}
Offender: [{pid,undefined},{id,{ranch_listener_sup,{acceptor,{0,0,0,0,0,0,0,0},5671}}},{mfargs,{ranch_listener_sup,start_link,[{acceptor,{0,0,0,0,0,0,0,0},5671},ranch_ssl,#{co
nnection_type => supervisor,handshake_timeout => 5000,max_connections => infinity,num_acceptors => 10,socket_opts => [{ip,{0,0,0,0,0,0,0,0}},{port,5671},inet6,{backlog,128},{nodelay,
true},{linger,{true,0}},{exit_on_close,false},{versions,['tlsv1.1','tlsv1.2']},{reuse_sessions,false},{keyfile,"/etc/rabbitmq/ssl/server/key.pem"},{certfile,"/etc/rabbitmq/ssl/server
/cert.pem"},{fail_if_no_peer_cert,true},{verify,verify_peer}]},rabbit_connection_sup,[]]}},{restart_type,permanent},{shutdown,infinity},{child_type,supervisor}]
After downgrading to RabbitMQ 3.8.3 everything works as expected.
Best regards
Wesley Peng
Jun 2, 2020, 6:06:19 AM6/2/20
to rabbitm...@googlegroups.com
Maybe this is not a version issue but you can check this news,
Thanks
--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/eb153f78-da17-4c28-9cfb-84245eaa80bd%40googlegroups.com.
Michael Klishin
Jun 2, 2020, 10:00:48 AM6/2/20
to rabbitm...@googlegroups.com
There is no evidence of a plugin startup order issue of any kind. The exception is reported by a core TLS listener (AMQP 0-9-1, AMQP 1.0).
Curiously the exception says
- {listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}
So your CA certificate file path is an empty string according to this stack trace.
Can your configuration files be shared?
--
Markus
Jun 3, 2020, 2:02:38 AM6/3/20
to rabbitmq-users
I thought about an order problem because the log states that the two plugins are started at the end of the boot process. Additionally, the log indicates the following lines:
2020-05-27 10:36:00.263 [warning] <0.558.0> Could not find exchange type x-presence.
2020-05-27 10:36:00.263 [warning] <0.517.0> Could not find exchange type x-presence.
2020-05-27 10:36:00.263 [warning] <0.517.0> Could not find exchange type x-presence.
which tells me that the rabbitmq_presence_exchange plugin was not yet initialized as this defines the x-presence type. In the log of RabbitMQ 3.8.3 these lines do not appear.
Regarding the TLS problem, the same configuration is used. There is no shared configuration. I also setup a fresh installation with the same configuration files copied to /etc/rabbitmq and I had the same behaviour. Hence, something has changed between 3.8.3 and 3.8.4.
I do not specify the ssl option "cacertfile" in rabbitmq.conf, I only use the ssl option "certfile" which points to a self-signed certificate (which was created according to https://www.rabbitmq.com/ssl.html#manual-certificate-generation). Is it now mandatory to define "ssl_options.cacertfile"? As mentioned before, the configuration worked as is until 3.8.4.
There is no evidence of a plugin startup order issue of any kind. The exception is reported by a core TLS listener (AMQP 0-9-1, AMQP 1.0).
Curiously the exception says
- {listen_error,{acceptor,{0,0,0,0,0,0,0,0},5671},{options,{cacertfile,[]}
So your CA certificate file path is an empty string according to this stack trace.
Can your configuration files be shared?
On 02.06.2020, 12:14, rabbit...@googlegroups.com on behalf of Markus wrote:
Hi,
I used RabbitMQ 3.8.3 with the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange (custom plugin) plugins enabled. RabbitMQ started fine and the clients were able to connect to RabbitMQ using secured connections. Here is the startup log of RabbitMQ 3.8.3:
2020-05-20 08:03:58.327 [info] <0.323.0>
Starting RabbitMQ 3.8.3 on Erlang 22.2.8
Copyright (c) 2007-2020 Pivotal Software, Inc.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-20 08:03:58.339 [info] <0.323.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rabbit@hostname.log
2020-05-20 08:04:04.409 [notice] <0.107.0> Changed loghwm of /var/log/rabbitmq/rabbit@hostname.log to 50
2020-05-20 08:04:04.751 [info] <0.8.0> Server startup complete; 6 plugins started.
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
2020-05-20 08:04:08.247 [error] <0.543.0> Trust store will attempt to refresh certificates...
2020-05-20 08:04:13.378 [error] <0.543.0> Trust store will attempt to refresh certificates...
After updating to RabbitMQ 3.8.4, clients were not able to connect anymore. After checking the logs I detected that there was a crash and additionally, the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange plugins started last. Here are the logs of RabbitMQ 3.8.4:
2020-05-27 10:35:58.896 [info] <0.267.0>
Starting RabbitMQ 3.8.4 on Erlang 22.2.8
Copyright (c) 2007-2020 VMware, Inc. or its affiliates.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-27 10:35:58.945 [info] <0.267.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rabbit@hostname.log
2020-05-27 10:36:06.964 [notice] <0.276.0> Changed loghwm of /var/log/rabbitmq/rabbit@hostname.log to 5000
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitm...@googlegroups.com.
Markus
Jun 3, 2020, 5:42:24 AM6/3/20
to rabbitmq-users
Here is the configuration file (I removed unecessary information and point the truststore url to a dummy):
listeners.tcp = none
listeners.ssl.default = 5671
ssl_options.versions.1 = tlsv1.2
ssl_options.versions.2 = tlsv1.1
ssl_options.certfile = /etc/rabbitmq/ssl/server/cert.pem
ssl_options.keyfile = /etc/rabbitmq/ssl/server/key.pem
# cacert
#ssl_options.cacertfile = /etc/rabbitmq/ssl/testca/cacert.pem
listeners.ssl.default = 5671
ssl_options.versions.1 = tlsv1.2
ssl_options.versions.2 = tlsv1.1
ssl_options.certfile = /etc/rabbitmq/ssl/server/cert.pem
ssl_options.keyfile = /etc/rabbitmq/ssl/server/key.pem
# cacert
#ssl_options.cacertfile = /etc/rabbitmq/ssl/testca/cacert.pem
# path to a pem without content
ssl_options.cacertfile = /etc/rabbitmq/ssl/empty.pem
ssl_options.verify = verify_peer
ssl_options.fail_if_no_peer_cert = true
ssl_options.reuse_sessions = false
auth_mechanisms.1 = EXTERNAL
ssl_cert_login_from = common_name
ssl_options.cacertfile = /etc/rabbitmq/ssl/empty.pem
ssl_options.verify = verify_peer
ssl_options.fail_if_no_peer_cert = true
ssl_options.reuse_sessions = false
auth_mechanisms.1 = EXTERNAL
ssl_cert_login_from = common_name
management.listener.port = 15671
management.listener.ssl = false
management.listener.ssl_opts.certfile = /etc/rabbitmq/ssl/server/cert.pem
management.listener.ssl_opts.keyfile = /etc/rabbitmq/ssl/server/key.pem
# No management.listener.ssl_opts.cacertfile
vm_memory_high_watermark.relative = 0.7
vm_memory_high_watermark_paging_ratio = 0.75
disk_free_limit.relative = 1.5
## Certificate Whitelisting
# See https://github.com/rabbitmq/rabbitmq-trust-store#http-provider for details.
trust_store.refresh_interval = 5
#trust_store.ssl_options.certfile = /etc/rabbitmq/ssl/server/cert.pem
#trust_store.ssl_options.keyfile = /etc/rabbitmq/ssl/server/key.pem
trust_store.providers.1 = http
trust_store.url = http://<server>:<port>/whitelist
cluster_formation.peer_discovery_backend = rabbit_peer_discovery_classic_config
#cluster_formation.classic_config.nodes.1 = rabbit@hostname1
#cluster_formation.classic_config.nodes.2 = rabbit@hostname2
management.listener.ssl = false
management.listener.ssl_opts.certfile = /etc/rabbitmq/ssl/server/cert.pem
management.listener.ssl_opts.keyfile = /etc/rabbitmq/ssl/server/key.pem
# No management.listener.ssl_opts.cacertfile
vm_memory_high_watermark.relative = 0.7
vm_memory_high_watermark_paging_ratio = 0.75
disk_free_limit.relative = 1.5
## Certificate Whitelisting
# See https://github.com/rabbitmq/rabbitmq-trust-store#http-provider for details.
trust_store.refresh_interval = 5
#trust_store.ssl_options.certfile = /etc/rabbitmq/ssl/server/cert.pem
#trust_store.ssl_options.keyfile = /etc/rabbitmq/ssl/server/key.pem
trust_store.providers.1 = http
trust_store.url = http://<server>:<port>/whitelist
cluster_formation.peer_discovery_backend = rabbit_peer_discovery_classic_config
#cluster_formation.classic_config.nodes.1 = rabbit@hostname1
#cluster_formation.classic_config.nodes.2 = rabbit@hostname2
---
Additionally, here is the list of enabled plugins:
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
Having the ssl_options.cacertfile specified and pointing to a valid or empty cacert file, RabbitMQ 3.8.4 starts without the error message of the missing cacertfile (whereas RabbitMQ 3.8.3 does not need it at all). Still there is the connection issue persisting.
After some tests we detected the following additional issue (besides the now mandatory definition of the cacertfile, and the issue with the x-presence type):
RabbitMQ retrieves via the rabbitmq_trust_store plugin the certificates from the whilelist server, the client tries to connect to RabbitMQ 3.8.4 but gets rejected during handshake with "bad_certificate". Downgrading to RabbitMQ 3.8.3 with the same version Erlang 22.2.8 and without changing the configuration or certificates, everything works as expected (client can connect with its certificate).
Thus, it seems there are the following issues:
1.) rabbitmq_presence_exchange plugin is started too late in RabbitMQ 3.8.4
2.) ssl_options.cacertfile is now mandatory in RabbitMQ 3.8.4
3.) retrieved certificates from rabbitmq_trust_store plugin are not handled correctly anymore in RabbitMQ 3.8.4
Please note that I tested with the following Erlang versions:
* Erlang 22.2.8 (with RabbitMQ 3.8.3 and 3.8.4)
* Erlang 22.3.4.1 (with RabbitMQ 3.8.3 and 3.8.4)
* Erlang 23.0.2 (with RabbitMQ 3.8.4)
Best regards
Michael Klishin
Jun 3, 2020, 9:44:27 AM6/3/20
to rabbitm...@googlegroups.com
Two things have changed:
- How a node starts its dependencies, including plugins, on boot
- How the config file generated from rabbitmq.conf is merged with advanced.config
I cannot comment on the latter since I do not understandd what the “ssl option certfile” is. Supposedly it is `ssl_options.cacertfile`
but in advanced.config but this is just a guess. If you could put together a minimalistic example config files that demonstrate
the difference using, say, tls-gen’s basic profile (so that you don’t have to share anything sensitive), we’d be able to see if the behavior is expected.
CA certificate file has never been optional, no matter what file it was configured in, as it is not optional in the peer verification process.
As for the dependency startup change, it sounds very much like the discussion in [1]. Do your clients connect to RabbitMQ *immediately* after
It binds to a port? In that case they have a natural race condition with plugin activation, which includes exchange type registration. Subsequent client operations will succeed.
Introducing a couple of seconds of delay before application start is all it takes to avoid the exception you see if your clients cannot retry the operation.
log(s) : /var/log/rabbitmq/rab...@hostname.log
2020-05-20 08:04:04.409 [notice] <0.107.0> Changed loghwm of /var/log/rabbitmq/rab...@hostname.log to 50
2020-05-20 08:04:04.751 [info] <0.8.0> Server startup complete; 6 plugins started.
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
2020-05-20 08:04:08.247 [error] <0.543.0> Trust store will attempt to refresh certificates...
2020-05-20 08:04:13.378 [error] <0.543.0> Trust store will attempt to refresh certificates...
After updating to RabbitMQ 3.8.4, clients were not able to connect anymore. After checking the logs I detected that there was a crash and additionally, the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange plugins started last. Here are the logs of RabbitMQ 3.8.4:
2020-05-27 10:35:58.896 [info] <0.267.0>
Starting RabbitMQ 3.8.4 on Erlang 22.2.8
Copyright (c) 2007-2020 VMware, Inc. or its affiliates.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-27 10:35:58.945 [info] <0.267.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rab...@hostname.log
2020-05-27 10:36:06.964 [notice] <0.276.0> Changed loghwm of /var/log/rabbitmq/rab...@hostname.log to 5000
To unsubscribe from this group and stop receiving emails from it, send an email to
rabbitmq-user...@googlegroups.com.
To view this discussion on the web, visit
https://groups.google.com/d/msgid/rabbitmq-users/9516e31b-807e-4935-9c08-06504c264fd3%40googlegroups.com.
Markus
Jun 23, 2020, 2:45:45 AM6/23/20
to rabbitmq-users
Sorry for the late reply as I was unavailable.
As stated before, we used the same configuration starting since RabbitMQ 3.7.x and did not specify a ssl_options.cacertfile but ssl_options.certfile only. These configuration parameters are specified here: https://www.rabbitmq.com/ssl.html#enabling-tls
We do not use an advanced.config. Hence, for us it seems that with RabbitMQ 3.8.4 onwards the behaviour with the cacertfile option has changed (maybe it was once a bug).
But our main problem is that the certificates retrieved by the truststore plugin cannot be validated anymore. With RabbitMQ 3.8.3 the validation worked fine and the client was able to connect after the certificate has been retrieved from the server. Now the client cannot connect (we have a reconnection manager that tries to connect after some time) and it always gets "bad_certificate". For us this is very strange as the certificate handling and generation has not changed and it works fine with RabbitMQ < 3.8.4 but not with RabbitMQ > 3.8.4.
The configuration I already posted and the certificates are generated according to the guide in https://www.rabbitmq.com/ssl.html#manual-certificate-generation.
Did anything change with the validation process of certificates?
log(s) : /var/log/rabbitmq/rabbit@hostname.log
2020-05-20 08:04:04.409 [notice] <0.107.0> Changed loghwm of /var/log/rabbitmq/rabbit@hostname.log to 50
2020-05-20 08:04:04.751 [info] <0.8.0> Server startup complete; 6 plugins started.
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
2020-05-20 08:04:08.247 [error] <0.543.0> Trust store will attempt to refresh certificates...
2020-05-20 08:04:13.378 [error] <0.543.0> Trust store will attempt to refresh certificates...
After updating to RabbitMQ 3.8.4, clients were not able to connect anymore. After checking the logs I detected that there was a crash and additionally, the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange plugins started last. Here are the logs of RabbitMQ 3.8.4:
2020-05-27 10:35:58.896 [info] <0.267.0>
Starting RabbitMQ 3.8.4 on Erlang 22.2.8
Copyright (c) 2007-2020 VMware, Inc. or its affiliates.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-27 10:35:58.945 [info] <0.267.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rabbit@hostname.log
2020-05-27 10:36:06.964 [notice] <0.276.0> Changed loghwm of /var/log/rabbitmq/rabbit@hostname.log to 5000
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/9516e31b-807e-4935-9c08-06504c264fd3%40googlegroups.com.
Wesley Peng
Jun 23, 2020, 3:21:16 AM6/23/20
to rabbitm...@googlegroups.com
Are you sure this is a RMQ issue not the SSL cert problem?
Can you upgrade to RMQ 3.8.5 to see if the issue has been resolved?
Also please check this news:
Regards.
log(s) : /var/log/rabbitmq/rab...@hostname.log
2020-05-20 08:04:04.409 [notice] <0.107.0> Changed loghwm of /var/log/rabbitmq/rab...@hostname.log to 50
2020-05-20 08:04:04.751 [info] <0.8.0> Server startup complete; 6 plugins started.
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
2020-05-20 08:04:08.247 [error] <0.543.0> Trust store will attempt to refresh certificates...
2020-05-20 08:04:13.378 [error] <0.543.0> Trust store will attempt to refresh certificates...
After updating to RabbitMQ 3.8.4, clients were not able to connect anymore. After checking the logs I detected that there was a crash and additionally, the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange plugins started last. Here are the logs of RabbitMQ 3.8.4:
2020-05-27 10:35:58.896 [info] <0.267.0>
Starting RabbitMQ 3.8.4 on Erlang 22.2.8
Copyright (c) 2007-2020 VMware, Inc. or its affiliates.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-27 10:35:58.945 [info] <0.267.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rab...@hostname.log
2020-05-27 10:36:06.964 [notice] <0.276.0> Changed loghwm of /var/log/rabbitmq/rab...@hostname.log to 5000
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/843ef56b-69bc-4dad-8093-ea6a5da0f0b9o%40googlegroups.com.
Markus
Jun 23, 2020, 3:42:33 AM6/23/20
to rabbitmq-users
As stated before, we use the creation of the certificate according to the guide which creates a self-signed certificate with its own CA. Therfore, this has nothing to do witht he expired certificate. Furthermore, the issue already happened before May 30.
The issue also exists in RabbitMQ 3.8.5.
Best regards.
log(s) : /var/log/rabbitmq/rabbit@hostname.log
2020-05-20 08:04:04.409 [notice] <0.107.0> Changed loghwm of /var/log/rabbitmq/rabbit@hostname.log to 50
2020-05-20 08:04:04.751 [info] <0.8.0> Server startup complete; 6 plugins started.
* rabbitmq_management
* rabbitmq_web_dispatch
* rabbitmq_management_agent
* rabbitmq_presence_exchange
* rabbitmq_auth_mechanism_ssl
* rabbitmq_trust_store
2020-05-20 08:04:08.247 [error] <0.543.0> Trust store will attempt to refresh certificates...
2020-05-20 08:04:13.378 [error] <0.543.0> Trust store will attempt to refresh certificates...
After updating to RabbitMQ 3.8.4, clients were not able to connect anymore. After checking the logs I detected that there was a crash and additionally, the rabbitmq_auth_mechanism_ssl and rabbitmq_presence_exchange plugins started last. Here are the logs of RabbitMQ 3.8.4:
2020-05-27 10:35:58.896 [info] <0.267.0>
Starting RabbitMQ 3.8.4 on Erlang 22.2.8
Copyright (c) 2007-2020 VMware, Inc. or its affiliates.
Licensed under the MPL 1.1. Website: https://rabbitmq.com
2020-05-27 10:35:58.945 [info] <0.267.0>
node : rabbit@hostname
home dir : /var/lib/rabbitmq
config file(s) : /etc/rabbitmq/rabbitmq.conf
cookie hash : x
log(s) : /var/log/rabbitmq/rabbit@hostname.log
2020-05-27 10:36:06.964 [notice] <0.276.0> Changed loghwm of /var/log/rabbitmq/rabbit@hostname.log to 5000
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/843ef56b-69bc-4dad-8093-ea6a5da0f0b9o%40googlegroups.com.
Luke Bakken
Jun 23, 2020, 11:52:33 AM6/23/20
to rabbitmq-users
Hi Markus,
We need your complete, un-edited RabbitMQ configuration files and log files to be able to assist.
Thanks,
Luke
Markus
Jun 24, 2020, 2:48:09 AM6/24/20
to rabbitmq-users
I already provided them in previous posts but I attached the complete files (only removed/obfuscated sensitive data). The log is during my test with RabbitMQ 3.8.5 but is has the same behaviour as with RabbitMQ 3.8.4. Please note that the trust store server was simply started after RabbitMQ, thus, the 404 errors.
I also added a comment on the line with the ssl_options.cacertfile that this line was not needed for starting up RabbitMQ < 3.8.4. Please note that the given configuration file also works fine with RabbitMQ < 3.8.4.
Note that the rabbitmq.conf is the only configuration file we use.
Regarding the logs, please note that this is the complete log from startup to shutdown of RabbitMQ 3.8.5.
Luke Bakken
Jun 25, 2020, 2:19:48 PM6/25/20
to rabbitmq-users
Hi Markus,
I used the generic-unix package and started RabbitMQ this way:
I can't reproduce the issue you report with regard to the cacertfile setting. I tried using RabbitMQ 3.8.5 as well as the latest code. I can have cacertfile completely commented out, and I can have it pointing to an empty file. In both cases, RabbitMQ starts correctly. I have attached the configuration file I used.
I used the generic-unix package and started RabbitMQ this way:
RABBITMQ_CONFIG_FILE="/home/lbakken/issues/misc/rabbitmq-tls.conf" ./sbin/rabbitmq-server
Thanks,
Luke
Markus
Jul 6, 2020, 2:48:54 AM7/6/20
to rabbitmq-users
Hi Luke,
thank you for testing. We also checked it and it worked without the error. Now we checked on the different configuration settings and found the culprit. The issue with the empty cacertfile configuration happens when the configuration contains the following paramter:
ssl_options.verify = verify_peer
It seems that starting from RabbitMQ 3.8.4 this setting needs a cacertfile configuration. But we are using the authentication configuration:
auth_mechanisms.1 = EXTERNAL
with the RabbitMQ Certificate trust store plugin. Thus, it should verify against the stored certificates which seems not to be the case anymore. If we do not have the setting, clients cannot connect with their generated certificates and the server logs the exterer "EXTERNAL login refused: no peer certificate". It seems that something has changed in the handling as the same settings and certificate generation worked with RabbitMQ 3.8.3 and below.
Best regards,
Luke Bakken
Jul 7, 2020, 11:04:56 AM7/7/20
to rabbitmq-users
Thanks for the information Markus.
I'm going to spend today trying to reproduce this issue. If I need more information I will let you know. I've created a repository for configuration files and other artifacts for this - https://github.com/lukebakken/tls-auth-cert-store-GHeD-CRU5lk
Luke
Luke Bakken
Jul 7, 2020, 9:59:24 PM7/7/20
to rabbitmq-users
Hi Markus,
I can verify that RabbitMQ 3.8.3 works as you describe, and that the latest code doesn't. Like you said, it probably has to do with plugin startup order. I'm investigating a fix!
Thanks for your patience -
Luke
Reply all
Reply to author
Forward
0 new messages