Skip to content

No rabbitmq logs {removed_failing_handler,rabbit_log} #474

Closed
@jaschaio

Description

@jaschaio

I don't get any rabbitmq logs beside the start up ones. Instead I see {removed_failing_handler,rabbit_log} when I would expect the first log to appear (e.G. an application making a connection):

touch: cannot touch '/etc/rabbitmq/rabbitmq.conf': Read-only file system

WARNING: '/etc/rabbitmq/rabbitmq.conf' is not writable, but environment variables have been provided which request that we write to it
  We have copied it to '/tmp/rabbitmq.conf' so it can be amended to work around the problem, but it is recommended that the read-only source file should be modified and the environment variables removed instead.

Configuring logger redirection
2021-03-21 18:50:35.161 [debug] <0.294.0> Lager installed handler error_logger_lager_h into error_logger
2021-03-21 18:50:35.174 [debug] <0.297.0> Lager installed handler lager_forwarder_backend into error_logger_lager_event
2021-03-21 18:50:35.174 [debug] <0.300.0> Lager installed handler lager_forwarder_backend into rabbit_log_lager_event
2021-03-21 18:50:35.176 [debug] <0.303.0> Lager installed handler lager_forwarder_backend into rabbit_log_channel_lager_event
2021-03-21 18:50:35.180 [debug] <0.306.0> Lager installed handler lager_forwarder_backend into rabbit_log_connection_lager_event
2021-03-21 18:50:35.188 [debug] <0.309.0> Lager installed handler lager_forwarder_backend into rabbit_log_feature_flags_lager_event
2021-03-21 18:50:35.189 [debug] <0.312.0> Lager installed handler lager_forwarder_backend into rabbit_log_federation_lager_event
2021-03-21 18:50:35.191 [debug] <0.315.0> Lager installed handler lager_forwarder_backend into rabbit_log_ldap_lager_event
2021-03-21 18:50:35.194 [debug] <0.318.0> Lager installed handler lager_forwarder_backend into rabbit_log_mirroring_lager_event
2021-03-21 18:50:35.199 [debug] <0.321.0> Lager installed handler lager_forwarder_backend into rabbit_log_prelaunch_lager_event
2021-03-21 18:50:35.202 [debug] <0.324.0> Lager installed handler lager_forwarder_backend into rabbit_log_queue_lager_event
2021-03-21 18:50:35.206 [debug] <0.327.0> Lager installed handler lager_forwarder_backend into rabbit_log_ra_lager_event
2021-03-21 18:50:35.208 [debug] <0.330.0> Lager installed handler lager_forwarder_backend into rabbit_log_shovel_lager_event
2021-03-21 18:50:35.212 [debug] <0.333.0> Lager installed handler lager_forwarder_backend into rabbit_log_upgrade_lager_event
2021-03-21 18:50:35.268 [info] <0.44.0> Application lager started on node 'rabbit@rabbit-01'
2021-03-21 18:50:35.659 [debug] <0.290.0> Lager installed handler lager_backend_throttle into lager_event
2021-03-21 18:50:38.714 [info] <0.44.0> Application mnesia started on node 'rabbit@rabbit-01'

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

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

  Logs: <stdout>

  Config file(s): /tmp/rabbitmq.conf

  Starting broker...2021-03-21 18:50:38.715 [info] <0.279.0>
 Starting RabbitMQ 3.8.14 on Erlang 23.2.7
 Copyright (c) 2007-2021 VMware, Inc. or its affiliates.
 Licensed under the MPL 2.0. Website: https://rabbitmq.com
2021-03-21 18:50:38.717 [info] <0.279.0>
 node           : rabbit@rabbit-01
 home dir       : /var/lib/rabbitmq
 config file(s) : /tmp/rabbitmq.conf
 cookie hash    : Wshq4WD2kDufnsGLpnfzYnA==
 log(s)         : <stdout>
 database dir   : /var/lib/rabbitmq/mnesia/rabbit@rabbit-01
