auth_ldap.log not appearing

[Ian Fuller]

I’ve posted over here but haven’t gotten a response:

https://stackoverflow.com/questions/65962840/auth-ldap-log-is-not-appearing-when-auth-ldap-log-network-in-rabbitmq

 

I've created a rabbitmq.conf and advanced.config for RabbitMQ intended to allow LDAP authentication with internal fallback. Because RabbitMQ is dumb and tries to use the installing user's appdata which is a terrible design for a Windows service, I've also redirected locations with environment variables:

• RABBITMQ_BASE = D:\RabbitMQData\
• RABBITMQ_CONFIG_FILE = D:\RabbitMQData\config\rabbitmq.conf
• RABBITMQ_ADVANCED_CONFIG_FILE = D:\RabbitMQData\config\advanced.config

The config locations appear to be working correctly as they are referenced in the startup information and cause no errors on startup.

rabbitmq.conf (trimmed to relevant portions)

auth_backends.1 = ldap

auth_backends.2 = internal

auth_ldap.servers.1 = domain.local

auth_ldap.use_ssl = true

auth_ldap.port = 636

auth_ldap.dn_lookup_bind = as_user

auth_ldap.log = network

 

log.dir = D:\\RabbitMQData\\log

log.file.level = info

log.file.rotation.date = $D0

log.file.rotation.size = 10485760

advanced.config

[

    {rabbitmq_auth_backend_ldap, [

        {ssl_options, [{cacertfile,"D:\\RabbitMQData\\SSL\\ca.pem"},

            {certfile,"D:\\RabbitMQData\\SSL\\server_certificate.pem"},

            {keyfile,"D:\\RabbitMQData\\SSL\\server_key.pem"},

            {verify, verify_peer},

            {fail_if_no_peer_cert, true}

        ]},

        {user_bind_pattern, ""},

        {user_dn_pattern, ""},

        {dn_lookup_attribute, "sAMAccountName"},

        {dn_lookup_base, "DC=domain,DC=local"},

        {group_lookup_base,"OU=Groups,DC=domain,DC=local"},

        {vhost_access_query, {in_group, "cn=RabbitUsers,OU=Groups,DC=domain,DC=local"}},

        {tag_queries, [

            {administrator, {in_group, "CN=RabbitAdmins,OU=Groups,DC=domain,DC=local"}},

            {management, {in_group, "CN=RabbitAdmins,OU=Groups,DC=domain,DC=local"}}

        ]}

    ]}

].

I'm using auth_ldap.log = network so there should be an ldap_auth.log file in my log directory which would help me troubleshoot but it's not there. Why would this occur? I've not seen any documented settings for auth_ldap logging other than .log so I would assume it would be with the other logs.

I'm currently running into issues with LDAP, specifically the error LDAP bind error: "xxxx" anonymous_auth. As I'm using simple bind via auth_ldap.dn_lookup_bind = as_user I should not be getting anonymous authentication. Without the detailed log however, I can't get additional information.

 

[Luke Bakken]

Hello,

Please note that this mailing list is the best place to ask RabbitMQ questions.

LDAP log messages will be written to the RabbitMQ log file. Have you checked the contents of that file?

Thanks,

Luke

On Thursday, February 4, 2021 at 3:01:29 PM UTC-8 afulle...@gmail.com wrote:

I’ve posted over here but haven’t gotten a response:

https://stackoverflow.com/questions/65962840/auth-ldap-log-is-not-appearing-when-auth-ldap-log-network-in-rabbitmq

 I'm using auth_ldap.log = network so there should be an ldap_auth.log file in my log directory which would help me troubleshoot but it's not there. Why would this occur? I've not seen any documented settings for auth_ldap logging other than .log so I would assume it would be with the other logs.

[Ian Fuller]

Thanks Luke,

Okay looks I made two mistakes here:

1) Going back and re-reading, looks like I misinterpreted the documentation and believed auth_ldap.log was a separate file rather than just a setting.

2) I had pulled your config from https://groups.google.com/g/rabbitmq-users/c/Dby1OWQKLs8/discussion but somehow the following lines ended up as:

    {user_bind_pattern, ""},
    {user_dn_pattern, ""},

instead of
    {user_bind_pattern, "${username}"},
    {user_dn_pattern, "${ad_user}"},

Not sure how that happened but fixing that let me log on with "domain\username". Is there a way to allow logon with just "username", versus "username@domain" or "domain\username"?

As an aside for the log, even at debug and network_unsafe levels the information was insufficient to help me. "LDAP bind error: [] anonymous_auth" was all I could see. What aspect of the bind was failing? I could see in the AD security logs that a logon attempt from the rabbit server with the username was successful. Why did RabbitMQ think it failed via anonymous auth then? What could I have done to realize the issue was the domain context?

2021-02-05 13:05:00.169 [info] <0.15267.0> LDAP CHECK: login for john.smith

2021-02-05 13:05:00.169 [info] <0.15267.0>         LDAP filling template "" with
            [{username,<<"john.smith">>}]
