[Date Prev][Date Next] [Chronological] [Thread] [Top]
RE: sasl UID mapping

To: Howard Chu <hyc@highlandsun.com>
Subject: RE: sasl UID mapping
From: Paul Jakma <paul@clubi.ie>
Date: Sun, 18 Jan 2004 03:51:47 +0000 (GMT)
Cc: "'OpenLDAP list'" <openldap-software@OpenLDAP.org>
In-reply-to: <043801c3dd71$ffab3880$1801a8c0@CELLO>
References: <043801c3dd71$ffab3880$1801a8c0@CELLO>
On Sat, 17 Jan 2004, Howard Chu wrote:

> slapd doesn't bind to itself, internal searches don't need to bind.
> But all authentication attempts are performed as anonymous. That
> means all the relevant information that is needed to perform an
> authentication must grant auth access to anonymous.

So the sasl-regexp is performed as anonymous? That /would/ explain 
it. Hmmm.. no, if i allow anonymous read access to krbname:

[paul@fogarty gpe-irc]$ ldapsearch -x -D "" -s one -b \
ou=people,dc=jakma,dc=org krbname=paul@jakma.org dn
# extended LDIF
#
# LDAPv3
# base <ou=people,dc=jakma,dc=org> with scope one
# filter: krbname=paul@jakma.org
# requesting: dn 
#

# paul, People, jakma.org
dn: uid=paul,ou=People,dc=jakma,dc=org

# search result
search: 2
result: 0 Success

# numResponses: 2
# numEntries: 1

The problem unfortunately remains.

> You haven't set a very useful debug level for chasing problems.
> It's OK for history logging of server activity, but not for
> troubleshooting. Try debug level 7 (lucky number) instead.

Ok, i had set 2056 (just about everything, bar what you ask for 
above).

> True, that's Cyrus SASL for you. By default it loads all installed
> plugins, and calls all of them for name lookups, whether you need
> them or not.

Ah.

> You can de-install the plugins you're not using, or edit the
> lib/sasl2/slapd.conf to configure an explicit list of plugins to
> use.

Yes, I actually did that after sending last mail.

> It would be nice if you posted a useful log from the beginning.
> Whenever you want to say "it doesn't do foo" the first question is
> always going to be "well, what *does* it do?" Since your log
> doesn't have anything interesting in it to answer that question,
> there are two possibilities:

>    a) we the developers are idiots, and didn't put any useful logging into
> the code

>    b) there is useful logging available, but you haven't enabled it

> If you believe (a) then there's not much point in going any
> further.

LOL.

> If (b) then you should RTFM and find out what's really going on
> before posting.

Essentially, I've been trying to post simple/quick questions, eg
"these are my sasl-regexp's, what's wrong?" with the belief/educated
guess that these are most likely the cause of the problem and someone
can point out the problem without having to deluge the list with
tonnes of debug output and extraneous info, rather withhold those
until its obvious they are needed. Apologies if approach was actually
counter-productive and/or annoying.

Find below loglevel 7 output of an ldapmodify consisting of:

# /misc, auto.master, Automount, jakma.org
dn: cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org
changetype: modify
replace: automountInformation
automountInformation: ldap:auto.misc

dn: cn=/home,ou=auto.master,ou=Automount,dc=jakma,dc=org
changetype: modify
replace: automountInformation
automountInformation: ldap:auto.home

Which fails:

[paul@fogarty gpe-irc]$ ldapmodify -f /tmp/auto.ldif
SASL/GSSAPI authentication started
SASL username: paul@JAKMA.ORG
SASL SSF: 56
SASL installing layers
modifying entry 
"cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org"
ldapmodify: update failed: 
cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org
ldap_modify: Insufficient access (50)

Note that if i replace the sasl-regexp in question:

sasl-regexp
 uid=(.*),cn=(.*),cn=gssapi,cn=auth
 ldap:///ou=people,dc=jakma,dc=org???krbName=$1@$2

with:

sasl-regexp  
 uid=(.*),cn=jakma.org,cn=gssapi,cn=auth
 uid=$1,ou=people,dc=jakma,dc=org