2021-03-21 18:50:39.821 [info] <0.279.0> Feature flags: list of feature flags found:
2021-03-21 18:50:39.822 [info] <0.279.0> Feature flags:   [x] drop_unroutable_metric
2021-03-21 18:50:39.822 [info] <0.279.0> Feature flags:   [x] empty_basic_get_metric
2021-03-21 18:50:39.822 [info] <0.279.0> Feature flags:   [x] implicit_default_bindings
2021-03-21 18:50:39.822 [info] <0.279.0> Feature flags:   [x] maintenance_mode_status
2021-03-21 18:50:39.822 [info] <0.279.0> Feature flags:   [x] quorum_queue
2021-03-21 18:50:39.822 [info] <0.279.0> Feature flags:   [x] user_limits
2021-03-21 18:50:39.822 [info] <0.279.0> Feature flags:   [x] virtual_host_metadata
2021-03-21 18:50:39.822 [info] <0.279.0> Feature flags: feature flag states written to disk: yes
2021-03-21 18:50:40.258 [info] <0.279.0> Running boot step pre_boot defined by app rabbit
2021-03-21 18:50:40.258 [info] <0.279.0> Running boot step rabbit_core_metrics defined by app rabbit
2021-03-21 18:50:40.259 [info] <0.279.0> Running boot step rabbit_alarm defined by app rabbit
2021-03-21 18:50:40.263 [info] <0.448.0> Memory high watermark set to 3114 MiB (3265884979 bytes) of 7786 MiB (8164712448 bytes) total
2021-03-21 18:50:40.268 [info] <0.450.0> Enabling free disk space monitoring
2021-03-21 18:50:40.268 [info] <0.450.0> Disk free limit set to 50MB
2021-03-21 18:50:40.273 [info] <0.279.0> Running boot step code_server_cache defined by app rabbit
2021-03-21 18:50:40.273 [info] <0.279.0> Running boot step file_handle_cache defined by app rabbit
2021-03-21 18:50:40.273 [info] <0.453.0> Limiting to approx 1048479 file handles (943629 sockets)
2021-03-21 18:50:40.274 [info] <0.454.0> FHC read buffering:  OFF
2021-03-21 18:50:40.274 [info] <0.454.0> FHC write buffering: ON
2021-03-21 18:50:40.274 [info] <0.279.0> Running boot step worker_pool defined by app rabbit
2021-03-21 18:50:40.275 [info] <0.395.0> Will use 2 processes for default worker pool
2021-03-21 18:50:40.275 [info] <0.395.0> Starting worker pool 'worker_pool' with 2 processes in it
2021-03-21 18:50:40.275 [info] <0.279.0> Running boot step database defined by app rabbit
2021-03-21 18:50:41.508 [info] <0.279.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2021-03-21 18:50:41.508 [info] <0.279.0> Successfully synced tables from a peer
2021-03-21 18:50:41.508 [info] <0.279.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2021-03-21 18:50:41.509 [info] <0.279.0> Successfully synced tables from a peer
2021-03-21 18:50:41.569 [info] <0.279.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
2021-03-21 18:50:41.569 [info] <0.279.0> Successfully synced tables from a peer
2021-03-21 18:50:41.569 [info] <0.279.0> Will register with peer discovery backend rabbit_peer_discovery_classic_config
2021-03-21 18:50:41.569 [info] <0.279.0> Running boot step database_sync defined by app rabbit
2021-03-21 18:50:41.569 [info] <0.279.0> Running boot step feature_flags defined by app rabbit
2021-03-21 18:50:41.569 [info] <0.279.0> Running boot step codec_correctness_check defined by app rabbit
2021-03-21 18:50:41.570 [info] <0.279.0> Running boot step external_infrastructure defined by app rabbit
2021-03-21 18:50:41.570 [info] <0.279.0> Running boot step rabbit_registry defined by app rabbit
2021-03-21 18:50:41.570 [info] <0.279.0> Running boot step rabbit_auth_mechanism_cr_demo defined by app rabbit
2021-03-21 18:50:41.570 [info] <0.279.0> Running boot step rabbit_queue_location_random defined by app rabbit
2021-03-21 18:50:41.570 [info] <0.279.0> Running boot step rabbit_event defined by app rabbit
2021-03-21 18:50:41.570 [info] <0.279.0> Running boot step rabbit_auth_mechanism_amqplain defined by app rabbit
2021-03-21 18:50:41.570 [info] <0.279.0> Running boot step rabbit_auth_mechanism_plain defined by app rabbit
2021-03-21 18:50:41.570 [info] <0.279.0> Running boot step rabbit_exchange_type_direct defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_exchange_type_fanout defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_exchange_type_headers defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_exchange_type_topic defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_mirror_queue_mode_all defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_mirror_queue_mode_exactly defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_mirror_queue_mode_nodes defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_priority_queue defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Priority queues enabled, real BQ is rabbit_variable_queue
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_queue_location_client_local defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_queue_location_min_masters defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step kernel_ready defined by app rabbit
2021-03-21 18:50:41.571 [info] <0.279.0> Running boot step rabbit_sysmon_minder defined by app rabbit
2021-03-21 18:50:41.572 [info] <0.279.0> Running boot step rabbit_epmd_monitor defined by app rabbit
2021-03-21 18:50:41.572 [info] <0.483.0> epmd monitor knows us, inter-node communication (distribution) port: 25672
2021-03-21 18:50:41.572 [info] <0.279.0> Running boot step guid_generator defined by app rabbit
2021-03-21 18:50:41.589 [info] <0.279.0> Running boot step rabbit_node_monitor defined by app rabbit
2021-03-21 18:50:41.590 [info] <0.487.0> Starting rabbit_node_monitor
2021-03-21 18:50:41.591 [info] <0.279.0> Running boot step delegate_sup defined by app rabbit
2021-03-21 18:50:41.594 [info] <0.279.0> Running boot step rabbit_memory_monitor defined by app rabbit
2021-03-21 18:50:41.595 [info] <0.279.0> Running boot step core_initialized defined by app rabbit
2021-03-21 18:50:41.595 [info] <0.279.0> Running boot step upgrade_queues defined by app rabbit
2021-03-21 18:50:41.636 [info] <0.279.0> Running boot step channel_tracking defined by app rabbit
2021-03-21 18:50:41.637 [info] <0.279.0> Setting up a table for channel tracking on this node: 'tracked_channel_on_node_rabbit@rabbit-01'
2021-03-21 18:50:41.637 [info] <0.279.0> Setting up a table for channel tracking on this node: 'tracked_channel_table_per_user_on_node_rabbit@rabbit-01'
2021-03-21 18:50:41.638 [info] <0.279.0> Running boot step rabbit_channel_tracking_handler defined by app rabbit
2021-03-21 18:50:41.638 [info] <0.279.0> Running boot step connection_tracking defined by app rabbit
2021-03-21 18:50:41.639 [info] <0.279.0> Setting up a table for connection tracking on this node: 'tracked_connection_on_node_rabbit@rabbit-01'
2021-03-21 18:50:41.639 [info] <0.279.0> Setting up a table for per-vhost connection counting on this node: 'tracked_connection_per_vhost_on_node_rabbit@rabbit-01'
2021-03-21 18:50:41.639 [info] <0.279.0> Setting up a table for per-user connection counting on this node: 'tracked_connection_table_per_user_on_node_rabbit@rabbit-01'
2021-03-21 18:50:41.640 [info] <0.279.0> Running boot step rabbit_connection_tracking_handler defined by app rabbit
2021-03-21 18:50:41.640 [info] <0.279.0> Running boot step rabbit_exchange_parameters defined by app rabbit
2021-03-21 18:50:41.640 [info] <0.279.0> Running boot step rabbit_mirror_queue_misc defined by app rabbit
2021-03-21 18:50:41.641 [info] <0.279.0> Running boot step rabbit_policies defined by app rabbit
2021-03-21 18:50:41.644 [info] <0.279.0> Running boot step rabbit_policy defined by app rabbit
2021-03-21 18:50:41.645 [info] <0.279.0> Running boot step rabbit_queue_location_validator defined by app rabbit
2021-03-21 18:50:41.645 [info] <0.279.0> Running boot step rabbit_quorum_memory_manager defined by app rabbit
2021-03-21 18:50:41.645 [info] <0.279.0> Running boot step rabbit_vhost_limit defined by app rabbit
2021-03-21 18:50:41.645 [info] <0.279.0> Running boot step rabbit_mgmt_reset_handler defined by app rabbitmq_management
2021-03-21 18:50:41.645 [info] <0.279.0> Running boot step rabbit_mgmt_db_handler defined by app rabbitmq_management_agent
2021-03-21 18:50:41.645 [info] <0.279.0> Management plugin: using rates mode 'basic'
2021-03-21 18:50:41.647 [info] <0.279.0> Running boot step recovery defined by app rabbit
2021-03-21 18:50:41.649 [info] <0.523.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@rabbit-01/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists
2021-03-21 18:50:41.662 [info] <0.523.0> Starting message stores for vhost '/'
2021-03-21 18:50:41.663 [info] <0.527.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index
2021-03-21 18:50:41.669 [info] <0.523.0> Started message store of type transient for vhost '/'
2021-03-21 18:50:41.670 [info] <0.531.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
2021-03-21 18:50:41.676 [info] <0.523.0> Started message store of type persistent for vhost '/'
2021-03-21 18:50:41.726 [info] <0.279.0> Running boot step empty_db_check defined by app rabbit
2021-03-21 18:50:41.726 [info] <0.279.0> Will not seed default virtual host and user: have definitions to load...
2021-03-21 18:50:41.726 [info] <0.279.0> Running boot step rabbit_looking_glass defined by app rabbit
2021-03-21 18:50:41.726 [info] <0.279.0> Running boot step rabbit_core_metrics_gc defined by app rabbit
2021-03-21 18:50:41.727 [info] <0.279.0> Running boot step background_gc defined by app rabbit
2021-03-21 18:50:41.727 [info] <0.279.0> Running boot step routing_ready defined by app rabbit
2021-03-21 18:50:41.728 [info] <0.279.0> Running boot step pre_flight defined by app rabbit
2021-03-21 18:50:41.728 [info] <0.279.0> Running boot step notify_cluster defined by app rabbit
2021-03-21 18:50:41.728 [info] <0.279.0> Running boot step networking defined by app rabbit
2021-03-21 18:50:41.728 [info] <0.279.0> Running boot step definition_import_worker_pool defined by app rabbit
2021-03-21 18:50:41.728 [info] <0.395.0> Starting worker pool 'definition_import_pool' with 2 processes in it
2021-03-21 18:50:41.730 [info] <0.279.0> Running boot step cluster_name defined by app rabbit
2021-03-21 18:50:41.731 [info] <0.279.0> Running boot step direct_client defined by app rabbit
2021-03-21 18:50:41.731 [info] <0.279.0> Running boot step rabbit_management_load_definitions defined by app rabbitmq_management
2021-03-21 18:50:41.731 [info] <0.564.0> Resetting node maintenance status
2021-03-21 18:50:41.732 [info] <0.44.0> Application rabbit started on node 'rabbit@rabbit-01'
2021-03-21 18:50:41.738 [info] <0.44.0> Application rabbitmq_management_agent started on node 'rabbit@rabbit-01'
2021-03-21 18:50:41.739 [info] <0.44.0> Application cowlib started on node 'rabbit@rabbit-01'
2021-03-21 18:50:41.740 [info] <0.44.0> Application cowboy started on node 'rabbit@rabbit-01'
2021-03-21 18:50:41.741 [info] <0.44.0> Application rabbitmq_web_dispatch started on node 'rabbit@rabbit-01'
2021-03-21 18:50:41.741 [info] <0.44.0> Application amqp_client started on node 'rabbit@rabbit-01'
2021-03-21 18:50:41.787 [info] <0.625.0> Management plugin: HTTP (non-TLS) listener started on port 15672
2021-03-21 18:50:41.829 [info] <0.625.0> Management plugin: HTTPS listener started on port 15671
2021-03-21 18:50:41.831 [info] <0.836.0> Statistics database started.
2021-03-21 18:50:41.831 [info] <0.835.0> Starting worker pool 'management_worker_pool' with 3 processes in it
2021-03-21 18:50:41.834 [info] <0.44.0> Application rabbitmq_management started on node 'rabbit@rabbit-01'
2021-03-21 18:50:41.877 [info] <0.44.0> Application prometheus started on node 'rabbit@rabbit-01'
2021-03-21 18:50:41.881 [info] <0.849.0> Prometheus metrics: HTTP (non-TLS) listener started on port 15692
2021-03-21 18:50:41.882 [info] <0.564.0> Ready to start client connection listeners
2021-03-21 18:50:41.882 [info] <0.44.0> Application rabbitmq_prometheus started on node 'rabbit@rabbit-01'
2021-03-21 18:50:41.887 [info] <0.969.0> started TLS (SSL) listener on [::]:5671
2021-03-21 18:50:42.638 [info] <0.564.0> Server startup complete; 4 plugins started.
 * rabbitmq_prometheus
 * rabbitmq_management
 * rabbitmq_web_dispatch
 * rabbitmq_management_agent
 completed with 4 plugins.