2021-02-05 13:05:00.169 [info] <0.15267.0>         LDAP template result: ""
2021-02-05 13:05:00.169 [info] <0.15267.0>     LDAP connecting to servers: ["DC1.domain.local"]
2021-02-05 13:05:08.253 [debug] <0.521.0> Asked to [re-]register this node (rabbit@RABBITSRV) with epmd...
2021-02-05 13:05:09.112 [debug] <0.521.0> [Re-]registered this node (rabbit@RABBITSRV) with epmd at port 25672
2021-02-05 13:05:11.935 [info] <0.454.0>     LDAP bind error: [] anonymous_auth
2021-02-05 13:05:11.935 [info] <0.15267.0> LDAP DECISION: login for john.smith: {error,ldap_bind_error}
2021-02-05 13:05:11.935 [debug] <0.15267.0> User 'john.smith' failed authenticatation by backend rabbit_auth_backend_ldap
2021-02-05 13:05:11.935 [debug] <0.15267.0> User 'john.smith' failed authenticatation by backend rabbit_auth_backend_internal
2021-02-05 13:05:11.935 [warning] <0.15267.0> HTTP access denied: user 'john.smith' - invalid credentials
2021-02-05 13:05:11.935 [info] <0.658.0> webmachine_log_handler: closing log file: "d:/RabbitMQData/log/http_access/access.log"
2021-02-05 13:05:11.951 [info] <0.658.0> opening log file: "d:/RabbitMQData/log/http_access/access.log.2021_02_05_18"

--
You received this message because you are subscribed to a topic in the Google Groups "rabbitmq-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rabbitmq-users/T3QHNlerZ2U/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/ea83b8a2-9569-4916-a81c-e7fef3f52d69n%40googlegroups.com.

[Ian Fuller]

I've also now run into the issue where if john.smith is a member of RabbitAdmins and in_group is used it works but if john.smith is a member of RabbitAdmins and in_group_nested is used, it does not grant the management tag.

2021-02-05 17:09:24.022 [info] <0.1047.0> LDAP CHECK: login for domain\testuser
2021-02-05 17:09:24.022 [info] <0.1047.0>         LDAP filling template "${username}" with
            [{username,<<"domain\\testuser">>},{ad_domain,<<"domain">>},{ad_user,<<"testuser">>}]
2021-02-05 17:09:24.022 [info] <0.1047.0>         LDAP template result: "domain\testuser"
2021-02-05 17:09:24.022 [info] <0.1047.0>     LDAP connecting to servers: ["dc1.domain.local"]
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: bind request = {'BindRequest',3,"xxxx",{simple,"xxxx"}}
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: bind reply = {ok,{'LDAPMessage',15,{bindResponse,{'BindResponse',success,[],[],asn1_NOVALUE,asn1_NOVALUE}},asn1_NOVALUE}}
2021-02-05 17:09:24.022 [info] <0.454.0>     LDAP bind succeeded: xxxx
2021-02-05 17:09:24.022 [info] <0.454.0>         LDAP filling template "${ad_user}" with
            [{username,<<"domain\\testuser">>},{ad_domain,<<"domain">>},{ad_user,<<"testuser">>}]
2021-02-05 17:09:24.022 [info] <0.454.0>         LDAP template result: "testuser"
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: search request = {'SearchRequest',"DC=domain,DC=local",wholeSubtree,derefAlways,0,0,false,{equalityMatch,{'AttributeValueAssertion',"sAMAccountName","testuser"}},["distinguishedName"]}
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',16,{searchResEntry,{'SearchResultEntry',"CN=Test User,OU=Other,OU=Users,DC=domain,DC=local",[{'PartialAttribute',"distinguishedName",["CN=Test User,OU=Other,OU=Users,DC=domain,DC=local"]}]}},asn1_NOVALUE}}
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',16,{searchResRef,["ldaps://ForestDnsZones.domain.local/DC=ForestDnsZones,DC=domain,DC=local"]},asn1_NOVALUE}}
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',16,{searchResRef,["ldaps://DomainDnsZones.domain.local/DC=DomainDnsZones,DC=domain,DC=local"]},asn1_NOVALUE}}
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',16,{searchResRef,["ldaps://domain.local/CN=Configuration,DC=domain,DC=local"]},asn1_NOVALUE}}
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',16,{searchResDone,{'LDAPResult',success,[],[],asn1_NOVALUE}},asn1_NOVALUE}}
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: search reply = searchResDone
2021-02-05 17:09:24.022 [info] <0.454.0>     LDAP DN lookup: domain\testuser -> CN=Test User,OU=Other,OU=Users,DC=domain,DC=local
2021-02-05 17:09:24.022 [info] <0.454.0>     LDAP CHECK: does domain\testuser have tag administrator?
2021-02-05 17:09:24.022 [info] <0.454.0>     LDAP evaluating query: {in_group_nested,"CN=RabbitAdmins,OU=Groups,DC=domain,DC=local"}
2021-02-05 17:09:24.022 [info] <0.454.0>     LDAP evaluating query: {in_group_nested,"CN=RabbitAdmins,OU=Groups,DC=domain,DC=local","member",subtree}
2021-02-05 17:09:24.022 [info] <0.454.0>         LDAP filling template "CN=RabbitAdmins,OU=Groups,DC=domain,DC=local" with
            [{username,<<"domain\\testuser">>},{user_dn,"CN=Test User,OU=Other,OU=Users,DC=domain,DC=local"},{ad_domain,<<"domain">>},{ad_user,<<"testuser">>}]
