'"PLAIN login refused: User authentication failed" after upgrading RabbitMQ and Erlang
I've just tryed upgrading my RabbitMQ from 3.9.8 to 3.9.14, as well as updating Erlang from 23.3 to 24.3.3 (according to RabbitMQ documentation, RabbitMQ v3.9.14 supports Erlang from 23.2 to 24.x), and unfortunately I'm experiencing some issues that I cannot find a solution to.
I have several consumers using the internal backend auth (username:password), and to authenticate to the management UI plugin, I'm using LDAP. That means that my config looks something like this:
[
{ rabbit, [
{auth_backends, [rabbit_auth_backend_ldap, rabbit_auth_backend_internal]}
]},
...
]
So I'm trying to authenticate using LDAP, if that doesn't work, RabbitMQ tries internal. This has been working ever since I installed RabbitMQ, but is not working anymore.
If I check the logs, it looks like is just fails to authenticate with LDAP, and it's as if it never tries with internal, which I cannot understand.
I've updated two of my 3 nodes in our production environment, so as of right now, all consumers and publishers are communicating with a single node. After updating our test environment, everything on test works as expected, so this is only an issue for my production environment.
I can't figure out was the issue is. I haven't touched anything within the config file.
What seems to be my issue?
Snippet from log
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> ** Generic server <0.542.0> terminating
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> ** Last message in was {submit,#Fun<rabbit_auth_backend_ldap.14.8489193>,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> <0.14152.0>,reuse}
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> ** When Server state == {from,<0.14152.0>,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> #Ref<0.4081940967.2306080769.101088>}
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> ** Reason for termination ==
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> ** {{case_clause,{ok,{eldap_search_result,[],[],asn1_NOVALUE}}},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{rabbit_auth_backend_ldap,dn_lookup,2,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"rabbit_auth_backend_ldap.erl"},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {line,826}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {rabbit_auth_backend_ldap,call_ldap_fun,3,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"rabbit_auth_backend_ldap.erl"},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {line,588}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {rabbit_auth_backend_ldap,with_login,5,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"rabbit_auth_backend_ldap.erl"},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {line,540}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {rabbit_auth_backend_ldap,'-with_ldap/3-fun-2-',4,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"rabbit_auth_backend_ldap.erl"},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {line,510}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {worker_pool_worker,handle_call,3,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"worker_pool_worker.erl"},{line,96}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {gen_server2,handle_msg,2,[{file,"gen_server2.erl"},{line,1046}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}]}
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0>
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> crasher:
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> initial call: worker_pool_worker:init/1
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> pid: <0.542.0>
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> registered_name: []
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> exception exit: {{case_clause,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {ok,{eldap_search_result,[],[],asn1_NOVALUE}}},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{rabbit_auth_backend_ldap,dn_lookup,2,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"rabbit_auth_backend_ldap.erl"},{line,826}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {rabbit_auth_backend_ldap,call_ldap_fun,3,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"rabbit_auth_backend_ldap.erl"},{line,588}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {rabbit_auth_backend_ldap,with_login,5,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"rabbit_auth_backend_ldap.erl"},{line,540}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {rabbit_auth_backend_ldap,'-with_ldap/3-fun-2-',4,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"rabbit_auth_backend_ldap.erl"},{line,510}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {worker_pool_worker,handle_call,3,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"worker_pool_worker.erl"},{line,96}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {gen_server2,handle_msg,2,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"gen_server2.erl"},{line,1046}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {proc_lib,wake_up,3,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{file,"proc_lib.erl"},{line,236}]}]}
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> in function gen_server2:terminate/3 (gen_server2.erl, line 1183)
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> ancestors: [ldap_pool_sup,rabbit_sup,<0.241.0>]
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> message_queue_len: 0
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> messages: []
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> links: [<0.481.0>,<0.14130.0>]
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> dictionary: [{ldap_conns,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> #{{false,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> ["[DOMAIN OBSCURED]"],
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{log,#Fun<rabbit_auth_backend_ldap.12.8489193>},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {port,389},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {idle_timeout,300000},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {anon_auth,false}]} =>
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> <0.14130.0>}},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {worker_pool_worker,true},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {rand_seed,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {#{jump => #Fun<rand.3.92093067>,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> max => 288230376151711743,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> next => #Fun<rand.5.92093067>,type => exsplus},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [186383336712754926|245984873093678204]}},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {timeouts,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {dict,1,16,16,8,80,48,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {{[],[],[],[],[],[],[],[],[],[],[],[],
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [[{false,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> ["[DOMAIN OBSCURED]"],
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [{log,
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> #Fun<rabbit_auth_backend_ldap.12.8489193>},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {port,389},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {idle_timeout,300000},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {anon_auth,false}]}|
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> #Ref<0.4081940967.2306080769.101090>]],
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> [],[],[]}}}},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {worker_pool_name,ldap_pool},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> {{parse_memo_table,rabbit_semver_parser},
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> #Ref<0.4081940967.2306211841.100835>}]
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> trap_exit: false
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> status: running
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> heap_size: 1598
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> stack_size: 29
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> reductions: 194404
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> neighbours:
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> neighbour:
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> pid: <0.14130.0>
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> registered_name: []
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> initial_call: {erlang,apply,2}
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> current_function: {eldap,loop,2}
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> ancestors: []
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> message_queue_len: 0
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> links: [<0.542.0>,#Port<0.1389>]
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> trap_exit: false
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> status: waiting
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> heap_size: 6772
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> stack_size: 6
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> reductions: 93522
2022-04-12 10:41:50.737000+02:00 [error] <0.542.0> current_stacktrace: [{eldap,loop,2,[{file,"eldap.erl"},{line,522}]}]
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> supervisor: {local,ldap_pool_sup}
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> errorContext: child_terminated
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> reason: {{case_clause,{ok,{eldap_search_result,[],[],asn1_NOVALUE}}},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> [{rabbit_auth_backend_ldap,dn_lookup,2,
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> [{file,"rabbit_auth_backend_ldap.erl"},{line,826}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {rabbit_auth_backend_ldap,call_ldap_fun,3,
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> [{file,"rabbit_auth_backend_ldap.erl"},{line,588}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {rabbit_auth_backend_ldap,with_login,5,
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> [{file,"rabbit_auth_backend_ldap.erl"},{line,540}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {rabbit_auth_backend_ldap,'-with_ldap/3-fun-2-',4,
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> [{file,"rabbit_auth_backend_ldap.erl"},{line,510}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {worker_pool_worker,handle_call,3,
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> [{file,"worker_pool_worker.erl"},{line,96}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {gen_server2,handle_msg,2,
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> [{file,"gen_server2.erl"},{line,1046}]},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}]}
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> offender: [{pid,<0.542.0>},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {id,60},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {mfargs,{worker_pool_worker,start_link,[ldap_pool]}},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {restart_type,transient},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {significant,false},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {shutdown,4294967295},
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0> {child_type,worker}]
2022-04-12 10:41:50.737000+02:00 [error] <0.481.0>
2022-04-12 10:41:50.737000+02:00 [info] <0.481.0> Supervisor {local,ldap_pool_sup}: child 60 started (<0.14153.0>): {worker_pool_worker,start_link,[ldap_pool]}
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> User '[USERNAME OBSCURED]' authentication failed with exit:{{{case_clause,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {ok,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {eldap_search_result,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [],[],asn1_NOVALUE}}},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{rabbit_auth_backend_ldap,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> dn_lookup,2,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> "rabbit_auth_backend_ldap.erl"},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {line,826}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {rabbit_auth_backend_ldap,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> call_ldap_fun,3,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> "rabbit_auth_backend_ldap.erl"},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {line,588}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {rabbit_auth_backend_ldap,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> with_login,5,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> "rabbit_auth_backend_ldap.erl"},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {line,540}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {rabbit_auth_backend_ldap,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> '-with_ldap/3-fun-2-',
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> 4,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> "rabbit_auth_backend_ldap.erl"},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {line,510}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {worker_pool_worker,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> handle_call,3,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> "worker_pool_worker.erl"},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {line,96}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {gen_server2,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> handle_msg,2,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> "gen_server2.erl"},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {line,1046}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {proc_lib,wake_up,3,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,"proc_lib.erl"},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {line,236}]}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {gen_server2,call,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [<0.542.0>,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {submit,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> #Fun<rabbit_auth_backend_ldap.14.8489193>,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> <0.14152.0>,reuse},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> infinity]}}:
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{gen_server2,call,3,[{file,"gen_server2.erl"},{line,346}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {rabbit_auth_backend_ldap,user_login_authentication,2,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,"rabbit_auth_backend_ldap.erl"},{line,71}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {rabbit_access_control,try_authenticate,3,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,"rabbit_access_control.erl"},{line,92}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {rabbit_access_control,'-check_user_login/2-fun-0-',4,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,"rabbit_access_control.erl"},{line,57}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {lists,foldl,3,[{file,"lists.erl"},{line,1267}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {rabbit_access_control,check_user_login,2,
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> [{file,"rabbit_access_control.erl"},{line,42}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {rabbit_reader,auth_phase,2,[{file,"rabbit_reader.erl"},{line,1423}]},
2022-04-12 10:41:50.737000+02:00 [debug] <0.14152.0> {rabbit_reader,handle_method0,3,[{file,"rabbit_reader.erl"},{line,1133}]}]
2022-04-12 10:41:50.737000+02:00 [error] <0.14152.0> Error on AMQP connection <0.14152.0> ([IP OBSCURED]:61057 -> [IP OBSCURED]:5672, state: starting):
2022-04-12 10:41:50.737000+02:00 [error] <0.14152.0> PLAIN login refused: User '[USERNAME OBSCURED]' authentication failed with internal error. Enable debug logs to see the real error.
Solution 1:[1]
Issue has been fixed in 3.9.15:
https://github.com/rabbitmq/rabbitmq-server/pull/4448
So an upgrade to a newer version should fix this
Sources
This article follows the attribution requirements of Stack Overflow and is licensed under CC BY-SA 3.0.
Source: Stack Overflow
| Solution | Source |
|---|---|
| Solution 1 | klarsen |