Unexpected dependency between shovels #4006

inikulshin · 2022-01-18T08:36:16Z

inikulshin
Jan 18, 2022

We use RabbitMQ 3.8.16, Erlang 24.1.7 on the machine the logs from, 3.8.16 + 24.0.4 on CloudAMQP.

I tried to make our shovels work with verify=verify_peer, and I made the following testing actions (from browser):

Create shovel zzz with both URIs amqps://varadmrabbit-d4cc9fdc:[redacted]@hasty-crimson-flamingo.rmq3.cloudamqp.com:5671/d4cc9fdc-2e48-4135-9863-87c9e9859351?cacertfile=C%3A%5CWorkingShare%5Crmqcluster_service%5Ccacert.pem&verify=verify_peer&heartbeat=900&server_name_indication=hasty-crimson-flamingo.rmq3.cloudamqp.com.
The shovel zzz fails to start.
This hostname_check_failed failure is also unexpected, openssl s_client ... -verify_hostname hasty-crimson-flamingo.rmq3.cloudamqp.com succeeds, probably this is related to the following.
Create shovel xxx with both URIs amqps://varadmrabbit-d4cc9fdc:[redacted]@hasty-crimson-flamingo.rmq3.cloudamqp.com:5671/d4cc9fdc-2e48-4135-9863-87c9e9859351?cacertfile=C%3A%5CWorkingShare%5Crmqcluster_service%5Ccacert.pem&verify=verify_peer&heartbeat=900&server_name_indication=disable. The only difference from zzz is disabled SNI.
Shovels xxx succeeds to start.
Unexpectedly, shovel zzz also succeeds to start!
After shovel zzz restart , the unexpected behavior didn't reproduced. Repeating 1-5 also didn't reproduce.

Also, similar shovel with server_name_indication=*.rmq3.cloudamqp.com succeeds. It looks like in hostname matching process the wildcard pattern is used as a hostname, and vice versa.

