Connection falls back to default user when SASL profile is ANONYMOUS

[coro]

Summary

When a client connects to a RabbitMQ server over AMQP1.0 using the 'Anonymous' SASL Profile, and then attempts to send messages to that server, RabbitMQ behaves as if it were receiving messages from the default user (in our case, we had not set a default user, so this was 'guest' as per the docs.)

Symptoms

When running the client script, the AMQP1.0 connection closes and RabbitMQ sends back an internal Erlang stacktrace over the wire to the client in the AMQP 'close' frame:

amqp:internal-error±  Reader error: {badmatch,
               {error,
                {'EXIT',
                 {{badmatch,
                   {error,
                    {{{badmatch,{error,not_allowed}},
                      [{rabbit_amqp1_0_session_process,init,1,
                        [{file,"src/rabbit_amqp1_0_session_process.erl"},
                         {line,52}]},
                       {gen_server2,init_it,6,
                        [{file,"src/gen_server2.erl"},{line,554}]},
                       {proc_lib,init_p_do_apply,3,
                        [{file,"proc_lib.erl"},{line,249}]}]},
                     {child,undefined,channel,
                      {rabbit_amqp1_0_session_process,start_link,
                       [{0,<0.1612.0>,<0.1617.0>,
                         {user,<<"guest">>,
                          [administrator],
                          [{rabbit_auth_backend_internal,none}]},
                         <<"test-vhost">>,8184,
                         {amqp_adapter_info,
                          {127,0,0,1},
                          5672,
                          {127,0,0,1},
                          49800,<<"127.0.0.1:49800 -> 127.0.0.1:5672">>,
                          {'AMQP',"1.0"},
                          [{ssl,false}]},
                         <0.1614.0>}]},
                      intrinsic,30000,worker,
                      [rabbit_amqp1_0_session_process]}}}},
                  [{rabbit_amqp1_0_session_sup,start_link,1,
                    [{file,"src/rabbit_amqp1_0_session_sup.erl"},{line,53}]},
                   {supervisor2,do_start_child_i,3,
                    [{file,"src/supervisor2.erl"},{line,391}]},
                   {supervisor2,handle_call,3,
                    [{file,"src/supervisor2.erl"},{line,417}]},
                   {gen_server,try_handle_call,4,
                    [{file,"gen_server.erl"},{line,661}]},
                   {gen_server,handle_msg,6,
                    [{file,"gen_server.erl"},{line,690}]},
                   {proc_lib,init_p_do_apply,3,
                    [{file,"proc_lib.erl"},{line,249}]}]}}}}
[{rabbit_amqp1_0_reader,send_to_new_1_0_session,3,
                        [{file,"src/rabbit_amqp1_0_reader.erl"},{line,690}]},
 {rabbit_amqp1_0_reader,handle_1_0_session_frame,3,
                        [{file,"src/rabbit_amqp1_0_reader.erl"},{line,467}]},
 {rabbit_amqp1_0_reader,handle_1_0_frame,4,
                        [{file,"src/rabbit_amqp1_0_reader.erl"},{line,321}]},
 {rabbit_amqp1_0_reader,recvloop,2,
                        [{file,"src/rabbit_amqp1_0_reader.erl"},{line,123}]},
 {rabbit_reader,run,1,[{file,"src/rabbit_reader.erl"},{line,459}]},
 {rabbit_reader,start_connection,4,
                [{file,"src/rabbit_reader.erl"},{line,358}]},
 {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,249}]}]

Workaround

If the default user is allowed all permissions on the vhost, then the connection succeeds and messages can be successfully sent; the Management UI shows this connection as being from the default user.

Switching the SASL Profile to Plain results in the connection succeeding, and messages are sent from the correct user:

Diags

Server logs can be found in RabbitMQLogs.zip. Packet captures for each of the three cases (failure, success as guest user and success as correct user) can be found in Archive.zip.

Repro Script

using System;
using System.Threading;
using Amqp;
using Amqp.Sasl;
using Amqp.Framing;

