User authenticated successfully but then blocked #4041

valentyn-bulakh · 2022-01-25T13:03:52Z

valentyn-bulakh
Jan 25, 2022

Can someone help to troubleshoot problem with RabbitMQ,
I have strange problem and can't find how to fix it?

I see in rabbit logs this message:

"2022-01-25 11:16:00.700868+00:00 [info] <0.11605.3> Supervisor {<0.11605.3>,rabbit_channel_sup}: child channel started (<0.11609.3>): {rabbit_channel,start_link,[1,<0.11546.3>,<0.11606.3>,<0.11546.3>,<<"10.0.0.49:57410 -> 10.142.0.12:5672">>,rabbit_framing_amqp_0_9_1,{user,<<"k8s-prod">>,[],[{rabbit_auth_backend_internal,none}]},<<"/">>,[{<<"publisher_confirms">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"basic.nack">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},{<<"connection.blocked">>,bool,true},{<<"authentication_failure_close">>,bool,true}],<0.11547.3>,<0.11607.3>]}"

but before this message I get "User 'k8s-prod' authenticated successfully by backend rabbit_auth_backend_internal"

confused why it's blocked then?

Answered by michaelklishin

Jan 25, 2022

Those log lines are client properties it advertises to RabbitMQ such as Blocked Connection Notifications, which should be used to determine when a connection was actually blocked, together with metrics, management UI and the very visible log messages about Resource Alarms.

In your rabbitmq-diagnostics status output you see that there are no active alarms, no connections will be blocked.

Those capabilities are not really meant to be logged but in your version and configuration, end up leaking via supervisor info messages. They should be debug entries instead but not all supervisor info lines are logged by RabbitMQ itself.

It's expected that all those messages are nearly identical: the code…

View full answer

michaelklishin · 2022-01-25T13:12:07Z

michaelklishin
Jan 25, 2022
Maintainer

Thank you for your time.

Team RabbitMQ uses GitHub issues for specific actionable items engineers can work on. This assumes that we have a certain amount of information to work with.

Getting all the details necessary to reproduce an issue, make a conclusion or even form a hypothesis about what's happening can take a fair amount of time. Our team is multiple orders of magnitude smaller than the RabbitMQ community. Please help others help you by providing a way to reproduce the behavior you're
observing and sharing as much relevant information as possible on the list:

Server, client library and plugin (if applicable) versions used
Server logs
A code example or terminal transcript that can be used to reproduce
Full exception stack traces (not a single line message)
rabbitmqctl status (and, if possible, rabbitmqctl environment output)
Other relevant things about the environment and workload, e.g. OS/systemd logs, a traffic capture, deployment tool logs, etc

Feel free to edit out hostnames and other potentially sensitive information.

When/if we have a complete enough understanding of what's going on, a recommendation will be provided or a new issues with more context will be filed.

Thank you.

0 replies

michaelklishin · 2022-01-25T13:13:48Z

michaelklishin
Jan 25, 2022
Maintainer

We cannot suggest anything with a couple of log lines. They simply mean that a new connection starts a channel supervisor. All key connection lifecycle events are logged, including authentication failures.

We don't have any RabbitMQ version information to work with either, and it's not clear what you mean by "blocked".

8 replies

michaelklishin Jan 25, 2022
Maintainer

Those lines are from the client capability table. They mean that this client supports blocked connection notifications, not that the connection was blocked. See the doc guide on resource alarms and blocked connection notifications.

valentyn-bulakh Jan 25, 2022
Author

also we are using Node.js app
amqplib to v0.8.0
and
@elastic.io/amqp-rpc to 2.1.0

valentyn-bulakh Jan 25, 2022
Author

@michaelklishin you mean that this no error and we get it from our app?
That it's no issue on RabbitMQ side?

michaelklishin Jan 25, 2022
Maintainer

I mean that those are client properties it advertises to RabbitMQ such as Blocked Connection Notifications, which should be used to determine when a connection was actually blocked, together with metrics, management UI and the very visible log messages about Resource Alarms.