Then the modify works:

[paul@fogarty gpe-irc]$ ldapmodify -f /tmp/auto.misc
SASL/GSSAPI authentication started
SASL username: paul@JAKMA.ORG
SASL SSF: 56
SASL installing layers
modifying entry 
"cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org"

modifying entry 
"cn=/home,ou=auto.master,ou=Automount,dc=jakma,dc=org"

The ACL which applies to ou=automount,dc=jakma,dc=org is:

access to 
dn.regex="^(.*),ou=(Protocols|Netgroup|Rpc|Networks|Services|Automount),dc=jakma,dc=org$"
        by group.exact="cn=ldapadmins,ou=ldapgroups,dc=jakma,dc=org" write
        by * read

Ie, the problem would appear to be with ACLs.

Here is the debug level 7 output produced when i ran ldapmodify with 
the problematic sasl-regexp in place:

Jan 18 03:33:16 hibernia slapd[9323]: slapd startup: initiated. 
Jan 18 03:33:16 hibernia slapd[9323]: slapd starting 
Jan 18 03:33:25 hibernia slapd[9326]: connection_get(10) 
Jan 18 03:33:25 hibernia slapd[9326]: connection_get(10): got connid=0 
Jan 18 03:33:25 hibernia slapd[9326]: connection_read(10): checking for input on id=0 
Jan 18 03:33:25 hibernia slapd[9326]: ber_get_next on fd 10 failed errno=11 (Resource temporarily unavailable) 
Jan 18 03:33:25 hibernia slapd[9329]: do_search 
Jan 18 03:33:25 hibernia slapd[9329]: >>> dnPrettyNormal: <> 
Jan 18 03:33:25 hibernia slapd[9329]: <<< dnPrettyNormal: <>, <> 
Jan 18 03:33:25 hibernia slapd[9329]: SRCH "" 0 0
Jan 18 03:33:25 hibernia slapd[9329]:     0 0 0 
Jan 18 03:33:25 hibernia slapd[9329]:     filter: (objectClass=*) 
Jan 18 03:33:25 hibernia slapd[9329]:     attrs:
Jan 18 03:33:25 hibernia slapd[9329]:  supportedSASLMechanisms
Jan 18 03:33:25 hibernia slapd[9329]:  
Jan 18 03:33:25 hibernia slapd[9329]: => send_search_entry: dn="" 
Jan 18 03:33:25 hibernia slapd[9329]: <= send_search_entry 
Jan 18 03:33:25 hibernia slapd[9329]: send_ldap_result: conn=0 op=0 p=3 
Jan 18 03:33:26 hibernia slapd[9329]: send_ldap_result: err=0 matched="" text="" 
Jan 18 03:33:26 hibernia slapd[9329]: send_ldap_response: msgid=1 tag=101 err=0 
Jan 18 03:33:26 hibernia slapd[9326]: connection_get(10) 
Jan 18 03:33:26 hibernia slapd[9326]: connection_get(10): got connid=0 
Jan 18 03:33:26 hibernia slapd[9326]: connection_read(10): checking for input on id=0 
Jan 18 03:33:26 hibernia slapd[9326]: ber_get_next on fd 10 failed errno=11 (Resource temporarily unavailable) 
Jan 18 03:33:26 hibernia slapd[9329]: do_bind 
Jan 18 03:33:26 hibernia slapd[9329]: >>> dnPrettyNormal: <> 
Jan 18 03:33:26 hibernia slapd[9329]: <<< dnPrettyNormal: <>, <> 
Jan 18 03:33:26 hibernia slapd[9329]: do_sasl_bind: dn () mech GSSAPI 
Jan 18 03:33:26 hibernia slapd[9329]: ==> sasl_bind: dn="" mech=GSSAPI datalen=544 
Jan 18 03:33:26 hibernia slapd[9329]: send_ldap_sasl: err=14 len=153 
Jan 18 03:33:26 hibernia slapd[9329]: send_ldap_response: msgid=2 tag=97 err=14 
Jan 18 03:33:26 hibernia slapd[9329]: <== slap_sasl_bind: rc=14 
Jan 18 03:33:26 hibernia slapd[9326]: connection_get(10) 
Jan 18 03:33:26 hibernia slapd[9326]: connection_get(10): got connid=0 
Jan 18 03:33:26 hibernia slapd[9326]: connection_read(10): checking for input on id=0 
Jan 18 03:33:26 hibernia slapd[9326]: ber_get_next on fd 10 failed errno=11 (Resource temporarily unavailable) 
Jan 18 03:33:26 hibernia slapd[9329]: do_bind
Jan 18 03:33:26 hibernia slapd[9329]: >>> dnPrettyNormal: <> 
Jan 18 03:33:26 hibernia slapd[9329]: <<< dnPrettyNormal: <>, <> 
Jan 18 03:33:26 hibernia slapd[9329]: do_sasl_bind: dn () mech GSSAPI 
Jan 18 03:33:26 hibernia slapd[9329]: ==> sasl_bind: dn="" mech=<continuing> datalen=0 
Jan 18 03:33:26 hibernia slapd[9329]: send_ldap_sasl: err=14 len=65 
Jan 18 03:33:26 hibernia slapd[9329]: send_ldap_response: msgid=3 tag=97 err=14 
Jan 18 03:33:26 hibernia slapd[9329]: <== slap_sasl_bind: rc=14 
Jan 18 03:33:26 hibernia slapd[9326]: connection_get(10) 
Jan 18 03:33:26 hibernia slapd[9326]: connection_get(10): got connid=0 
Jan 18 03:33:26 hibernia slapd[9326]: connection_read(10): checking for input on id=0 
Jan 18 03:33:26 hibernia slapd[9326]: ber_get_next on fd 10 failed errno=11 (Resource temporarily unavailable) 
Jan 18 03:33:26 hibernia slapd[9329]: do_bind 
Jan 18 03:33:26 hibernia slapd[9329]: >>> dnPrettyNormal: <> 
Jan 18 03:33:26 hibernia slapd[9329]: <<< dnPrettyNormal: <>, <> 
Jan 18 03:33:26 hibernia slapd[9329]: do_sasl_bind: dn () mech GSSAPI 
Jan 18 03:33:26 hibernia slapd[9329]: ==> sasl_bind: dn="" mech=<continuing> datalen=65 
Jan 18 03:33:26 hibernia slapd[9329]: SASL Canonicalize [conn=0]: authcid="paul" 
Jan 18 03:33:26 hibernia slapd[9329]: slap_sasl_getdn: id=paul [len=4] 
Jan 18 03:33:26 hibernia slapd[9329]: getdn: u:id converted to uid=paul,cn=JAKMA.ORG,cn=GSSAPI,cn=auth 
Jan 18 03:33:26 hibernia slapd[9329]: >>> dnNormalize: <uid=paul,cn=JAKMA.ORG,cn=GSSAPI,cn=auth> 
Jan 18 03:33:26 hibernia slapd[9329]: <<< dnNormalize: <uid=paul,cn=jakma.org,cn=gssapi,cn=auth> 
Jan 18 03:33:26 hibernia slapd[9329]: ==>slap_sasl2dn: converting SASL name uid=paul,cn=jakma.org,cn=gssapi,cn=auth to a DN 
Jan 18 03:33:26 hibernia slapd[9329]: slap_sasl_regexp: converting SASL name uid=paul,cn=jakma.org,cn=gssapi,cn=auth 
Jan 18 03:33:26 hibernia slapd[9329]: slap_sasl_regexp: converted SASL name to ldap:///ou=people,dc=jakma,dc=org???krbName=paul@jakma.org 
Jan 18 03:33:27 hibernia slapd[9329]: slap_parseURI: parsing ldap:///ou=people,dc=jakma,dc=org???krbName=paul@jakma.org 
Jan 18 03:33:27 hibernia slapd[9329]: >>> dnNormalize: <ou=people,dc=jakma,dc=org> 
Jan 18 03:33:27 hibernia slapd[9329]: <<< dnNormalize: <ou=people,dc=jakma,dc=org> 
Jan 18 03:33:27 hibernia slapd[9329]: <==slap_sasl2dn: Converted SASL name to ou=people,dc=jakma,dc=org 
Jan 18 03:33:27 hibernia slapd[9329]: getdn: dn:id converted to ou=people,dc=jakma,dc=org
Jan 18 03:33:27 hibernia slapd[9329]: SASL Canonicalize [conn=0]: authcDN="ou=people,dc=jakma,dc=org" 
Jan 18 03:33:27 hibernia slapd[9329]: SASL [conn=0] Error: unable to open Berkeley db /etc/sasldb2: Permission denied 
Jan 18 03:33:27 hibernia slapd[9329]: SASL Authorize [conn=0]: authcid="paul@JAKMA.ORG" authzid="paul@JAKMA.ORG" 
Jan 18 03:33:27 hibernia slapd[9329]: SASL Authorize [conn=0]:  authorization allowed 
Jan 18 03:33:27 hibernia slapd[9329]: send_ldap_sasl: err=0 len=-1 
Jan 18 03:33:27 hibernia slapd[9329]: send_ldap_response: msgid=4 tag=97 err=0 
Jan 18 03:33:27 hibernia slapd[9329]: <== slap_sasl_bind: rc=0 
Jan 18 03:33:27 hibernia slapd[9326]: connection_get(10) 
Jan 18 03:33:27 hibernia slapd[9329]: do_bind: SASL/GSSAPI bind: dn="ou=people,dc=jakma,dc=org" ssf=56 
Jan 18 03:33:27 hibernia slapd[9326]: connection_get(10): got connid=0 
Jan 18 03:33:27 hibernia slapd[9326]: connection_read(10): checking for input on id=0 
Jan 18 03:33:27 hibernia slapd[9326]: deferring operation 
Jan 18 03:33:27 hibernia slapd[9330]: do_modify 
Jan 18 03:33:27 hibernia slapd[9330]: do_modify: dn (cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org) 
Jan 18 03:33:27 hibernia slapd[9330]: >>> dnPrettyNormal: <cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org> 
Jan 18 03:33:27 hibernia slapd[9330]: <<< dnPrettyNormal: <cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org>, <cn=/misc,ou=auto.master,ou=automount,dc=jakma,dc=org> 
Jan 18 03:33:27 hibernia slapd[9330]: modifications: 
Jan 18 03:33:27 hibernia slapd[9330]: ^Ireplace: automountInformation 
Jan 18 03:33:27 hibernia slapd[9330]: ^I^Ione value, length 14 
Jan 18 03:33:27 hibernia slapd[9330]: dn2entry_r: dn: "cn=/misc,ou=auto.master,ou=automount,dc=jakma,dc=org" 
Jan 18 03:33:27 hibernia slapd[9330]: => dn2id( "cn=/misc,ou=auto.master,ou=automount,dc=jakma,dc=org" ) 
Jan 18 03:33:27 hibernia slapd[9330]: => ldbm_cache_open( "dn2id.dbb", 73, 600 ) 
Jan 18 03:33:27 hibernia slapd[9330]: ldbm_cache_open (blksize 8192) (maxids 2046) (maxindirect 5) 
Jan 18 03:33:27 hibernia slapd[9330]: <= ldbm_cache_open (opened 0) 
Jan 18 03:33:27 hibernia slapd[9330]: <= dn2id 759 
Jan 18 03:33:27 hibernia slapd[9330]: => id2entry_r( 759 ) 
Jan 18 03:33:27 hibernia slapd[9330]: => ldbm_cache_open( "id2entry.dbb", 73, 600 ) 
Jan 18 03:33:27 hibernia slapd[9330]: ldbm_cache_open (blksize 8192) (maxids 2046) (maxindirect 5) 
Jan 18 03:33:27 hibernia slapd[9330]: <= ldbm_cache_open (opened 1) 
Jan 18 03:33:27 hibernia slapd[9330]: => str2entry
Jan 18 03:33:27 hibernia slapd[9330]: >>> dnPrettyNormal: <cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org> 
Jan 18 03:33:27 hibernia slapd[9330]: <<< dnPrettyNormal: <cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org>, <cn=/misc,ou=auto.master,ou=automount,dc=jakma,dc=org> 
Jan 18 03:33:27 hibernia slapd[9330]: <= str2entry(cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org) -> 0x8f03e68 
Jan 18 03:33:27 hibernia slapd[9330]: <= id2entry_r( 759 ) 0x8f03e68 (disk) 
Jan 18 03:33:27 hibernia slapd[9330]: ====> cache_return_entry_r( 759 ): created (0) 
Jan 18 03:33:27 hibernia slapd[9330]: ldbm_back_modify: 
Jan 18 03:33:27 hibernia slapd[9330]: dn2entry_w: dn: "cn=/misc,ou=auto.master,ou=automount,dc=jakma,dc=org" 
Jan 18 03:33:27 hibernia slapd[9330]: => dn2id( "cn=/misc,ou=auto.master,ou=automount,dc=jakma,dc=org" ) 
Jan 18 03:33:27 hibernia slapd[9330]: ====> cache_find_entry_dn2id("cn=/misc,ou=auto.master,ou=automount,dc=jakma,dc=org"): 759 (1 tries) 
Jan 18 03:33:27 hibernia slapd[9330]: <= dn2id 759 (in cache) 
Jan 18 03:33:27 hibernia slapd[9330]: => id2entry_w( 759 ) 
Jan 18 03:33:27 hibernia slapd[9330]: ====> cache_find_entry_id( 759 ) "cn=/misc,ou=auto.master,ou=Automount,dc=jakma,dc=org" (found) (1 tries) 
Jan 18 03:33:27 hibernia slapd[9330]: <= id2entry_w( 759 ) 0x8f03e68 (cache)
Jan 18 03:33:27 hibernia slapd[9330]: ldbm_modify_internal: cn=/misc,ou=auto.master,ou=automount,dc=jakma,dc=org 
Jan 18 03:33:27 hibernia slapd[9330]: => ldbm_back_group: gr dn: "cn=ldapadmins,ou=ldapgroups,dc=jakma,dc=org" 
Jan 18 03:33:27 hibernia slapd[9330]: => ldbm_back_group: op dn: "ou=people,dc=jakma,dc=org" 
Jan 18 03:33:28 hibernia slapd[9330]: => ldbm_back_group: oc: "groupOfNames" at: "member" 
Jan 18 03:33:28 hibernia slapd[9330]: => ldbm_back_group: tr dn: "cn=/misc,ou=auto.master,ou=automount,dc=jakma,dc=org" 
Jan 18 03:33:28 hibernia slapd[9330]: dn2entry_r: dn: "cn=ldapadmins,ou=ldapgroups,dc=jakma,dc=org" 
Jan 18 03:33:28 hibernia slapd[9330]: => dn2id( "cn=ldapadmins,ou=ldapgroups,dc=jakma,dc=org" ) 
Jan 18 03:33:28 hibernia slapd[9330]: => ldbm_cache_open( "dn2id.dbb", 73, 600 ) 
Jan 18 03:33:28 hibernia slapd[9330]: <= ldbm_cache_open (cache 0) 
Jan 18 03:33:28 hibernia slapd[9330]: <= dn2id 776 
Jan 18 03:33:28 hibernia slapd[9330]: => id2entry_r( 776 ) 
Jan 18 03:33:28 hibernia slapd[9330]: => ldbm_cache_open( "id2entry.dbb", 73, 600 ) 
Jan 18 03:33:28 hibernia slapd[9330]: <= ldbm_cache_open (cache 1) 
Jan 18 03:33:28 hibernia slapd[9330]: => str2entry 
Jan 18 03:33:28 hibernia slapd[9330]: >>> dnPrettyNormal: <cn=ldapadmins,ou=ldapgroups,dc=jakma,dc=org> 
Jan 18 03:33:28 hibernia slapd[9330]: <<< dnPrettyNormal: <cn=ldapadmins,ou=ldapgroups,dc=jakma,dc=org>, <cn=ldapadmins,ou=ldapgroups,dc=jakma,dc=org> 
Jan 18 03:33:28 hibernia slapd[9330]: <= str2entry(cn=ldapadmins,ou=ldapgroups,dc=jakma,dc=org) -> 0x8f0d300 
Jan 18 03:33:28 hibernia slapd[9330]: <= id2entry_r( 776 ) 0x8f0d300 (disk) 
Jan 18 03:33:28 hibernia slapd[9330]: >>> dnNormalize: <cn=manager,dc=jakma,dc=org> 
Jan 18 03:33:28 hibernia slapd[9330]: <<< dnNormalize: <cn=manager,dc=jakma,dc=org> 
Jan 18 03:33:28 hibernia slapd[9330]: dnMatch 1 ^I"cn=manager,dc=jakma,dc=org" ^I"ou=people,dc=jakma,dc=org" 
Jan 18 03:33:28 hibernia slapd[9330]: >>> dnNormalize: <uid=paul,ou=people,dc=jakma,dc=org> 
Jan 18 03:33:28 hibernia slapd[9330]: <<< dnNormalize: <uid=paul,ou=people,dc=jakma,dc=org> 
Jan 18 03:33:28 hibernia slapd[9330]: dnMatch 9 ^I"uid=paul,ou=people,dc=jakma,dc=org" ^I"ou=people,dc=jakma,dc=org" 
Jan 18 03:33:28 hibernia slapd[9330]: ====> cache_return_entry_r( 776 ): created (0) 
Jan 18 03:33:28 hibernia slapd[9330]: ldbm_back_group: rc=1
Jan 18 03:33:28 hibernia slapd[9330]: send_ldap_result: conn=0 op=4 p=3 
Jan 18 03:33:28 hibernia slapd[9330]: send_ldap_result: err=50 matched="" text="" 
Jan 18 03:33:28 hibernia slapd[9330]: send_ldap_response: msgid=5 tag=103 err=50 
Jan 18 03:33:28 hibernia slapd[9330]: ====> cache_return_entry_w( 759 ): returned (0) 
Jan 18 03:33:28 hibernia slapd[9326]: connection_get(10) 
Jan 18 03:33:28 hibernia slapd[9326]: connection_get(10): got connid=0 
Jan 18 03:33:28 hibernia slapd[9326]: connection_read(10): checking for input on id=0 
Jan 18 03:33:28 hibernia slapd[9326]: ber_get_next on fd 10 failed errno=0 (Success) 
Jan 18 03:33:28 hibernia slapd[9329]: do_unbind 
Jan 18 03:33:28 hibernia slapd[9326]: connection_read(10): input error=-2 id=0, closing. 
Jan 18 03:33:28 hibernia slapd[9326]: connection_closing: readying conn=0 sd=10 for close 
Jan 18 03:33:28 hibernia slapd[9326]: connection_close: deferring conn=0 sd=10 
Jan 18 03:33:28 hibernia slapd[9329]: connection_resched: attempting closing conn=0 sd=10 
Jan 18 03:33:28 hibernia slapd[9329]: connection_close: conn=0 sd=10
Jan 18 03:33:29 hibernia slapd[9326]: daemon: shutdown requested and initiated. 
Jan 18 03:33:29 hibernia slapd[9326]: slapd shutdown: waiting for 0 threads to terminate 

>   -- Howard Chu

regards,
-- 
Paul Jakma	paul@clubi.ie	paul@jakma.org	Key ID: 64A2FF6A
	warning: do not ever send email to spam@dishone.st
Fortune:
The road to ruin is always in good repair, and the travellers pay the
expense of it.
		-- Josh Billings
Follow-Ups:
- RE: sasl UID mapping
  - From: Quanah Gibson-Mount <quanah@stanford.edu>
- RE: sasl UID mapping
  - From: "Howard Chu" <hyc@highlandsun.com>
References:
- RE: sasl UID mapping
  - From: "Howard Chu" <hyc@highlandsun.com>
Prev by Date: RE: sasl UID mapping
Next by Date: RE: sasl UID mapping
Index(es):
- Chronological
- Thread