namespace MyApp
{
    class Program
    {
        static void Main(string[] args)
        {
            Connection connection = null;
            Session session = null;
            SenderLink sender = null;
            ReceiverLink receiver = null;

            try {
                connection = new Connection(
                        new Address("amqp://test-user:test-password@127.0.0.1"),
                        null, // set to SaslProfile.Anonymous to repro
                        new Open() {
                        ContainerId = "client.1.2",
                        HostName = "vhost:test-vhost",
                        MaxFrameSize = 8 * 1024
                        },
                        (c, o) => {
                        });

                session = new Session(connection);
                sender = new SenderLink(session, "sender-link", "q1-yolo1");
                receiver = new ReceiverLink(session, "receiver-link", "q1-yolo1");

                Message message = new Message("Hello AMQP");
                sender.Send(message, null, null);
                message = receiver.Receive();
                Console.WriteLine(message);
                // Thread.Sleep(15000);
            }

            finally {
                connection.Close();
                session.Close();
                sender.Close();
                receiver.Close();
            }
        }
    }
}

System Info

• MacOS 10.14.3
• RabbitMQ Server running locally, version 3.7.14
• .NET Client running .NET Core v2.2.106 using plugin AMQPNetLite v1.1.8.

rabbitmqctl status

Status of node rabbit@localhost ...
[{pid,14651},
 {running_applications,
     [{rabbitmq_amqp1_0,"AMQP 1.0 support for RabbitMQ","3.7.14"},
      {rabbitmq_management,"RabbitMQ Management Console","3.7.14"},
      {rabbitmq_mqtt,"RabbitMQ MQTT Adapter","3.7.14"},
      {rabbitmq_management_agent,"RabbitMQ Management Agent","3.7.14"},
      {rabbitmq_stomp,"RabbitMQ STOMP plugin","3.7.14"},
      {rabbitmq_web_dispatch,"RabbitMQ Web Dispatcher","3.7.14"},
      {rabbit,"RabbitMQ","3.7.14"},
      {amqp_client,"RabbitMQ AMQP Client","3.7.14"},
      {rabbit_common,
          "Modules shared by rabbitmq-server and rabbitmq-erlang-client",
          "3.7.14"},
      {cowboy,"Small, fast, modern HTTP server.","2.6.1"},
      {ranch,"Socket acceptor pool for TCP protocols.","1.7.1"},
      {ssl,"Erlang/OTP SSL application","9.2.2"},
      {public_key,"Public key infrastructure","1.6.5"},
      {sysmon_handler,"Rate-limiting system_monitor event handler","1.1.0"},
      {os_mon,"CPO  CXC 138 46","2.4.7"},
      {sasl,"SASL  CXC 138 11","3.3"},
      {inets,"INETS  CXC 138 49","7.0.7"},
      {asn1,"The Erlang ASN1 compiler version 5.0.8","5.0.8"},
      {xmerl,"XML parser","1.3.20"},
      {amqp10_common,
          "Modules shared by rabbitmq-amqp1.0 and rabbitmq-amqp1.0-client",
          "3.7.14"},
      {jsx,"a streaming, evented json parsing toolkit","2.9.0"},
      {cowlib,"Support library for manipulating Web protocols.","2.7.0"},
      {crypto,"CRYPTO","4.4.2"},
      {mnesia,"MNESIA  CXC 138 12","4.15.6"},
      {recon,"Diagnostic tools for production use","2.4.0"},
      {lager,"Erlang logging framework","3.6.9"},
      {goldrush,"Erlang event stream processor","0.1.9"},
      {compiler,"ERTS  CXC 138 10","7.3.2"},
      {syntax_tools,"Syntax tools","2.1.7"},
      {stdlib,"ERTS  CXC 138 10","3.8.1"},
      {kernel,"ERTS  CXC 138 10","6.3.1"}]},
 {os,{unix,darwin}},
 {erlang_version,
     "Erlang/OTP 21 [erts-10.3.4] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:128] [hipe] [dtrace]\n"},
 {memory,
     [{connection_readers,0},
      {connection_writers,0},
      {connection_channels,0},
      {connection_other,46364},
      {queue_procs,163408},
      {queue_slave_procs,0},
      {plugins,3024288},
      {other_proc,25313288},
      {metrics,229196},
      {mgmt_db,560544},
      {mnesia,128848},
      {other_ets,3162560},
      {binary,1050296},
      {msg_index,240000},
      {code,24089477},
      {atom,1180881},
      {other_system,17724666},
      {allocated_unused,13656936},
      {reserved_unallocated,0},
      {strategy,rss},
      {total,[{erlang,76913816},{rss,86544384},{allocated,90570752}]}]},
 {alarms,[]},
 {listeners,
     [{clustering,25672,"::"},
      {amqp,5672,"127.0.0.1"},
      {stomp,61613,"::"},
      {mqtt,1883,"::"},
      {http,15672,"::"}]},
 {vm_memory_calculation_strategy,rss},
 {vm_memory_high_watermark,0.4},
 {vm_memory_limit,10307921510},
 {disk_free_limit,50000000},
 {disk_free,81759232000},
 {file_descriptors,
     [{total_limit,4764},
      {total_used,17},
      {sockets_limit,4285},
      {sockets_used,0}]},
 {processes,[{limit,1048576},{used,533}]},
 {run_queue,1},
 {uptime,4291},
 {kernel,{net_ticktime,60}}]