Those capabilities are not really meant to be logged but in your version and configuration, end up leaking via supervisor info messages. They should be debug entries instead but not all supervisor info lines are logged by RabbitMQ itself.

It's expected that all those messages are nearly identical: the code path a new connection goes through, and the kind of operations clients perform early on, are identical.

valentyn-bulakh Jan 25, 2022
Author

I see,
Thanks a lot.

valentyn-bulakh · 2022-01-25T13:16:57Z

valentyn-bulakh
Jan 25, 2022
Author

OS PID: 3590
OS: Linux
Uptime (seconds): 3255
Is under maintenance?: false
RabbitMQ version: 3.9.12
Node name: rabbit@rabbitmq-01
Erlang configuration: Erlang/OTP 24 [erts-12.2] [source] [64-bit] [smp:2:2] [ds:2:2:10] [async-threads:1]
Erlang processes: 533 used, 1048576 limit
Scheduler run queue: 1
Cluster heartbeat timeout (net_ticktime): 60

Enabled plugin file: /etc/rabbitmq/enabled_plugins
Enabled plugins:

 * rabbitmq_event_exchange
 * rabbitmq_management
 * amqp_client
 * rabbitmq_web_dispatch
 * cowboy
 * cowlib
 * rabbitmq_management_agent
 
 Alarms

(none)

Memory

Total memory used: 0.1039 gb
Calculation strategy: rss
Memory high watermark setting: 0.4 of available memory, computed to: 3.1343 gb

code: 0.0317 gb (29.59 %)
other_proc: 0.0205 gb (19.09 %)
other_system: 0.0131 gb (12.25 %)
allocated_unused: 0.013 gb (12.17 %)
queue_procs: 0.0122 gb (11.36 %)
other_ets: 0.0034 gb (3.19 %)
binary: 0.0033 gb (3.08 %)
connection_other: 0.0031 gb (2.87 %)
plugins: 0.003 gb (2.79 %)
atom: 0.0014 gb (1.32 %)
mgmt_db: 0.0011 gb (1.03 %)
connection_readers: 7.0e-4 gb (0.64 %)
metrics: 4.0e-4 gb (0.34 %)
mnesia: 2.0e-4 gb (0.14 %)
connection_channels: 1.0e-4 gb (0.07 %)
quorum_ets: 0.0 gb (0.03 %)
msg_index: 0.0 gb (0.03 %)
connection_writers: 0.0 gb (0.02 %)
stream_queue_procs: 0.0 gb (0.0 %)
stream_queue_replica_reader_procs: 0.0 gb (0.0 %)
queue_slave_procs: 0.0 gb (0.0 %)
quorum_queue_procs: 0.0 gb (0.0 %)
reserved_unallocated: 0.0 gb (0.0 %)
stream_queue_coordinator_procs: 0.0 gb (0.0 %)

File Descriptors

Total: 21, limit: 32671
Sockets: 12, limit: 29401

Free Disk Space

Low free disk space watermark: 0.05 gb
Free disk space: 38.4504 gb

Totals

Connection count: 12
Queue count: 23
Virtual host count: 1

Listeners
Interface: [::], port: 15672, protocol: http, purpose: HTTP API
Interface: [::], port: 25672, protocol: clustering, purpose: inter-node and CLI tool communication
Interface: [::], port: 5672, protocol: amqp, purpose: AMQP 0-9-1 and AMQP 1.0

0 replies

valentyn-bulakh · 2022-01-25T13:19:06Z

valentyn-bulakh
Jan 25, 2022
Author

that isn't a lot logs that can describe more,
they are repeating