2021-03-21 18:50:42.639 [info] <0.564.0> Resetting node maintenance status
{removed_failing_handler,rabbit_log}

This is a three node cluster. In my docker compose file I am just setting the SSL environment variables and user and password:

            RABBITMQ_MANAGEMENT_SSL_CACERTFILE: /run/secrets/ca_cert.pem
            RABBITMQ_MANAGEMENT_SSL_CERTFILE: /run/secrets/cert.pem
            RABBITMQ_MANAGEMENT_SSL_KEYFILE: /run/secrets/privkey.pem
            RABBITMQ_MANAGEMENT_SSL_VERIFY: verify_peer
            RABBITMQ_MANAGEMENT_SSL_FAIL_IF_NO_PEER_CERT: "true"
            RABBITMQ_SSL_CACERTFILE: /run/secrets/ca_cert.pem
            RABBITMQ_SSL_CERTFILE: /run/secrets/cert.pem
            RABBITMQ_SSL_KEYFILE: /run/secrets/privkey.pem
            RABBITMQ_SSL_VERIFY: verify_peer
            RABBITMQ_SSL_FAIL_IF_NO_PEER_CERT: "true"
            RABBITMQ_DEFAULT_USER_FILE: /run/secrets/rabbit_user
            RABBITMQ_DEFAULT_PASS_FILE: /run/secrets/rabbit_pass
            RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS: -pa $ERL_SSL_PATH -proto_dist inet_tls -ssl_dist_opt server_certfile /run/secrets/fullchain.pem

My config file is fairly simple:

listeners.tcp = none

ssl_options.versions.1 = tlsv1.3
ssl_options.ciphers.1  = TLS_AES_256_GCM_SHA384
ssl_options.ciphers.2  = TLS_AES_128_GCM_SHA256
ssl_options.ciphers.3  = TLS_CHACHA20_POLY1305_SHA256
ssl_options.ciphers.4  = TLS_AES_128_CCM_SHA256
ssl_options.ciphers.5  = TLS_AES_128_CCM_8_SHA256

cluster_formation.peer_discovery_backend = classic_config

cluster_formation.classic_config.nodes.1 = rabbit@rabbit-01
cluster_formation.classic_config.nodes.2 = rabbit@rabbit-02
cluster_formation.classic_config.nodes.3 = rabbit@rabbit-03

loopback_users.guest = true

RabbitMQ Version rabbitmq:3.8.14-management

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions