Okay, here's the log from a SASL/PLAIN bind working.
Mar 10 16:28:51 kdc1 slapd[2367]: daemon: read active on 21 Mar 10 16:28:51 kdc1 slapd[2367]: connection_get(21) Mar 10 16:28:51 kdc1 slapd[2367]: connection_get(21): got connid=41 Mar 10 16:28:51 kdc1 slapd[2367]: connection_read(21): checking for input on id=41 Mar 10 16:28:51 kdc1 slapd[2367]: do_bind Mar 10 16:28:51 kdc1 slapd[2367]: >>> dnPrettyNormal: <uid=zschtest,cn=MARS.ASU.EDU,cn=auth> Mar 10 16:28:51 kdc1 slapd[2367]: <<< dnPrettyNormal: <uid=zschtest,cn=MARS.ASU.EDU,cn=auth> <uid=zschtest,cn=mars.asu.edu,cn=auth> Mar 10 16:28:51 kdc1 slapd[2367]: do_sasl_bind: dn (uid=zschtest,cn=MARS.ASU.EDU,cn=auth) mech PLAIN Mar 10 16:28:51 kdc1 slapd[2367]: ==> sasl_bind: dn="uid=zschtest,cn=MARS.ASU.EDU,cn=auth" mech=PLAIN datalen=20 Mar 10 16:28:51 kdc1 slapd[2367]: SASL Canonicalize [conn=41]: authcid="zschtest" Mar 10 16:28:51 kdc1 slapd[2367]: slap_sasl_getdn: conn 41 id=zschtest [len=8] Mar 10 16:28:51 kdc1 slapd[2367]: slap_sasl_getdn: u:id converted to uid=zschtest,cn=MARS.ASU.EDU,cn=PLAIN,cn=auth Mar 10 16:28:51 kdc1 slapd[2367]: >>> dnNormalize: <uid=zschtest,cn=MARS.ASU.EDU,cn=PLAIN,cn=auth> Mar 10 16:28:51 kdc1 slapd[2367]: <<< dnNormalize: <uid=zschtest,cn=mars.asu.edu,cn=plain,cn=auth> Mar 10 16:28:51 kdc1 slapd[2367]: ==>slap_sasl2dn: converting SASL name uid=zschtest,cn=mars.asu.edu,cn=plain,cn=auth to a DN Mar 10 16:28:51 kdc1 slapd[2367]: slap_authz_regexp: converting SASL name uid=zschtest,cn=mars.asu.edu,cn=plain,cn=auth Mar 10 16:28:51 kdc1 slapd[2367]: slap_authz_regexp: converted SASL name to ldap:///ou=people,o=mars??sub?(&(uid=zschtest)(objectClass=marsPerson)) Mar 10 16:28:51 kdc1 slapd[2367]: slap_parseURI: parsing ldap:///ou=people,o=mars??sub?(&(uid=zschtest)(objectClass=marsPerson)) Mar 10 16:28:51 kdc1 slapd[2367]: str2filter "(&(uid=zschtest)(objectClass=marsPerson))" Mar 10 16:28:51 kdc1 slapd[2367]: begin get_filter Mar 10 16:28:51 kdc1 slapd[2367]: AND Mar 10 16:28:51 kdc1 slapd[2367]: begin get_filter_list Mar 10 16:28:51 kdc1 slapd[2367]: begin get_filter Mar 10 16:28:51 kdc1 slapd[2367]: EQUALITY Mar 10 16:28:51 kdc1 slapd[2367]: end get_filter 0 Mar 10 16:28:51 kdc1 slapd[2367]: begin get_filter Mar 10 16:28:51 kdc1 slapd[2367]: EQUALITY Mar 10 16:28:51 kdc1 slapd[2367]: end get_filter 0 Mar 10 16:28:51 kdc1 slapd[2367]: end get_filter_list Mar 10 16:28:51 kdc1 slapd[2367]: end get_filter 0 Mar 10 16:28:51 kdc1 slapd[2367]: >>> dnNormalize: <ou=people,o=mars> Mar 10 16:28:51 kdc1 slapd[2367]: <<< dnNormalize: <ou=people,o=mars> Mar 10 16:28:51 kdc1 slapd[2367]: slap_sasl2dn: performing internal search (base=ou=people,o=mars, scope=2) Mar 10 16:28:51 kdc1 slapd[2367]: => hdb_search Mar 10 16:28:51 kdc1 slapd[2367]: bdb_dn2entry("ou=people,o=mars") Mar 10 16:28:51 kdc1 slapd[2367]: search_candidates: base="ou=people,o=mars" (0x00000002) scope=2 Mar 10 16:28:51 kdc1 slapd[2367]: => hdb_dn2idl("ou=people,o=mars") Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_filter_candidates Mar 10 16:28:51 kdc1 slapd[2367]: AND Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_list_candidates 0xa0 Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_filter_candidates Mar 10 16:28:51 kdc1 slapd[2367]: OR Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_list_candidates 0xa1 Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_filter_candidates Mar 10 16:28:51 kdc1 slapd[2367]: EQUALITY Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_equality_candidates (objectClass) Mar 10 16:28:51 kdc1 slapd[2367]: => key_read Mar 10 16:28:51 kdc1 slapd[2367]: bdb_idl_fetch_key: [b49d1940] Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_index_read: failed (-30989) Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_equality_candidates: id=0, first=0, last=0 Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_filter_candidates: id=0 first=0 last=0 Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_filter_candidates Mar 10 16:28:51 kdc1 slapd[2367]: AND Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_list_candidates 0xa0 Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_filter_candidates Mar 10 16:28:51 kdc1 slapd[2367]: EQUALITY Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_equality_candidates (uid) Mar 10 16:28:51 kdc1 slapd[2367]: => key_read Mar 10 16:28:51 kdc1 slapd[2367]: bdb_idl_fetch_key: [7598d43a] Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_index_read 1 candidates Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_equality_candidates: id=1, first=5721, last=5721 Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_filter_candidates: id=1 first=5721 last=5721 Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_filter_candidates Mar 10 16:28:51 kdc1 slapd[2367]: EQUALITY Mar 10 16:28:51 kdc1 slapd[2367]: => bdb_equality_candidates (objectClass) Mar 10 16:28:51 kdc1 slapd[2367]: => key_read Mar 10 16:28:51 kdc1 slapd[2367]: bdb_idl_fetch_key: [13f0c171] Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_index_read 2932 candidates Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_equality_candidates: id=2932, first=3, last=5776 Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_filter_candidates: id=2932 first=3 last=5776 Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_list_candidates: id=1 first=5721 last=5721 Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_filter_candidates: id=1 first=5721 last=5721 Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_list_candidates: id=1 first=5721 last=5721 Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_filter_candidates: id=1 first=5721 last=5721 Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_list_candidates: id=1 first=5721 last=5721 Mar 10 16:28:51 kdc1 slapd[2367]: <= bdb_filter_candidates: id=1 first=5721 last=5721 Mar 10 16:28:51 kdc1 slapd[2367]: bdb_search_candidates: id=1 first=5721 last=5721 Mar 10 16:28:51 kdc1 slapd[2367]: => test_filter Mar 10 16:28:51 kdc1 slapd[2367]: AND Mar 10 16:28:51 kdc1 slapd[2367]: => test_filter_and Mar 10 16:28:51 kdc1 slapd[2367]: => test_filter Mar 10 16:28:51 kdc1 slapd[2367]: EQUALITY Mar 10 16:28:51 kdc1 slapd[2367]: => access_allowed: auth access to "cn=Zach Schimke - TEST,ou=people,o=mars" "uid" requested Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [1] o=new Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [2] ou=rooms,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [3] ou=acl,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [4] ou=groups,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [5] ou=people,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: => acl_get: [5] matched Mar 10 16:28:51 kdc1 slapd[2367]: => acl_get: [5] attr uid Mar 10 16:28:51 kdc1 slapd[2367]: => acl_mask: access to entry "cn=Zach Schimke - TEST,ou=people,o=mars", attr "uid" requested Mar 10 16:28:51 kdc1 slapd[2367]: => acl_mask: to value by "", (=0) Mar 10 16:28:51 kdc1 slapd[2367]: <= check a_dn_pat: ou=admins,ou=people,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: <= check a_dn_pat: cn=mars admin,ou=role,ou=people,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: <= check a_dn_pat: * Mar 10 16:28:51 kdc1 slapd[2367]: <= acl_mask: [3] applying read(=rscxd) (stop) Mar 10 16:28:51 kdc1 slapd[2367]: <= acl_mask: [3] mask: read(=rscxd) Mar 10 16:28:51 kdc1 slapd[2367]: => access_allowed: auth access granted by read(=rscxd) Mar 10 16:28:51 kdc1 slapd[2367]: <= test_filter 6 Mar 10 16:28:51 kdc1 slapd[2367]: => test_filter Mar 10 16:28:51 kdc1 slapd[2367]: EQUALITY Mar 10 16:28:51 kdc1 slapd[2367]: => access_allowed: auth access to "cn=Zach Schimke - TEST,ou=people,o=mars" "objectClass" requested Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [1] o=new Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [2] ou=rooms,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [3] ou=acl,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [4] ou=groups,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: => dn: [5] ou=people,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: => acl_get: [5] matched Mar 10 16:28:51 kdc1 slapd[2367]: => acl_get: [5] attr objectClass Mar 10 16:28:51 kdc1 slapd[2367]: => acl_mask: access to entry "cn=Zach Schimke - TEST,ou=people,o=mars", attr "objectClass" requested Mar 10 16:28:51 kdc1 slapd[2367]: => acl_mask: to value by "", (=0) Mar 10 16:28:51 kdc1 slapd[2367]: <= check a_dn_pat: ou=admins,ou=people,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: <= check a_dn_pat: cn=mars admin,ou=role,ou=people,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: <= check a_dn_pat: * Mar 10 16:28:51 kdc1 slapd[2367]: <= acl_mask: [3] applying read(=rscxd) (stop) Mar 10 16:28:51 kdc1 slapd[2367]: <= acl_mask: [3] mask: read(=rscxd) Mar 10 16:28:51 kdc1 slapd[2367]: => access_allowed: auth access granted by read(=rscxd) Mar 10 16:28:51 kdc1 slapd[2367]: <= test_filter 6 Mar 10 16:28:51 kdc1 slapd[2367]: <= test_filter_and 6 Mar 10 16:28:51 kdc1 slapd[2367]: <= test_filter 6 Mar 10 16:28:51 kdc1 slapd[2367]: send_ldap_result: conn=41 op=0 p=3 Mar 10 16:28:51 kdc1 slapd[2367]: send_ldap_result: err=0 matched="" text="" Mar 10 16:28:51 kdc1 slapd[2367]: <==slap_sasl2dn: Converted SASL name to cn=zach schimke - test,ou=people,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: slap_sasl_getdn: dn:id converted to cn=zach schimke - test,ou=people,o=mars Mar 10 16:28:51 kdc1 slapd[2367]: SASL Canonicalize [conn=41]: slapAuthcDN="cn=zach schimke - test,ou=people,o=mars" Mar 10 16:28:51 kdc1 slapd[2367]: SASL [conn=41] Error: unable to open Berkeley db /etc/sasldb2: No such file or directory Mar 10 16:28:51 kdc1 slapd[2367]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Mar 10 16:28:51 kdc1 slapd[2367]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Mar 10 16:28:51 kdc1 slapd[2367]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Mar 10 16:28:51 kdc1 slapd[2367]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Mar 10 16:28:51 kdc1 slapd[2367]: daemon: activity on 1 descriptor Mar 10 16:28:51 kdc1 slapd[2367]: daemon: activity on: Mar 10 16:28:51 kdc1 slapd[2367]: Mar 10 16:28:51 kdc1 slapd[2367]: daemon: epoll: listen=7 active_threads=0 tvp=NULL Mar 10 16:28:51 kdc1 slapd[2367]: daemon: epoll: listen=8 active_threads=0 tvp=NULL Mar 10 16:28:51 kdc1 slapd[2367]: daemon: epoll: listen=9 active_threads=0 tvp=NULL Mar 10 16:28:51 kdc1 slapd[2367]: daemon: epoll: listen=10 active_threads=0 tvp=NULL Mar 10 16:28:51 kdc1 slapd[2367]: SASL Canonicalize [conn=41]: authzid="zschtest" Mar 10 16:28:51 kdc1 slapd[2367]: SASL proxy authorize [conn=41]: authcid="zschtest@MARS.ASU.EDU" authzid="zschtest@MARS.ASU.EDU" Mar 10 16:28:51 kdc1 slapd[2367]: SASL Authorize [conn=41]: proxy authorization allowed authzDN="" Mar 10 16:28:51 kdc1 slapd[2367]: send_ldap_sasl: err=0 len=-1 Mar 10 16:28:51 kdc1 slapd[2367]: do_bind: SASL/PLAIN bind: dn="cn=zach schimke - test,ou=people,o=mars" ssf=0 Mar 10 16:28:51 kdc1 slapd[2367]: send_ldap_response: msgid=1 tag=97 err=0 Mar 10 16:28:51 kdc1 slapd[2367]: <== slap_sasl_bind: rc=0 Mar 10 16:28:51 kdc1 slapd[2367]: daemon: activity on 1 descriptor Mar 10 16:28:51 kdc1 slapd[2367]: daemon: activity on: Mar 10 16:28:51 kdc1 slapd[2367]: 21r
Zach Schimke Mars Space Flight Facility
On 3/10/2011 4:03 PM, Dan White wrote:
Without seeing any output from your SASL/PLAIN bind, I suspect that saslauthd may not be working with your slapd installation.
If that's the case, double check the permissions on your saslauthd mux, and specify a saslauthd_path parameter within your sasl slapd.conf config if necessary.
On 10/03/11 15:42 -0700, Zach Schimke wrote:
Okay, I get nothing from saslauthd. The relevent logging slapd gives me: daemon: epoll: listen=7 active_threads=0 tvp=NULL daemon: epoll: listen=8 active_threads=0 tvp=NULL daemon: epoll: listen=9 active_threads=0 tvp=NULL daemon: epoll: listen=10 active_threads=0 tvp=NULL do_bind
dnPrettyNormal: <cn=zach schimke - test,ou=people,o=mars>
<<< dnPrettyNormal: <cn=zach schimke - test,ou=people,o=mars>, <cn=zach schimke - test,ou=people,o=mars> do_bind: version=3 dn="cn=zach schimke - test,ou=people,o=mars" method=128 ==> hdb_bind: dn: cn=zach schimke - test,ou=people,o=mars bdb_dn2entry("cn=zach schimke - test,ou=people,o=mars") => access_allowed: auth access to "cn=Zach Schimke - TEST,ou=people,o=mars" "userPassword" requested => dn: [1] o=new => dn: [2] ou=rooms,o=mars => dn: [3] ou=acl,o=mars => dn: [4] ou=groups,o=mars => dn: [5] ou=people,o=mars => acl_get: [5] matched => acl_get: [5] attr userPassword access_allowed: no res from state (userPassword) => acl_mask: access to entry "cn=Zach Schimke - TEST,ou=people,o=mars", attr "userPassword" requested => acl_mask: to value by "", (=0) <= check a_dn_pat: ou=admins,ou=people,o=mars <= check a_dn_pat: cn=mars admin,ou=role,ou=people,o=mars <= check a_dn_pat: * <= acl_mask: [3] applying read(=rscxd) (stop) <= acl_mask: [3] mask: read(=rscxd) => access_allowed: auth access granted by read(=rscxd) send_ldap_result: conn=4 op=0 p=3 send_ldap_result: err=49 matched="" text="" send_ldap_response: msgid=1 tag=97 err=49 daemon: activity on 1 descriptor daemon: activity on: 15r
So, I do not see anything looking at SASL. Is there something special I need to put in slapd.access to make the pass-through bit work? It seems to be an ACL problem at this point (but regular password binds work properly with other users).
Zach Schimke Mars Space Flight Facility
On 3/4/2011 2:09 PM, Dan White wrote:
On 04/03/11 13:59 -0700, Zach Schimke wrote:
I'm using openldap-2.3.32, loglevel = -1 (log grows at 2MB/minute), and neither of those tests work. I've even tried with and without the @REALM.
Can you run your slapd in debug mode (-d -1), and your saslauthd in debug mode (-d)?
Try performing your SASL PLAIN bind, and then your non-sasl pass-through bind, and let us have a look at any relevant output you're seeing from either daemon. It might help to have a look at both to compare.