2022-01-25 12:23:18.234366+00:00 [info] <0.770.0> accepting AMQP connection <0.770.0> (10.0.5.50:46370 -> 10.142.0.12:5672)
2022-01-25 12:23:18.238505+00:00 [debug] <0.770.0> Raw client connection hostname during authN phase: {0,0,0,0,0,65535,2702,12}
2022-01-25 12:23:18.238667+00:00 [debug] <0.770.0> Resolved client hostname during authN phase: ::ffff:10.142.0.12
2022-01-25 12:23:18.238791+00:00 [debug] <0.770.0> User 'k8s-prod' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-25 12:23:18.239924+00:00 [info] <0.769.0> Supervisor {<0.769.0>,rabbit_connection_helper_sup}: child collector started (<0.774.0>): {rabbit_queue_collector,start_link,[<<"10.0.5.50:46370 -> 10.142.0.12:5672">>]}
2022-01-25 12:23:18.240109+00:00 [info] <0.769.0> Supervisor {<0.769.0>,rabbit_connection_helper_sup}: child heartbeat_sender started (<0.775.0>): {rabbit_heartbeat,start_heartbeat_sender,[#Port<0.57>,60,#Fun<rabbit_reader.4.28767156>,{hear
tbeat_sender,<<"10.0.5.50:46370 -> 10.142.0.12:5672">>}]}
2022-01-25 12:23:18.240331+00:00 [info] <0.769.0> Supervisor {<0.769.0>,rabbit_connection_helper_sup}: child heartbeat_receiver started (<0.776.0>): {rabbit_heartbeat,start_heartbeat_receiver,[#Port<0.57>,60,#Fun<rabbit_reader.5.28767156>,{
heartbeat_receiver,<<"10.0.5.50:46370 -> 10.142.0.12:5672">>}]}
2022-01-25 12:23:18.244869+00:00 [info] <0.766.0> Supervisor {<0.766.0>,rabbit_connection_helper_sup}: child channel_sup_sup started (<0.777.0>): {rabbit_channel_sup_sup,start_link,[]}
2022-01-25 12:23:18.245153+00:00 [info] <0.767.0> connection <0.767.0> (10.0.0.49:48808 -> 10.142.0.12:5672): user 'k8s-prod' authenticated and granted access to vhost '/'
2022-01-25 12:23:18.249940+00:00 [info] <0.779.0> Supervisor {<0.779.0>,rabbit_channel_sup}: child writer started (<0.780.0>): {rabbit_writer,start_link,[#Port<0.56>,1,4096,rabbit_framing_amqp_0_9_1,<0.767.0>,{<<"10.0.0.49:48808 -> 10.142.0
.12:5672">>,1},true]}
2022-01-25 12:23:18.250176+00:00 [info] <0.779.0> Supervisor {<0.779.0>,rabbit_channel_sup}: child limiter started (<0.781.0>): {rabbit_limiter,start_link,[{<<"10.0.0.49:48808 -> 10.142.0.12:5672">>,1}]}
2022-01-25 12:23:18.250580+00:00 [info] <0.779.0> Supervisor {<0.779.0>,rabbit_channel_sup}: child channel started (<0.782.0>): {rabbit_channel,start_link,[1,<0.767.0>,<0.780.0>,<0.767.0>,<<"10.0.0.49:48808 -> 10.142.0.12:5672">>,rabbit_fra
ming_amqp_0_9_1,{user,<<"k8s-prod">>,[],[{rabbit_auth_backend_internal,none}]},<<"/">>,[{<<"publisher_confirms">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"basic.nack">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},
{<<"connection.blocked">>,bool,true},{<<"authentication_failure_close">>,bool,true}],<0.771.0>,<0.781.0>]}
2022-01-25 12:23:18.280844+00:00 [info] <0.769.0> Supervisor {<0.769.0>,rabbit_connection_helper_sup}: child channel_sup_sup started (<0.784.0>): {rabbit_channel_sup_sup,start_link,[]}
2022-01-25 12:23:18.281246+00:00 [info] <0.770.0> connection <0.770.0> (10.0.5.50:46370 -> 10.142.0.12:5672): user 'k8s-prod' authenticated and granted access to vhost '/'
2022-01-25 12:23:18.284981+00:00 [info] <0.786.0> Supervisor {<0.786.0>,rabbit_channel_sup}: child writer started (<0.787.0>): {rabbit_writer,start_link,[#Port<0.57>,1,4096,rabbit_framing_amqp_0_9_1,<0.770.0>,{<<"10.0.5.50:46370 -> 10.142.0
.12:5672">>,1},true]}
2022-01-25 12:23:18.285282+00:00 [info] <0.786.0> Supervisor {<0.786.0>,rabbit_channel_sup}: child limiter started (<0.788.0>): {rabbit_limiter,start_link,[{<<"10.0.5.50:46370 -> 10.142.0.12:5672">>,1}]}
2022-01-25 12:23:18.285760+00:00 [info] <0.786.0> Supervisor {<0.786.0>,rabbit_channel_sup}: child channel started (<0.789.0>): {rabbit_channel,start_link,[1,<0.770.0>,<0.787.0>,<0.770.0>,<<"10.0.5.50:46370 -> 10.142.0.12:5672">>,rabbit_fra
ming_amqp_0_9_1,{user,<<"k8s-prod">>,[],[{rabbit_auth_backend_internal,none}]},<<"/">>,[{<<"publisher_confirms">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"basic.nack">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},
{<<"connection.blocked">>,bool,true},{<<"authentication_failure_close">>,bool,true}],<0.774.0>,<0.788.0>]}
2022-01-25 12:23:20.010197+00:00 [info] <0.793.0> Supervisor {<0.793.0>,rabbit_connection_sup}: child helper_sup started (<0.794.0>): {rabbit_connection_helper_sup,start_link,[]}
2022-01-25 12:23:20.010500+00:00 [info] <0.793.0> Supervisor {<0.793.0>,rabbit_connection_sup}: child reader started (<0.795.0>): {rabbit_reader,start_link,[<0.794.0>,{acceptor,{0,0,0,0,0,0,0,0},5672}]}
2022-01-25 12:23:20.188829+00:00 [info] <0.795.0> accepting AMQP connection <0.795.0> (10.0.1.42:34870 -> 10.142.0.12:5672)
2022-01-25 12:23:20.196204+00:00 [debug] <0.795.0> Raw client connection hostname during authN phase: {0,0,0,0,0,65535,2702,12}
2022-01-25 12:23:20.196343+00:00 [debug] <0.795.0> Resolved client hostname during authN phase: ::ffff:10.142.0.12
2022-01-25 12:23:20.196430+00:00 [debug] <0.795.0> User 'k8s-prod' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-25 12:23:20.197839+00:00 [info] <0.794.0> Supervisor {<0.794.0>,rabbit_connection_helper_sup}: child collector started (<0.796.0>): {rabbit_queue_collector,start_link,[<<"10.0.1.42:34870 -> 10.142.0.12:5672">>]}
2022-01-25 12:23:20.198042+00:00 [info] <0.794.0> Supervisor {<0.794.0>,rabbit_connection_helper_sup}: child heartbeat_sender started (<0.797.0>): {rabbit_heartbeat,start_heartbeat_sender,[#Port<0.58>,60,#Fun<rabbit_reader.4.28767156>,{hear
tbeat_sender,<<"10.0.1.42:34870 -> 10.142.0.12:5672">>}]}
2022-01-25 12:23:20.198260+00:00 [info] <0.794.0> Supervisor {<0.794.0>,rabbit_connection_helper_sup}: child heartbeat_receiver started (<0.798.0>): {rabbit_heartbeat,start_heartbeat_receiver,[#Port<0.58>,60,#Fun<rabbit_reader.5.28767156>,{
heartbeat_receiver,<<"10.0.1.42:34870 -> 10.142.0.12:5672">>}]}
2022-01-25 12:23:20.240913+00:00 [info] <0.794.0> Supervisor {<0.794.0>,rabbit_connection_helper_sup}: child channel_sup_sup started (<0.799.0>): {rabbit_channel_sup_sup,start_link,[]}
2022-01-25 12:23:20.241271+00:00 [info] <0.795.0> connection <0.795.0> (10.0.1.42:34870 -> 10.142.0.12:5672): user 'k8s-prod' authenticated and granted access to vhost '/'
2022-01-25 12:23:20.245155+00:00 [info] <0.801.0> Supervisor {<0.801.0>,rabbit_channel_sup}: child writer started (<0.802.0>): {rabbit_writer,start_link,[#Port<0.58>,1,4096,rabbit_framing_amqp_0_9_1,<0.795.0>,{<<"10.0.1.42:34870 -> 10.142.0
.12:5672">>,1},true]}
2022-01-25 12:23:20.245441+00:00 [info] <0.801.0> Supervisor {<0.801.0>,rabbit_channel_sup}: child limiter started (<0.803.0>): {rabbit_limiter,start_link,[{<<"10.0.1.42:34870 -> 10.142.0.12:5672">>,1}]}
2022-01-25 12:23:20.245948+00:00 [info] <0.801.0> Supervisor {<0.801.0>,rabbit_channel_sup}: child channel started (<0.804.0>): {rabbit_channel,start_link,[1,<0.795.0>,<0.802.0>,<0.795.0>,<<"10.0.1.42:34870 -> 10.142.0.12:5672">>,rabbit_fra
ming_amqp_0_9_1,{user,<<"k8s-prod">>,[],[{rabbit_auth_backend_internal,none}]},<<"/">>,[{<<"publisher_confirms">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"basic.nack">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},
{<<"connection.blocked">>,bool,true},{<<"authentication_failure_close">>,bool,true}],<0.796.0>,<0.803.0>]}
2022-01-25 12:23:21.329421+00:00 [info] <0.806.0> Supervisor {<0.806.0>,rabbit_connection_sup}: child helper_sup started (<0.807.0>): {rabbit_connection_helper_sup,start_link,[]}
2022-01-25 12:23:21.329637+00:00 [info] <0.806.0> Supervisor {<0.806.0>,rabbit_connection_sup}: child reader started (<0.808.0>): {rabbit_reader,start_link,[<0.807.0>,{acceptor,{0,0,0,0,0,0,0,0},5672}]}
2022-01-25 12:23:21.409788+00:00 [info] <0.808.0> accepting AMQP connection <0.808.0> (10.0.6.40:59372 -> 10.142.0.12:5672)
2022-01-25 12:23:21.420774+00:00 [debug] <0.808.0> Raw client connection hostname during authN phase: {0,0,0,0,0,65535,2702,12}
2022-01-25 12:23:21.420914+00:00 [debug] <0.808.0> Resolved client hostname during authN phase: ::ffff:10.142.0.12
2022-01-25 12:23:21.421001+00:00 [debug] <0.808.0> User 'k8s-prod' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-25 12:23:21.422541+00:00 [info] <0.807.0> Supervisor {<0.807.0>,rabbit_connection_helper_sup}: child collector started (<0.809.0>): {rabbit_queue_collector,start_link,[<<"10.0.6.40:59372 -> 10.142.0.12:5672">>]}
2022-01-25 12:23:21.422749+00:00 [info] <0.807.0> Supervisor {<0.807.0>,rabbit_connection_helper_sup}: child heartbeat_sender started (<0.810.0>): {rabbit_heartbeat,start_heartbeat_sender,[#Port<0.59>,60,#Fun<rabbit_reader.4.28767156>,{hear
tbeat_sender,<<"10.0.6.40:59372 -> 10.142.0.12:5672">>}]}
2022-01-25 12:23:21.422983+00:00 [info] <0.807.0> Supervisor {<0.807.0>,rabbit_connection_helper_sup}: child heartbeat_receiver started (<0.811.0>): {rabbit_heartbeat,start_heartbeat_receiver,[#Port<0.59>,60,#Fun<rabbit_reader.5.28767156>,{
heartbeat_receiver,<<"10.0.6.40:59372 -> 10.142.0.12:5672">>}]}
2022-01-25 12:23:21.464965+00:00 [info] <0.807.0> Supervisor {<0.807.0>,rabbit_connection_helper_sup}: child channel_sup_sup started (<0.812.0>): {rabbit_channel_sup_sup,start_link,[]}
2022-01-25 12:23:21.465234+00:00 [info] <0.808.0> connection <0.808.0> (10.0.6.40:59372 -> 10.142.0.12:5672): user 'k8s-prod' authenticated and granted access to vhost '/'
2022-01-25 12:23:21.469602+00:00 [info] <0.814.0> Supervisor {<0.814.0>,rabbit_channel_sup}: child writer started (<0.815.0>): {rabbit_writer,start_link,[#Port<0.59>,1,4096,rabbit_framing_amqp_0_9_1,<0.808.0>,{<<"10.0.6.40:59372 -> 10.142.0

0 replies

michaelklishin · 2022-01-25T13:35:16Z

michaelklishin
Jan 25, 2022
Maintainer

Those log lines are client properties it advertises to RabbitMQ such as Blocked Connection Notifications, which should be used to determine when a connection was actually blocked, together with metrics, management UI and the very visible log messages about Resource Alarms.

In your rabbitmq-diagnostics status output you see that there are no active alarms, no connections will be blocked.

Those capabilities are not really meant to be logged but in your version and configuration, end up leaking via supervisor info messages. They should be debug entries instead but not all supervisor info lines are logged by RabbitMQ itself.

It's expected that all those messages are nearly identical: the code path a new connection goes through, and the kind of operations clients perform early on, are identical.

1 reply

valentyn-bulakh Jan 25, 2022
Author

Thank you!

valentyn-bulakh · 2022-01-25T13:47:39Z

valentyn-bulakh
Jan 25, 2022
Author

@michaelklishin can you explain about it?

rabbitmq-server/deps/amqp_client/include/amqp_client_internal.hrl

Lines 22 to 28 in 6e10225

    
           -define(CLIENT_CAPABILITIES, 
        
               [{<<"publisher_confirms">>,           bool, true}, 
        
                {<<"exchange_exchange_bindings">>,   bool, true}, 
        
                {<<"basic.nack">>,                   bool, true}, 
        
                {<<"consumer_cancel_notify">>,       bool, true}, 
        
                {<<"connection.blocked">>,           bool, true}, 
        
                {<<"authentication_failure_close">>, bool, true}]).

especially what it's means
-define(WAIT_FOR_CONFIRMS_TIMEOUT, {60000, millisecond}).?
what WAIT_FOR_CONFIRMS_TIMEOUT means?

0 replies

User authenticated successfully but then blocked #4041

Uh oh!

Uh oh!

valentyn-bulakh Jan 25, 2022

Replies: 6 comments · 9 replies

Uh oh!

michaelklishin Jan 25, 2022 Maintainer

Uh oh!

michaelklishin Jan 25, 2022 Maintainer

Uh oh!

michaelklishin Jan 25, 2022 Maintainer

Uh oh!

valentyn-bulakh Jan 25, 2022 Author

Uh oh!

valentyn-bulakh Jan 25, 2022 Author

Uh oh!

michaelklishin Jan 25, 2022 Maintainer

Uh oh!

valentyn-bulakh Jan 25, 2022 Author

Uh oh!

Uh oh!

valentyn-bulakh Jan 25, 2022 Author

Uh oh!

Uh oh!

valentyn-bulakh Jan 25, 2022 Author

Uh oh!

michaelklishin Jan 25, 2022 Maintainer

Uh oh!

valentyn-bulakh Jan 25, 2022 Author

Uh oh!

valentyn-bulakh Jan 25, 2022 Author

valentyn-bulakh
Jan 25, 2022

Replies: 6 comments 9 replies

michaelklishin
Jan 25, 2022
Maintainer

michaelklishin
Jan 25, 2022
Maintainer

michaelklishin Jan 25, 2022
Maintainer

valentyn-bulakh Jan 25, 2022
Author

valentyn-bulakh Jan 25, 2022
Author

michaelklishin Jan 25, 2022
Maintainer

valentyn-bulakh Jan 25, 2022
Author

valentyn-bulakh
Jan 25, 2022
Author

valentyn-bulakh
Jan 25, 2022
Author

michaelklishin
Jan 25, 2022
Maintainer

valentyn-bulakh Jan 25, 2022
Author

valentyn-bulakh
Jan 25, 2022
Author