rabbitmqctl environment

Application environment of node rabbit@localhost ...
[{amqp10_common,[]},
 {amqp_client,[{prefer_ipv6,false},{ssl_options,[]}]},
 {asn1,[]},
 {compiler,[]},
 {cowboy,[]},
 {cowlib,[]},
 {crypto,[{fips_mode,false},{rand_cache_size,896}]},
 {goldrush,[]},
 {inets,[]},
 {jsx,[]},
 {kernel,
     [{inet_default_connect_options,[{nodelay,true}]},
      {inet_dist_listen_max,25672},
      {inet_dist_listen_min,25672},
      {logger,
          [{handler,default,logger_std_h,
               #{config => #{type => standard_io},
                 formatter =>
                     {logger_formatter,
                         #{legacy_header => true,single_line => false}}}}]},
      {logger_level,notice},
      {logger_sasl_compatible,false}]},
 {lager,
     [{async_threshold,20},
      {async_threshold_window,5},
      {colored,false},
      {colors,
          [{debug,"\e[0;38m"},
           {info,"\e[1;37m"},
           {notice,"\e[1;36m"},
           {warning,"\e[1;33m"},
           {error,"\e[1;31m"},
           {critical,"\e[1;35m"},
           {alert,"\e[1;44m"},
           {emergency,"\e[1;41m"}]},
      {crash_log,"log/crash.log"},
      {crash_log_count,5},
      {crash_log_date,"$D0"},
      {crash_log_msg_size,65536},
      {crash_log_rotator,lager_rotator_default},
      {crash_log_size,10485760},
      {error_logger_format_raw,true},
      {error_logger_hwm,50},
      {error_logger_hwm_original,50},
      {error_logger_redirect,true},
      {extra_sinks,
          [{error_logger_lager_event,
               [{handlers,[{lager_forwarder_backend,[lager_event,inherit]}]},
                {rabbit_handlers,
                    [{lager_forwarder_backend,[lager_event,inherit]}]}]},
           {rabbit_log_lager_event,
               [{handlers,[{lager_forwarder_backend,[lager_event,inherit]}]},
                {rabbit_handlers,
                    [{lager_forwarder_backend,[lager_event,inherit]}]}]},
           {rabbit_log_channel_lager_event,
               [{handlers,[{lager_forwarder_backend,[lager_event,inherit]}]},
                {rabbit_handlers,
                    [{lager_forwarder_backend,[lager_event,inherit]}]}]},
           {rabbit_log_connection_lager_event,
               [{handlers,[{lager_forwarder_backend,[lager_event,inherit]}]},
                {rabbit_handlers,
                    [{lager_forwarder_backend,[lager_event,inherit]}]}]},
           {rabbit_log_ldap_lager_event,
               [{handlers,[{lager_forwarder_backend,[lager_event,inherit]}]},
                {rabbit_handlers,
                    [{lager_forwarder_backend,[lager_event,inherit]}]}]},
           {rabbit_log_mirroring_lager_event,
               [{handlers,[{lager_forwarder_backend,[lager_event,inherit]}]},
                {rabbit_handlers,
                    [{lager_forwarder_backend,[lager_event,inherit]}]}]},
           {rabbit_log_queue_lager_event,
               [{handlers,[{lager_forwarder_backend,[lager_event,inherit]}]},
                {rabbit_handlers,
                    [{lager_forwarder_backend,[lager_event,inherit]}]}]},
           {rabbit_log_federation_lager_event,
               [{handlers,[{lager_forwarder_backend,[lager_event,inherit]}]},
                {rabbit_handlers,
                    [{lager_forwarder_backend,[lager_event,inherit]}]}]},
           {rabbit_log_upgrade_lager_event,
               [{handlers,
                    [{lager_file_backend,
                         [{date,[]},
                          {file,
                              "/usr/local/var/log/rabbitmq/rabbit@localhost_upgrade.log"},
                          {formatter_config,
                              [date," ",time," ",color,"[",severity,"] ",
                               {pid,[]},
                               " ",message,"\n"]},
                          {level,info},
                          {size,0}]}]},
                {rabbit_handlers,
                    [{lager_file_backend,
                         [{date,[]},
                          {file,
                              "/usr/local/var/log/rabbitmq/rabbit@localhost_upgrade.log"},
                          {formatter_config,
                              [date," ",time," ",color,"[",severity,"] ",
                               {pid,[]},
                               " ",message,"\n"]},
                          {level,info},
                          {size,0}]}]}]}]},
      {handlers,
          [{lager_file_backend,
               [{date,[]},
                {file,"/usr/local/var/log/rabbitmq/rabbit@localhost.log"},
                {formatter_config,
                    [date," ",time," ",color,"[",severity,"] ",
                     {pid,[]},
                     " ",message,"\n"]},
                {level,info},
                {size,0}]}]},
      {log_root,"/usr/local/var/log/rabbitmq"},
      {rabbit_handlers,
          [{lager_file_backend,
               [{date,[]},
                {file,"/usr/local/var/log/rabbitmq/rabbit@localhost.log"},
                {formatter_config,
                    [date," ",time," ",color,"[",severity,"] ",
                     {pid,[]},
                     " ",message,"\n"]},
                {level,info},
                {size,0}]}]}]},
 {mnesia,[{dir,"/usr/local/var/lib/rabbitmq/mnesia/rabbit@localhost"}]},
 {os_mon,
     [{start_cpu_sup,false},
      {start_disksup,false},
      {start_memsup,false},
      {start_os_sup,false}]},
 {public_key,[]},
 {rabbit,
     [{auth_backends,[rabbit_auth_backend_internal]},
      {auth_mechanisms,['PLAIN','AMQPLAIN']},
      {autocluster,
          [{peer_discovery_backend,rabbit_peer_discovery_classic_config}]},
      {background_gc_enabled,false},
      {background_gc_target_interval,60000},
      {backing_queue_module,rabbit_priority_queue},
      {channel_max,2047},
      {channel_operation_timeout,15000},
      {cluster_keepalive_interval,10000},
      {cluster_nodes,{[],disc}},
      {cluster_partition_handling,ignore},
      {collect_statistics,fine},
      {collect_statistics_interval,5000},
      {config_entry_decoder,
          [{cipher,aes_cbc256},
           {hash,sha512},
           {iterations,1000},
           {passphrase,undefined}]},
      {connection_max,infinity},
      {credit_flow_default_credit,{400,200}},
      {default_consumer_prefetch,{false,0}},
      {default_permissions,[<<".*">>,<<".*">>,<<".*">>]},
      {default_user,<<"guest">>},
      {default_user_tags,[administrator]},
      {default_vhost,<<"/">>},
      {delegate_count,16},
      {disk_free_limit,50000000},
      {disk_monitor_failure_retries,10},
      {disk_monitor_failure_retry_interval,120000},
      {enabled_plugins_file,"/usr/local/etc/rabbitmq/enabled_plugins"},
      {fhc_read_buffering,false},
      {fhc_write_buffering,true},
      {frame_max,131072},
      {halt_on_upgrade_failure,true},
      {handshake_timeout,10000},
      {heartbeat,60},
      {hipe_compile,false},
      {hipe_modules,
          [rabbit_reader,rabbit_channel,gen_server2,rabbit_exchange,
           rabbit_command_assembler,rabbit_framing_amqp_0_9_1,rabbit_basic,
           rabbit_event,lists,queue,priority_queue,rabbit_router,rabbit_trace,
           rabbit_misc,rabbit_binary_parser,rabbit_exchange_type_direct,
           rabbit_guid,rabbit_net,rabbit_amqqueue_process,
           rabbit_variable_queue,rabbit_binary_generator,rabbit_writer,
           delegate,gb_sets,lqueue,sets,orddict,rabbit_amqqueue,
           rabbit_limiter,gb_trees,rabbit_queue_index,
           rabbit_exchange_decorator,gen,dict,ordsets,file_handle_cache,
           rabbit_msg_store,array,rabbit_msg_store_ets_index,rabbit_msg_file,
           rabbit_exchange_type_fanout,rabbit_exchange_type_topic,mnesia,
           mnesia_lib,rpc,mnesia_tm,qlc,sofs,proplists,credit_flow,pmon,
           ssl_connection,tls_connection,ssl_record,tls_record,gen_fsm,ssl]},
      {lager_default_file,"/usr/local/var/log/rabbitmq/rabbit@localhost.log"},
      {lager_extra_sinks,
          [rabbit_log_lager_event,rabbit_log_channel_lager_event,
           rabbit_log_connection_lager_event,rabbit_log_ldap_lager_event,
           rabbit_log_mirroring_lager_event,rabbit_log_queue_lager_event,
           rabbit_log_federation_lager_event,rabbit_log_upgrade_lager_event]},
      {lager_log_root,"/usr/local/var/log/rabbitmq"},
      {lager_upgrade_file,
          "/usr/local/var/log/rabbitmq/rabbit@localhost_upgrade.log"},
      {lazy_queue_explicit_gc_run_operation_threshold,1000},
      {log,
          [{file,[{file,"/usr/local/var/log/rabbitmq/rabbit@localhost.log"}]},
           {categories,
               [{upgrade,
                    [{file,
                         "/usr/local/var/log/rabbitmq/rabbit@localhost_upgrade.log"}]}]}]},
      {loopback_users,[<<"guest">>]},
      {memory_monitor_interval,2500},
      {mirroring_flow_control,true},
      {mirroring_sync_batch_size,4096},
      {mnesia_table_loading_retry_limit,10},
      {mnesia_table_loading_retry_timeout,30000},
      {msg_store_credit_disc_bound,{4000,800}},
      {msg_store_file_size_limit,16777216},
      {msg_store_index_module,rabbit_msg_store_ets_index},
      {msg_store_io_batch_size,4096},
      {num_ssl_acceptors,10},
      {num_tcp_acceptors,10},
      {password_hashing_module,rabbit_password_hashing_sha256},
      {plugins_dir,"/usr/local/Cellar/rabbitmq/3.7.14/plugins"},
      {plugins_expand_dir,
          "/usr/local/var/lib/rabbitmq/mnesia/rabbit@localhost-plugins-expand"},
      {proxy_protocol,false},
      {queue_explicit_gc_run_operation_threshold,1000},
      {queue_index_embed_msgs_below,4096},
      {queue_index_max_journal_entries,32768},
      {reverse_dns_lookups,false},
      {server_properties,[]},
      {ssl_allow_poodle_attack,false},
      {ssl_apps,[asn1,crypto,public_key,ssl]},
      {ssl_cert_login_from,distinguished_name},
      {ssl_handshake_timeout,5000},
      {ssl_listeners,[]},
      {ssl_options,[]},
      {tcp_listen_options,
          [{backlog,128},
           {nodelay,true},
           {linger,{true,0}},
           {exit_on_close,false}]},
      {tcp_listeners,[{"127.0.0.1",5672}]},
      {trace_vhosts,[]},
      {vhost_restart_strategy,continue},
      {vm_memory_calculation_strategy,rss},
      {vm_memory_high_watermark,0.4},
      {vm_memory_high_watermark_paging_ratio,0.5}]},
 {rabbit_common,[]},
 {rabbitmq_amqp1_0,
     [{default_user,"guest"},
      {default_vhost,<<"/">>},
      {protocol_strict_mode,false}]},
 {rabbitmq_management,
     [{content_security_policy,"default-src 'self'"},
      {cors_allow_origins,[]},
      {cors_max_age,1800},
      {http_log_dir,none},
      {load_definitions,none},
      {management_db_cache_multiplier,5},
      {process_stats_gc_timeout,300000},
      {stats_event_max_backlog,250}]},
 {rabbitmq_management_agent,
     [{rates_mode,basic},
      {sample_retention_policies,
          [{global,[{605,5},{3660,60},{29400,600},{86400,1800}]},
           {basic,[{605,5},{3600,60}]},
           {detailed,[{605,5}]}]}]},
 {rabbitmq_mqtt,
     [{allow_anonymous,true},
      {default_user,<<"guest">>},
      {exchange,<<"amq.topic">>},
      {num_ssl_acceptors,10},
      {num_tcp_acceptors,10},
      {prefetch,10},
      {proxy_protocol,false},
      {retained_message_store,rabbit_mqtt_retained_msg_store_dets},
      {retained_message_store_dets_sync_interval,2000},
      {ssl_cert_login,false},
      {ssl_listeners,[]},
      {subscription_ttl,86400000},
      {tcp_listen_options,[{backlog,128},{nodelay,true}]},
      {tcp_listeners,[1883]},
      {vhost,<<"/">>}]},
 {rabbitmq_stomp,
     [{default_topic_exchange,<<"amq.topic">>},
      {default_user,[{login,<<"guest">>},{passcode,<<"guest">>}]},
      {default_vhost,<<"/">>},
      {hide_server_info,false},
      {implicit_connect,false},
      {num_ssl_acceptors,10},
      {num_tcp_acceptors,10},
      {proxy_protocol,false},
      {ssl_cert_login,false},
      {ssl_listeners,[]},
      {tcp_listen_options,[{backlog,128},{nodelay,true}]},
      {tcp_listeners,[61613]},
      {trailing_lf,true}]},
 {rabbitmq_web_dispatch,[]},
 {ranch,[]},
 {recon,[]},
 {sasl,[{errlog_type,error},{sasl_error_logger,false}]},
 {ssl,[]},
 {stdlib,[]},
 {syntax_tools,[]},
 {sysmon_handler,
     [{busy_dist_port,true},
      {busy_port,false},
      {gc_ms_limit,0},
      {heap_word_limit,0},
      {port_limit,100},
      {process_limit,100},
      {schedule_ms_limit,0}]},
 {xmerl,[]}]

[coro]

The AMQPNetLite Plugin used to generate the pcaps was quite old, so I updated to 2.1.7, and still repro'd the issue.

Tagging @nodo as an interested party.

[kjnilsson]

Thanks @connor-rogers - what we need to do there is validate that the anonymous profile was used to in the connection frame and then investigate how to better handle the case where the internal amqp connection is denied due to invalid user credentials rather than crashing with the current error.

I also noticed that we have no actual tests that tests access to vhosts other than the default so that is also something to address.

[ansd]

Fixed in https://github.com/rabbitmq/rabbitmq-server/pull/11999

[coro]

@ansd <3