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(a)MARS.ASU.EDU" authzid="zschtest(a)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.
>>
>