2021-02-05 17:09:24.022 [info] <0.454.0>         LDAP template result: "CN=RabbitAdmins,OU=Groups,DC=domain,DC=local"
2021-02-05 17:09:24.022 [info] <0.1003.0>     LDAP network traffic: search request = {'SearchRequest',"OU=Groups,DC=domain,DC=local",wholeSubtree,derefAlways,0,0,false,{equalityMatch,{'AttributeValueAssertion',"member","CN=Test User,OU=Other,OU=Users,DC=domain,DC=local"}},["dn"]}
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',17,{searchResEntry,{'SearchResultEntry',"CN=RabbitAdmins,OU=Groups,DC=domain,DC=local",[]}},asn1_NOVALUE}}
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',17,{searchResDone,{'LDAPResult',success,[],[],asn1_NOVALUE}},asn1_NOVALUE}}
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search reply = searchResDone
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search request = {'SearchRequest',"OU=Groups,DC=domain,DC=local",wholeSubtree,derefAlways,0,0,false,{equalityMatch,{'AttributeValueAssertion',"member","CN=RabbitAdmins,OU=Groups,DC=domain,DC=local"}},["dn"]}
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',18,{searchResDone,{'LDAPResult',success,[],[],asn1_NOVALUE}},asn1_NOVALUE}}
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search reply = searchResDone
2021-02-05 17:09:24.038 [info] <0.454.0>     LDAP DECISION: does domain\testuser have tag administrator? false
2021-02-05 17:09:24.038 [info] <0.454.0>     LDAP CHECK: does domain\testuser have tag management?
2021-02-05 17:09:24.038 [info] <0.454.0>     LDAP evaluating query: {in_group_nested,"CN=RabbitAdmins,OU=Groups,DC=domain,DC=local"}
2021-02-05 17:09:24.038 [info] <0.454.0>     LDAP evaluating query: {in_group_nested,"CN=RabbitAdmins,OU=Groups,DC=domain,DC=local","member",subtree}
2021-02-05 17:09:24.038 [info] <0.454.0>         LDAP filling template "CN=RabbitAdmins,OU=Groups,DC=domain,DC=local" with
            [{username,<<"domain\\testuser">>},{user_dn,"CN=Test User,OU=Other,OU=Users,DC=domain,DC=local"},{ad_domain,<<"domain">>},{ad_user,<<"testuser">>}]
2021-02-05 17:09:24.038 [info] <0.454.0>         LDAP template result: "CN=RabbitAdmins,OU=Groups,DC=domain,DC=local"
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search request = {'SearchRequest',"OU=Groups,DC=domain,DC=local",wholeSubtree,derefAlways,0,0,false,{equalityMatch,{'AttributeValueAssertion',"member","CN=Test User,OU=Other,OU=Users,DC=domain,DC=local"}},["dn"]}
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',19,{searchResEntry,{'SearchResultEntry',"CN=RabbitAdmins,OU=Groups,DC=domain,DC=local",[]}},asn1_NOVALUE}}
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',19,{searchResDone,{'LDAPResult',success,[],[],asn1_NOVALUE}},asn1_NOVALUE}}
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search reply = searchResDone
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search request = {'SearchRequest',"OU=Groups,DC=domain,DC=local",wholeSubtree,derefAlways,0,0,false,{equalityMatch,{'AttributeValueAssertion',"member","CN=RabbitAdmins,OU=Groups,DC=domain,DC=local"}},["dn"]}
2021-02-05 17:09:24.038 [info] <0.1003.0>     LDAP network traffic: search reply = {ok,{'LDAPMessage',20,{searchResDone,{'LDAPResult',success,[],[],asn1_NOVALUE}},asn1_NOVALUE}}
2021-02-05 17:09:24.069 [info] <0.1003.0>     LDAP network traffic: search reply = searchResDone
2021-02-05 17:09:24.069 [info] <0.454.0>     LDAP DECISION: does domain\testuser have tag management? false
2021-02-05 17:09:24.069 [info] <0.1047.0> LDAP DECISION: login for domain\testuser: ok
2021-02-05 17:09:24.069 [debug] <0.1047.0> User 'domain\testuser' authenticated successfully by backend rabbit_auth_backend_ldap
2021-02-05 17:09:24.069 [warning] <0.1047.0> HTTP access denied: user 'domain\testuser' - Not management user