Re: Simple Bind pass-through to SASL/PLAIN

[Zach Schimke <zschimke@mars.asu.edu>]

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.