2022-01-17 15:58:57.310 [error] <0.19688.17> Supervisor {<0.19688.17>,rabbit_shovel_dyn_worker_sup} had child {<<"/">>,<<"zzz">>} started with rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"zzz">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at {restarting,<0.20290.17>} exit with reason shutdown in context child_terminated
2022-01-17 15:58:57.311 [debug] <0.20304.17> Initialising a Shovel 'zzz' in virtual host '/' of type 'dynamic'
2022-01-17 15:58:57.312 [debug] <0.19688.17> Supervisor {<0.19688.17>,rabbit_shovel_dyn_worker_sup} started rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"zzz">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at pid <0.20304.17>
2022-01-17 15:58:57.312 [debug] <0.20305.17> Supervisor {<0.20305.17>,amqp_connection_sup} started amqp_connection_type_sup:start_link() at pid <0.20306.17>
2022-01-17 15:58:57.312 [debug] <0.20305.17> Supervisor {<0.20305.17>,amqp_connection_sup} started amqp_gen_connection:start_link(<0.20306.17>, {amqp_params_network,<<"varadmrabbit-d4cc9fdc">>,{encrypted,<<"ulw4MK5UkAhtaGVW2Fr9qWKJPrGuBZX8OiJ...">>},...}) at pid <0.20307.17>
2022-01-17 15:58:57.332 [error] <0.20304.17> Shovel 'zzz' failed to connect (URI: amqps://hasty-crimson-flamingo.rmq3.cloudamqp.com:5671/d4cc9fdc-2e48-4135-9863-87c9e9859351): {tls_alert,{handshake_failure,"TLS client: In state certify at ssl_handshake.erl:2017 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,hostname_check_failed}"}}
2022-01-17 15:58:57.332 [error] <0.20304.17> Shovel 'zzz' has no more URIs to try for connection
2022-01-17 15:58:57.333 [error] <0.20304.17> Shovel 'zzz' could not connect, caught exception error:failed_to_connect_using_provided_uris
2022-01-17 15:58:57.333 [error] <0.20304.17> Shovel 'zzz' could not connect to source
2022-01-17 15:58:57.333 [error] <0.19688.17> Supervisor {<0.19688.17>,rabbit_shovel_dyn_worker_sup} had child {<<"/">>,<<"zzz">>} started with rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"zzz">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at <0.20304.17> exit with reason shutdown in context child_terminated
2022-01-17 15:58:57.355 [debug] <0.20314.17> User 'VaronisRabbitMQ' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-17 15:58:58.578 [debug] <0.20316.17> User 'qq' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-17 15:58:58.583 [debug] <0.20317.17> User 'qq' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-17 15:59:02.335 [error] <0.19688.17> Supervisor {<0.19688.17>,rabbit_shovel_dyn_worker_sup} had child {<<"/">>,<<"zzz">>} started with rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"zzz">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at {restarting,<0.20304.17>} exit with reason shutdown in context child_terminated
2022-01-17 15:59:02.336 [debug] <0.20318.17> Initialising a Shovel 'zzz' in virtual host '/' of type 'dynamic'
2022-01-17 15:59:02.337 [debug] <0.19688.17> Supervisor {<0.19688.17>,rabbit_shovel_dyn_worker_sup} started rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"zzz">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at pid <0.20318.17>
2022-01-17 15:59:02.337 [debug] <0.20319.17> Supervisor {<0.20319.17>,amqp_connection_sup} started amqp_connection_type_sup:start_link() at pid <0.20320.17>
2022-01-17 15:59:02.338 [debug] <0.20319.17> Supervisor {<0.20319.17>,amqp_connection_sup} started amqp_gen_connection:start_link(<0.20320.17>, {amqp_params_network,<<"varadmrabbit-d4cc9fdc">>,{encrypted,<<"9OnVbktwJMexxitv571+50guQHPqRuxa6G3...">>},...}) at pid <0.20321.17>
2022-01-17 15:59:02.356 [debug] <0.20325.17> User 'VaronisRabbitMQ' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-17 15:59:02.393 [error] <0.20318.17> Shovel 'zzz' failed to connect (URI: amqps://hasty-crimson-flamingo.rmq3.cloudamqp.com:5671/d4cc9fdc-2e48-4135-9863-87c9e9859351): {tls_alert,{handshake_failure,"TLS client: In state certify at ssl_handshake.erl:2017 generated CLIENT ALERT: Fatal - Handshake Failure\n {bad_cert,hostname_check_failed}"}}
2022-01-17 15:59:02.393 [error] <0.20318.17> Shovel 'zzz' has no more URIs to try for connection
2022-01-17 15:59:02.393 [error] <0.20318.17> Shovel 'zzz' could not connect, caught exception error:failed_to_connect_using_provided_uris
2022-01-17 15:59:02.393 [error] <0.20318.17> Shovel 'zzz' could not connect to source
2022-01-17 15:59:02.393 [error] <0.19688.17> Supervisor {<0.19688.17>,rabbit_shovel_dyn_worker_sup} had child {<<"/">>,<<"zzz">>} started with rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"zzz">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at <0.20318.17> exit with reason shutdown in context child_terminated
2022-01-17 15:59:03.021 [debug] <0.20330.17> User 'qq' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-17 15:59:03.021 [debug] <0.20330.17> Asked to set or update runtime parameter 'xxx' in vhost '/' for component 'shovel', value: [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"amqp091">>},{<<"dest-queue">>,<<"x2">>},{<<"dest-uri">>,<<"amqps://varadmrabbit-d4cc9fdc:ythiirQYDODFPJAm5zrbdvQlk5CTIU@hasty-crimson-flamingo.rmq3.cloudamqp.com:5671/d4cc9fdc-2e48-4135-9863-87c9e9859351?cacertfile=C%3A%5CWorkingShare%5Crmqcluster_service%5Ccacert.pem&verify=verify_peer&heartbeat=900&server_name_indication=disable">>},{<<"src-delete-after">>,<<"never">>},{<<"src-protocol">>,<<"amqp091">>},{<<"src-queue">>,<<"x1">>},{<<"src-uri">>,<<"amqps://varadmrabbit-d4cc9fdc:ythiirQYDODFPJAm5zrbdvQlk5CTIU@hasty-crimson-flamingo.rmq3.cloudamqp.com:5671/d4cc9fdc-2e48-4135-9863-87c9e9859351?cacertfile=C%3A%5CWorkingShare%5Crmqcluster_service%5Ccacert.pem&verify=verify_peer&heartbeat=900&server_name_indication=disable">>}]
2022-01-17 15:59:03.031 [debug] <0.20346.17> Shovel 'xxx' in virtual host '/' will use reconnection delay of 5
2022-01-17 15:59:03.032 [debug] <0.20347.17> Initialising a Shovel 'xxx' in virtual host '/' of type 'dynamic'
2022-01-17 15:59:03.032 [debug] <0.20346.17> Supervisor {<0.20346.17>,rabbit_shovel_dyn_worker_sup} started rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"xxx">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at pid <0.20347.17>
2022-01-17 15:59:03.033 [debug] <0.1460.0> Supervisor {<0.1460.0>,mirrored_supervisor_sups} started rabbit_shovel_dyn_worker_sup:start_link({<<"/">>,<<"xxx">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at pid <0.20346.17>
2022-01-17 15:59:03.033 [debug] <0.20348.17> Supervisor {<0.20348.17>,amqp_connection_sup} started amqp_connection_type_sup:start_link() at pid <0.20349.17>
2022-01-17 15:59:03.033 [debug] <0.20348.17> Supervisor {<0.20348.17>,amqp_connection_sup} started amqp_gen_connection:start_link(<0.20349.17>, {amqp_params_network,<<"varadmrabbit-d4cc9fdc">>,{encrypted,<<"9XkeTQi2/p2euldOCRpwGtXYgcAoMoq6HOo...">>},...}) at pid <0.20350.17>
2022-01-17 15:59:03.036 [debug] <0.20351.17> User 'qq' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-17 15:59:03.047 [debug] <0.20354.17> User 'qq' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-17 15:59:03.050 [debug] <0.20349.17> Supervisor {<0.20349.17>,amqp_connection_type_sup} started amqp_channel_sup_sup:start_link(network, <0.20350.17>, <<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>) at pid <0.20355.17>
2022-01-17 15:59:03.050 [debug] <0.20349.17> Supervisor {<0.20349.17>,amqp_connection_type_sup} started amqp_channels_manager:start_link(<0.20350.17>, <<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>, <0.20355.17>) at pid <0.20356.17>
2022-01-17 15:59:03.050 [debug] <0.20349.17> Supervisor {<0.20349.17>,amqp_connection_type_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140369>,tls_connection,undefined},[<0.20353.17>,<0.20352.17>]}, 0, 4096, rabbit_framing_amqp_0_9_1, <0.20350.17>, <<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>, false, 1000000000) at pid <0.20357.17>
2022-01-17 15:59:03.050 [debug] <0.20349.17> Supervisor {<0.20349.17>,amqp_connection_type_sup} started amqp_main_reader:start_link({sslsocket,{gen_tcp,#Port<0.140369>,tls_connection,undefined},[<0.20353.17>,<0.20352.17>]}, <0.20350.17>, <0.20356.17>, {method,rabbit_framing_amqp_0_9_1}, <<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>) at pid <0.20358.17>
2022-01-17 15:59:03.054 [debug] <0.20349.17> Supervisor {<0.20349.17>,amqp_connection_type_sup} started rabbit_heartbeat:start_heartbeat_sender({sslsocket,{gen_tcp,#Port<0.140369>,tls_connection,undefined},[<0.20353.17>,<0.20352.17>]}, 900, #Fun<amqp_network_connection.2.15045815>, {heartbeat_sender,<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>}) at pid <0.20359.17>
2022-01-17 15:59:03.054 [debug] <0.20349.17> Supervisor {<0.20349.17>,amqp_connection_type_sup} started rabbit_heartbeat:start_heartbeat_receiver({sslsocket,{gen_tcp,#Port<0.140369>,tls_connection,undefined},[<0.20353.17>,<0.20352.17>]}, 900, #Fun<amqp_network_connection.3.15045815>, {heartbeat_receiver,<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>}) at pid <0.20360.17>
2022-01-17 15:59:03.057 [debug] <0.20361.17> Supervisor {<0.20361.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>,1}) at pid <0.20362.17>
2022-01-17 15:59:03.057 [debug] <0.20361.17> Supervisor {<0.20361.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20350.17>, 1, <0.20362.17>, {<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>,1}) at pid <0.20363.17>
2022-01-17 15:59:03.057 [debug] <0.20361.17> Supervisor {<0.20361.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140369>,tls_connection,undefined},[<0.20353.17>,<0.20352.17>]}, 1, 131072, rabbit_framing_amqp_0_9_1, <0.20363.17>, {<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>,1}, false, 1000000000) at pid <0.20364.17>
2022-01-17 15:59:03.059 [debug] <0.20347.17> Shovel 'xxx' connected to source
2022-01-17 15:59:03.060 [debug] <0.20365.17> Supervisor {<0.20365.17>,amqp_connection_sup} started amqp_connection_type_sup:start_link() at pid <0.20366.17>
2022-01-17 15:59:03.060 [debug] <0.20365.17> Supervisor {<0.20365.17>,amqp_connection_sup} started amqp_gen_connection:start_link(<0.20366.17>, {amqp_params_network,<<"varadmrabbit-d4cc9fdc">>,{encrypted,<<"0m3V0X7VRwX0Kgdyp5001ws6htNIWwkzizJ...">>},...}) at pid <0.20367.17>
2022-01-17 15:59:03.067 [debug] <0.20366.17> Supervisor {<0.20366.17>,amqp_connection_type_sup} started amqp_channel_sup_sup:start_link(network, <0.20367.17>, <<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>) at pid <0.20370.17>
2022-01-17 15:59:03.067 [debug] <0.20366.17> Supervisor {<0.20366.17>,amqp_connection_type_sup} started amqp_channels_manager:start_link(<0.20367.17>, <<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>, <0.20370.17>) at pid <0.20371.17>
2022-01-17 15:59:03.067 [debug] <0.20366.17> Supervisor {<0.20366.17>,amqp_connection_type_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140364>,tls_connection,undefined},[<0.20369.17>,<0.20368.17>]}, 0, 4096, rabbit_framing_amqp_0_9_1, <0.20367.17>, <<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>, false, 1000000000) at pid <0.20372.17>
2022-01-17 15:59:03.067 [debug] <0.20366.17> Supervisor {<0.20366.17>,amqp_connection_type_sup} started amqp_main_reader:start_link({sslsocket,{gen_tcp,#Port<0.140364>,tls_connection,undefined},[<0.20369.17>,<0.20368.17>]}, <0.20367.17>, <0.20371.17>, {method,rabbit_framing_amqp_0_9_1}, <<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>) at pid <0.20373.17>
2022-01-17 15:59:03.070 [debug] <0.20366.17> Supervisor {<0.20366.17>,amqp_connection_type_sup} started rabbit_heartbeat:start_heartbeat_sender({sslsocket,{gen_tcp,#Port<0.140364>,tls_connection,undefined},[<0.20369.17>,<0.20368.17>]}, 900, #Fun<amqp_network_connection.2.15045815>, {heartbeat_sender,<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>}) at pid <0.20374.17>
2022-01-17 15:59:03.070 [debug] <0.20366.17> Supervisor {<0.20366.17>,amqp_connection_type_sup} started rabbit_heartbeat:start_heartbeat_receiver({sslsocket,{gen_tcp,#Port<0.140364>,tls_connection,undefined},[<0.20369.17>,<0.20368.17>]}, 900, #Fun<amqp_network_connection.3.15045815>, {heartbeat_receiver,<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>}) at pid <0.20375.17>
2022-01-17 15:59:03.073 [debug] <0.20376.17> Supervisor {<0.20376.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>,1}) at pid <0.20377.17>
2022-01-17 15:59:03.073 [debug] <0.20376.17> Supervisor {<0.20376.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20367.17>, 1, <0.20377.17>, {<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>,1}) at pid <0.20378.17>
2022-01-17 15:59:03.073 [debug] <0.20376.17> Supervisor {<0.20376.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140364>,tls_connection,undefined},[<0.20369.17>,<0.20368.17>]}, 1, 131072, rabbit_framing_amqp_0_9_1, <0.20378.17>, {<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>,1}, false, 1000000000) at pid <0.20379.17>
2022-01-17 15:59:03.075 [debug] <0.20347.17> Shovel 'xxx' connected to destination
2022-01-17 15:59:03.075 [debug] <0.20380.17> Supervisor {<0.20380.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>,2}) at pid <0.20381.17>
2022-01-17 15:59:03.075 [debug] <0.20380.17> Supervisor {<0.20380.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20367.17>, 2, <0.20381.17>, {<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>,2}) at pid <0.20382.17>
2022-01-17 15:59:03.076 [debug] <0.20380.17> Supervisor {<0.20380.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140364>,tls_connection,undefined},[<0.20369.17>,<0.20368.17>]}, 2, 131072, rabbit_framing_amqp_0_9_1, <0.20382.17>, {<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>,2}, false, 1000000000) at pid <0.20383.17>
2022-01-17 15:59:03.078 [debug] <0.20384.17> Supervisor {<0.20384.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>,2}) at pid <0.20385.17>
2022-01-17 15:59:03.078 [debug] <0.20384.17> Supervisor {<0.20384.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20367.17>, 2, <0.20385.17>, {<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>,2}) at pid <0.20386.17>
2022-01-17 15:59:03.079 [debug] <0.20384.17> Supervisor {<0.20384.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140364>,tls_connection,undefined},[<0.20369.17>,<0.20368.17>]}, 2, 131072, rabbit_framing_amqp_0_9_1, <0.20386.17>, {<<"client 10.188.34.37:6659 -> 20.122.170.159:5671">>,2}, false, 1000000000) at pid <0.20387.17>
2022-01-17 15:59:03.091 [debug] <0.20388.17> Supervisor {<0.20388.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>,2}) at pid <0.20389.17>
2022-01-17 15:59:03.091 [debug] <0.20388.17> Supervisor {<0.20388.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20350.17>, 2, <0.20389.17>, {<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>,2}) at pid <0.20390.17>
2022-01-17 15:59:03.091 [debug] <0.20388.17> Supervisor {<0.20388.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140369>,tls_connection,undefined},[<0.20353.17>,<0.20352.17>]}, 2, 131072, rabbit_framing_amqp_0_9_1, <0.20390.17>, {<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>,2}, false, 1000000000) at pid <0.20391.17>
2022-01-17 15:59:03.097 [debug] <0.20392.17> Supervisor {<0.20392.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>,2}) at pid <0.20393.17>
2022-01-17 15:59:03.097 [debug] <0.20392.17> Supervisor {<0.20392.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20350.17>, 2, <0.20393.17>, {<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>,2}) at pid <0.20394.17>
2022-01-17 15:59:03.097 [debug] <0.20392.17> Supervisor {<0.20392.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140369>,tls_connection,undefined},[<0.20353.17>,<0.20352.17>]}, 2, 131072, rabbit_framing_amqp_0_9_1, <0.20394.17>, {<<"client 10.188.34.37:6658 -> 20.122.170.159:5671">>,2}, false, 1000000000) at pid <0.20395.17>
2022-01-17 15:59:03.111 [debug] <0.20347.17> Shovel 'xxx' has finished setting up its topology
2022-01-17 15:59:06.117 [debug] <0.20396.17> User 'qq' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-17 15:59:06.117 [debug] <0.20396.17> rabbit_access_control:check_vhost_access result: {'EXIT',{amqp_error,not_allowed,"access to vhost 'panzura' refused for user 'qq'",none}}
2022-01-17 15:59:06.118 [debug] <0.20396.17> rabbit_access_control:check_vhost_access result: {'EXIT',{amqp_error,not_allowed,"access to vhost 'ctera' refused for user 'qq'",none}}
2022-01-17 15:59:06.118 [debug] <0.20396.17> rabbit_access_control:check_vhost_access result: {'EXIT',{amqp_error,not_allowed,"access to vhost 'nasuni' refused for user 'qq'",none}}
2022-01-17 15:59:06.118 [debug] <0.20396.17> rabbit_access_control:check_vhost_access result: {'EXIT',{amqp_error,not_allowed,"access to vhost 'cohesity' refused for user 'qq'",none}}
2022-01-17 15:59:06.118 [debug] <0.20396.17> rabbit_access_control:check_vhost_access result: {'EXIT',{amqp_error,not_allowed,"access to vhost 'nutanix' refused for user 'qq'",none}}
2022-01-17 15:59:07.358 [debug] <0.20400.17> User 'VaronisRabbitMQ' authenticated successfully by backend rabbit_auth_backend_internal
2022-01-17 15:59:07.396 [error] <0.19688.17> Supervisor {<0.19688.17>,rabbit_shovel_dyn_worker_sup} had child {<<"/">>,<<"zzz">>} started with rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"zzz">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at {restarting,<0.20318.17>} exit with reason shutdown in context child_terminated
2022-01-17 15:59:07.397 [debug] <0.20401.17> Initialising a Shovel 'zzz' in virtual host '/' of type 'dynamic'
2022-01-17 15:59:07.397 [debug] <0.19688.17> Supervisor {<0.19688.17>,rabbit_shovel_dyn_worker_sup} started rabbit_shovel_worker:start_link(dynamic, {<<"/">>,<<"zzz">>}, [{<<"ack-mode">>,<<"on-confirm">>},{<<"dest-add-forward-headers">>,false},{<<"dest-protocol">>,<<"...">>},...]) at pid <0.20401.17>
2022-01-17 15:59:07.398 [debug] <0.20402.17> Supervisor {<0.20402.17>,amqp_connection_sup} started amqp_connection_type_sup:start_link() at pid <0.20403.17>
2022-01-17 15:59:07.398 [debug] <0.20402.17> Supervisor {<0.20402.17>,amqp_connection_sup} started amqp_gen_connection:start_link(<0.20403.17>, {amqp_params_network,<<"varadmrabbit-d4cc9fdc">>,{encrypted,<<"bR7jdDGoucySB4NT+rL10uvvhEeUfHeD5Eg...">>},...}) at pid <0.20404.17>
2022-01-17 15:59:07.407 [debug] <0.20403.17> Supervisor {<0.20403.17>,amqp_connection_type_sup} started amqp_channel_sup_sup:start_link(network, <0.20404.17>, <<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>) at pid <0.20407.17>
2022-01-17 15:59:07.407 [debug] <0.20403.17> Supervisor {<0.20403.17>,amqp_connection_type_sup} started amqp_channels_manager:start_link(<0.20404.17>, <<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>, <0.20407.17>) at pid <0.20408.17>
2022-01-17 15:59:07.408 [debug] <0.20403.17> Supervisor {<0.20403.17>,amqp_connection_type_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140371>,tls_connection,undefined},[<0.20406.17>,<0.20405.17>]}, 0, 4096, rabbit_framing_amqp_0_9_1, <0.20404.17>, <<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>, false, 1000000000) at pid <0.20409.17>
2022-01-17 15:59:07.408 [debug] <0.20403.17> Supervisor {<0.20403.17>,amqp_connection_type_sup} started amqp_main_reader:start_link({sslsocket,{gen_tcp,#Port<0.140371>,tls_connection,undefined},[<0.20406.17>,<0.20405.17>]}, <0.20404.17>, <0.20408.17>, {method,rabbit_framing_amqp_0_9_1}, <<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>) at pid <0.20410.17>
2022-01-17 15:59:07.413 [debug] <0.20403.17> Supervisor {<0.20403.17>,amqp_connection_type_sup} started rabbit_heartbeat:start_heartbeat_sender({sslsocket,{gen_tcp,#Port<0.140371>,tls_connection,undefined},[<0.20406.17>,<0.20405.17>]}, 900, #Fun<amqp_network_connection.2.15045815>, {heartbeat_sender,<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>}) at pid <0.20412.17>
2022-01-17 15:59:07.413 [debug] <0.20403.17> Supervisor {<0.20403.17>,amqp_connection_type_sup} started rabbit_heartbeat:start_heartbeat_receiver({sslsocket,{gen_tcp,#Port<0.140371>,tls_connection,undefined},[<0.20406.17>,<0.20405.17>]}, 900, #Fun<amqp_network_connection.3.15045815>, {heartbeat_receiver,<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>}) at pid <0.20413.17>
2022-01-17 15:59:07.416 [debug] <0.20414.17> Supervisor {<0.20414.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>,1}) at pid <0.20415.17>
2022-01-17 15:59:07.416 [debug] <0.20414.17> Supervisor {<0.20414.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20404.17>, 1, <0.20415.17>, {<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>,1}) at pid <0.20416.17>
2022-01-17 15:59:07.416 [debug] <0.20414.17> Supervisor {<0.20414.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140371>,tls_connection,undefined},[<0.20406.17>,<0.20405.17>]}, 1, 131072, rabbit_framing_amqp_0_9_1, <0.20416.17>, {<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>,1}, false, 1000000000) at pid <0.20417.17>
2022-01-17 15:59:07.418 [debug] <0.20401.17> Shovel 'zzz' connected to source
2022-01-17 15:59:07.419 [debug] <0.20418.17> Supervisor {<0.20418.17>,amqp_connection_sup} started amqp_connection_type_sup:start_link() at pid <0.20419.17>
2022-01-17 15:59:07.419 [debug] <0.20418.17> Supervisor {<0.20418.17>,amqp_connection_sup} started amqp_gen_connection:start_link(<0.20419.17>, {amqp_params_network,<<"varadmrabbit-d4cc9fdc">>,{encrypted,<<"Th5K689WprZ0kC5T/6k0I++ot5bfk+HUV9I...">>},...}) at pid <0.20420.17>
2022-01-17 15:59:07.425 [debug] <0.20419.17> Supervisor {<0.20419.17>,amqp_connection_type_sup} started amqp_channel_sup_sup:start_link(network, <0.20420.17>, <<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>) at pid <0.20423.17>
2022-01-17 15:59:07.425 [debug] <0.20419.17> Supervisor {<0.20419.17>,amqp_connection_type_sup} started amqp_channels_manager:start_link(<0.20420.17>, <<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>, <0.20423.17>) at pid <0.20424.17>
2022-01-17 15:59:07.425 [debug] <0.20419.17> Supervisor {<0.20419.17>,amqp_connection_type_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140372>,tls_connection,undefined},[<0.20422.17>,<0.20421.17>]}, 0, 4096, rabbit_framing_amqp_0_9_1, <0.20420.17>, <<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>, false, 1000000000) at pid <0.20425.17>
2022-01-17 15:59:07.425 [debug] <0.20419.17> Supervisor {<0.20419.17>,amqp_connection_type_sup} started amqp_main_reader:start_link({sslsocket,{gen_tcp,#Port<0.140372>,tls_connection,undefined},[<0.20422.17>,<0.20421.17>]}, <0.20420.17>, <0.20424.17>, {method,rabbit_framing_amqp_0_9_1}, <<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>) at pid <0.20426.17>
2022-01-17 15:59:07.430 [debug] <0.20419.17> Supervisor {<0.20419.17>,amqp_connection_type_sup} started rabbit_heartbeat:start_heartbeat_sender({sslsocket,{gen_tcp,#Port<0.140372>,tls_connection,undefined},[<0.20422.17>,<0.20421.17>]}, 900, #Fun<amqp_network_connection.2.15045815>, {heartbeat_sender,<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>}) at pid <0.20427.17>
2022-01-17 15:59:07.430 [debug] <0.20419.17> Supervisor {<0.20419.17>,amqp_connection_type_sup} started rabbit_heartbeat:start_heartbeat_receiver({sslsocket,{gen_tcp,#Port<0.140372>,tls_connection,undefined},[<0.20422.17>,<0.20421.17>]}, 900, #Fun<amqp_network_connection.3.15045815>, {heartbeat_receiver,<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>}) at pid <0.20428.17>
2022-01-17 15:59:07.433 [debug] <0.20429.17> Supervisor {<0.20429.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>,1}) at pid <0.20430.17>
2022-01-17 15:59:07.433 [debug] <0.20429.17> Supervisor {<0.20429.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20420.17>, 1, <0.20430.17>, {<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>,1}) at pid <0.20431.17>
2022-01-17 15:59:07.433 [debug] <0.20429.17> Supervisor {<0.20429.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140372>,tls_connection,undefined},[<0.20422.17>,<0.20421.17>]}, 1, 131072, rabbit_framing_amqp_0_9_1, <0.20431.17>, {<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>,1}, false, 1000000000) at pid <0.20432.17>
2022-01-17 15:59:07.436 [debug] <0.20401.17> Shovel 'zzz' connected to destination
2022-01-17 15:59:07.436 [debug] <0.20433.17> Supervisor {<0.20433.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>,2}) at pid <0.20434.17>
2022-01-17 15:59:07.436 [debug] <0.20433.17> Supervisor {<0.20433.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20420.17>, 2, <0.20434.17>, {<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>,2}) at pid <0.20435.17>
2022-01-17 15:59:07.437 [debug] <0.20433.17> Supervisor {<0.20433.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140372>,tls_connection,undefined},[<0.20422.17>,<0.20421.17>]}, 2, 131072, rabbit_framing_amqp_0_9_1, <0.20435.17>, {<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>,2}, false, 1000000000) at pid <0.20436.17>
2022-01-17 15:59:07.441 [debug] <0.20437.17> Supervisor {<0.20437.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>,2}) at pid <0.20438.17>
2022-01-17 15:59:07.441 [debug] <0.20437.17> Supervisor {<0.20437.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20420.17>, 2, <0.20438.17>, {<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>,2}) at pid <0.20439.17>
2022-01-17 15:59:07.441 [debug] <0.20437.17> Supervisor {<0.20437.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140372>,tls_connection,undefined},[<0.20422.17>,<0.20421.17>]}, 2, 131072, rabbit_framing_amqp_0_9_1, <0.20439.17>, {<<"client 10.188.34.37:6663 -> 20.122.170.159:5671">>,2}, false, 1000000000) at pid <0.20440.17>
2022-01-17 15:59:07.459 [debug] <0.20441.17> Supervisor {<0.20441.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>,2}) at pid <0.20442.17>
2022-01-17 15:59:07.459 [debug] <0.20441.17> Supervisor {<0.20441.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20404.17>, 2, <0.20442.17>, {<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>,2}) at pid <0.20443.17>
2022-01-17 15:59:07.460 [debug] <0.20441.17> Supervisor {<0.20441.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140371>,tls_connection,undefined},[<0.20406.17>,<0.20405.17>]}, 2, 131072, rabbit_framing_amqp_0_9_1, <0.20443.17>, {<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>,2}, false, 1000000000) at pid <0.20444.17>
2022-01-17 15:59:07.471 [debug] <0.20445.17> Supervisor {<0.20445.17>,amqp_channel_sup} started amqp_gen_consumer:start_link(amqp_selective_consumer, [], {<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>,2}) at pid <0.20446.17>
2022-01-17 15:59:07.471 [debug] <0.20445.17> Supervisor {<0.20445.17>,amqp_channel_sup} started amqp_channel:start_link(network, <0.20404.17>, 2, <0.20446.17>, {<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>,2}) at pid <0.20447.17>
2022-01-17 15:59:07.471 [debug] <0.20445.17> Supervisor {<0.20445.17>,amqp_channel_sup} started rabbit_writer:start_link({sslsocket,{gen_tcp,#Port<0.140371>,tls_connection,undefined},[<0.20406.17>,<0.20405.17>]}, 2, 131072, rabbit_framing_amqp_0_9_1, <0.20447.17>, {<<"client 10.188.34.37:6662 -> 20.122.170.159:5671">>,2}, false, 1000000000) at pid <0.20448.17>
2022-01-17 15:59:07.496 [debug] <0.20401.17> Shovel 'zzz' has finished setting up its topology

michaelklishin · 2022-01-18T12:20:39Z

michaelklishin
Jan 18, 2022
Maintainer

Individual Shovels are entirely independent. What they do share is the underlying Erlang client, TLS library and URI/credential obfuscation library.

I don't think our team has the cycles to investigate issues like this. This is open source software, so you are welcome to do it if this makes any practical difference.

0 replies

michaelklishin · 2022-01-18T12:30:09Z

michaelklishin
Jan 18, 2022
Maintainer

IIRC months ago (3.8.16 is from May 2021) we addressed a couple of scenarios where shovels could affect each other's startup.
#3167, #3263, and another one involving credential obfuscation seed reuse come to mind.

The log contains virtual host access failures and one Shovel zzz restart which I cannot explain. So we don't have much specifics to work with.

Shovel is a small plugin with only a couple of modules responsible for its state machine. Searching the repo or GitHub for some
connection event log messages will lead you to the right place.

0 replies

inikulshin · 2022-01-18T13:38:29Z

inikulshin
Jan 18, 2022
Author

Maybe this is related to unexpected hostname_check_failed:

https://github.com/erlang/otp/blob/master/lib/ssl/src/ssl_certificate.erl

validate(Cert, valid_peer, UserState = #{role := client, server_name := Hostname, 
                                         customize_hostname_check := Customize}) when Hostname =/= disable ->
    case verify_hostname(Hostname, Customize, Cert, UserState) of
        {valid, UserState} ->
            validate(Cert, valid, UserState);
        Error ->
            Error
    end;

but in https://github.com/rabbitmq/rabbitmq-server/blob/master/deps/amqp_client/src/amqp_ssl.erl

% NOTE:
% The user state is the hostname to verify as configured in
% amqp_ssl:make_verify_fun
verify_fun(Cert, valid_peer, Hostname) when Hostname =/= disable ->
    verify_hostname(Cert, Hostname);

@michaelklishin are you sure UserState is hostname and not the record with server_name := Hostname?

0 replies

inikulshin · 2022-01-20T13:04:21Z

inikulshin
Jan 20, 2022
Author

@michaelklishin I'm not a SSL expert, but SNI and hostname check are similar, but different checks.

E.g. openssl s_client (https://www.openssl.org/docs/man1.1.1/man1/s_client.html) has

-verify_hostname hostname
-servername name

Imho, it is unexpected, that setting server_name_indication in shovel's URI affects hostname check.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Unexpected dependency between shovels #4006

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 4 comments

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Select a reply

Uh oh!

Unexpected dependency between shovels #4006

Uh oh!

Uh oh!

inikulshin Jan 18, 2022

Replies: 4 comments

Uh oh!

michaelklishin Jan 18, 2022 Maintainer

Uh oh!

michaelklishin Jan 18, 2022 Maintainer

Uh oh!

inikulshin Jan 18, 2022 Author

Uh oh!

Uh oh!

inikulshin Jan 20, 2022 Author

inikulshin
Jan 18, 2022

michaelklishin
Jan 18, 2022
Maintainer

michaelklishin
Jan 18, 2022
Maintainer

inikulshin
Jan 18, 2022
Author

inikulshin
Jan 20, 2022
Author