[Date Prev][Date Next] [Chronological] [Thread] [Top]
upgraded and all goes down...

To: openldap-software@OpenLDAP.org
Subject: upgraded and all goes down...
From: Alexander Lunyov <lan_mailing@startatom.ru>
Date: Thu, 18 Dec 2003 21:14:34 +0300
In-reply-to: <112785874.20031217215714@startatom.ru>
References: <05040765.20031217082859@startatom.ru> <005c01c3c49c$c65c0ed0$1801a8c0@CELLO> <112785874.20031217215714@startatom.ru>
Hello Alexander,

Wednesday, December 17, 2003, 9:57:14 PM, you wrote:

HC>> Please update to the current OpenLDAP release (at least 2.1.25). Among other
HC>> important bug fixes, the ldapsasl README file has also been updated with more
HC>> usage notes.

AL>     I wanted to, but there is still 2.1.23 port in FreeBSD port
AL>     collection (it's this week cvsup). I think, i'll do this port by
AL>     myself and take a look if it will work. Also i'll have to change
AL>     ldapdb-auxprop port (it's my own port for my comfort while
AL>     installing auxprop plugin) because SASL is already 2.1.17 now, and
AL>     old ldapdb-auxprop port based on 2.1.15 distfile of SASL

        All is ruined. I've upgraded to cyrus-sasl-2.1.17,
        openldap-2.1.25 and cyrus-imapd-2.1.16, compiled auxprop
        plugin and... it's not working. Ldapdb plugin is not working.
        Nor fresh compiled from openldap-2.1.25 contribs, nor the old
        one from 2.1.23. I don't know how to take it all back.
        Tomorrow everything have to be OK. This message is a S.O.S.,
        i think.

        Details:

        When i'm trying to ldapwhoami or ldapsearch with DIGEST-MD5
        auth - all is fine. Even proxy is works fine:

        From the beginning: 'lan' is a user, 'cyradm' - is a proxy
        user for plugin auth.

In /usr/local/lib/sasl2/Cyrus.conf:
=========================================
auxprop_plugin: ldapdb
#pwcheck_method: auxprop
ldapdb_uri: ldap:///
ldapdb_id: cyradm
ldapdb_pw: password
ldapdb_mech: DIGEST-MD5
mech_list: plain login digest-md5 cram-md5        
=========================================

In /usr/local/lib/sasl2/slapd.conf:
=========================================
auxprop_plugin: slapd
=========================================

In /usr/local/etc/openldap/slapd.conf:
=========================================
[skipped]
sasl-regexp uid=(.*),cn=.*,cn=auth
    ldap:///ou=users,dc=domain,dc=ru??sub?(uid=$1)

sasl-authz-policy to
password-hash   {CLEARTEXT}
[skipped]
=========================================

In 'cyradm' LDIF:
=========================================
dn: uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru
mail: cyradm-mail
uid: cyradm
objectClass: personAccount
sn: cyradm
cn: cyradm
userPassword: password
saslAuthzTo: uid=.*,node=.*,ou=users,dc=domain,dc=ru
=========================================

    But proxy auth is working.

=========================================
# ldapwhoami -U cyradm -X u:lan -Y DIGEST-MD5 -H ldap:///
SASL/DIGEST-MD5 authentication started
Please enter your password: {here i'm typing password for user 'cyradm'}
SASL username: u:lan
SASL SSF: 128
SASL installing layers
dn:uid=lan,node=33(10),ou=users,dc=domain,dc=ru
=========================================

    But when i'm trying to test ldapdb plugin with 'imtest' utility -
    it fails. And with any mail program - fails. I don't know why, but
    it fails. Now i'm thinking that i shouldn't upgrade at all... But
    now all is done, and i have to work it out.

    Log file (simple) when cyrus-imapd fails to authorize user:

=========================================
conn=12 op=1 BIND dn="uid=cyradm,node=33(10),ou=users,dc=startatom,dc=ru" mech=DIGEST-MD5 ssf=128
conn=12 op=2 RESULT tag=120 err=47 text=not authorized to assume identity
=========================================

        I've never seen such error before.
        In a full log (loglevel 769):

=========================================
conn=2 fd=9 ACCEPT from IP=127.0.0.1:4997 (IP=0.0.0.0:389)
connection_get(9): got connid=2 
connection_read(9): checking for input on id=2 
ber_get_next on fd 9 failed errno=35 (Resource temporarily unavailable) 
do_bind 
>>> dnPrettyNormal: <> 
<<< dnPrettyNormal: <>, <> 
do_sasl_bind: dn () mech DIGEST-MD5 
conn=2 op=0 BIND dn="" method=163 
SASL [conn=2] Debug: DIGEST-MD5 server step 1 
send_ldap_sasl: err=14 len=192 
send_ldap_response: msgid=1 tag=97 err=14 
<== slap_sasl_bind: rc=14 
connection_get(9): got connid=2 
connection_read(9): checking for input on id=2 
ber_get_next on fd 9 failed errno=35 (Resource temporarily unavailable) 
do_bind 
>>> dnPrettyNormal: <> 
<<< dnPrettyNormal: <>, <> 
do_sasl_bind: dn () mech DIGEST-MD5 
conn=2 op=1 BIND dn="" method=163 
SASL [conn=2] Debug: DIGEST-MD5 server step 2 
getdn: u:id converted to uid=cyradm,cn=DIGEST-MD5,cn=auth 
>>> dnNormalize: <uid=cyradm,cn=DIGEST-MD5,cn=auth> 
<<< dnNormalize: <uid=cyradm,cn=digest-md5,cn=auth> 
==>slap_sasl2dn: converting SASL name uid=cyradm,cn=digest-md5,cn=auth to a DN 
slap_sasl_regexp: converting SASL name uid=cyradm,cn=digest-md5,cn=auth 
slap_sasl_regexp: converted SASL name to ldap:///ou=users,dc=domain,dc=ru??sub?(uid=cyradm) 
slap_parseURI: parsing ldap:///ou=users,dc=domain,dc=ru??sub?(uid=cyradm) 
>>> dnNormalize: <ou=users,dc=domain,dc=ru> 
<<< dnNormalize: <ou=users,dc=domain,dc=ru> 
slap_sasl2dn: performing internal search (base=ou=users,dc=domain,dc=ru, scope=2) 
=> ldbm_back_search 
dn2entry_r: dn: "ou=users,dc=domain,dc=ru" 
=> dn2id( "ou=users,dc=domain,dc=ru" ) 
====> cache_find_entry_dn2id("ou=users,dc=domain,dc=ru"): 3 (1 tries) 
<= dn2id 3 (in cache) 
=> id2entry_r( 3 ) 
====> cache_find_entry_id( 3 ) "ou=users,dc=domain,dc=ru" (found) (1 tries) 
<= id2entry_r( 3 ) 0x8125980 (cache) 
search_candidates: base="ou=users,dc=domain,dc=ru" s=2 d=0 
=> filter_candidates 
=> list_candidates 0xa0 
=> filter_candidates 
=> dn2idl( "@ou=users,dc=domain,dc=ru" ) 
=> ldbm_cache_open( "dn2id.dbb", 73, 600 ) 
<= ldbm_cache_open (cache 0) 
<= filter_candidates 197 
=> filter_candidates 
=> list_candidates 0xa1 
=> filter_candidates 
=> equality_candidates 
=> ldbm_cache_open( "objectClass.dbb", 73, 600 ) 
<= ldbm_cache_open (cache 3) 
=> key_read 
<= index_read 0 candidates 
<= equality_candidates NULL 
<= equality_candidates 0 
<= filter_candidates 0 
=> filter_candidates 
=> equality_candidates 
<= equality_candidates: index_param returned=18 
<= filter_candidates 244 
<= list_candidates 244 
<= filter_candidates 244 
<= list_candidates 197 
<= filter_candidates 197 
====> cache_return_entry_r( 3 ): returned (0) 
=> id2entry_r( 3 ) 
====> cache_find_entry_id( 3 ) "ou=users,dc=domain,dc=ru" (found) (1 tries) 
<= id2entry_r( 3 ) 0x8125980 (cache) 
=> string_expand: pattern:  cn=replica,dc=domain,dc=ru 
=> string_expand: expanded: cn=replica,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
=> string_expand: pattern:  cn=usermaster,dc=domain,dc=ru 
=> string_expand: expanded: cn=usermaster,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
ldbm_search: candidate entry 3 does not match filter 
====> cache_return_entry_r( 3 ): returned (0) 
=> id2entry_r( 9 ) 
====> cache_find_entry_id( 9 ) "node=33(10),ou=users,dc=domain,dc=ru" (found) (1 tries) 
<= id2entry_r( 9 ) 0x8125b00 (cache) 
=> string_expand: pattern:  cn=replica,dc=domain,dc=ru 
=> string_expand: expanded: cn=replica,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
=> string_expand: pattern:  cn=usermaster,dc=domain,dc=ru 
=> string_expand: expanded: cn=usermaster,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
ldbm_search: candidate entry 9 does not match filter 
====> cache_return_entry_r( 9 ): returned (0) 
=> id2entry_r( 10 ) 
====> cache_find_entry_id( 10 ) "uid=lan,node=33(10),ou=users,dc=domain,dc=ru" (found) (1 tries) 
<= id2entry_r( 10 ) 0x8125c00 (cache) 
=> string_expand: pattern:  cn=replica,dc=domain,dc=ru 
=> string_expand: expanded: cn=replica,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
=> string_expand: pattern:  cn=usermaster,dc=domain,dc=ru 
=> string_expand: expanded: cn=usermaster,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
ldbm_search: candidate entry 10 does not match filter 
====> cache_return_entry_r( 10 ): returned (0) 
=> id2entry_r( 11 ) 

[skip - same blocks of log, nothing interesting]

====> cache_return_entry_r( 243 ): returned (0) 
<==slap_sasl2dn: Converted SASL name to uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru 
getdn: dn:id converted to uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru 
=> ldbm_back_search 
dn2entry_r: dn: "uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" 
=> dn2id( "uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" ) 
====> cache_find_entry_dn2id("uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru"): 175 (1 tries) 
<= dn2id 175 (in cache) 
=> id2entry_r( 175 ) 
====> cache_find_entry_id( 175 ) "uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" (found) (1 tries) 
<= id2entry_r( 175 ) 0x8a6b6c0 (cache) 
base_candidates: base: "uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" 
====> cache_return_entry_r( 175 ): returned (0) 
=> id2entry_r( 175 ) 
====> cache_find_entry_id( 175 ) "uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" (found) (1 tries) 
<= id2entry_r( 175 ) 0x8a6b6c0 (cache) 
=> string_expand: pattern:  cn=replica,dc=domain,dc=ru 
=> string_expand: expanded: cn=replica,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
=> string_expand: pattern:  cn=usermaster,dc=domain,dc=ru 
=> string_expand: expanded: cn=usermaster,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
=> string_expand: pattern:  cn=usermaster,dc=domain,dc=ru 
=> string_expand: expanded: cn=usermaster,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
=> string_expand: pattern:  cn=replica,dc=domain,dc=ru 
=> string_expand: expanded: cn=replica,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
=> string_expand: pattern:  cn=admin,dc=domain,dc=ru 
=> string_expand: expanded: cn=admin,dc=domain,dc=ru 
=> regex_matches: string:     
=> regex_matches: rc: 1 no matches 
slap_auxprop: str2ad(cmusaslsecretDIGEST-MD5): attribute type undefined 
====> cache_return_entry_r( 175 ): returned (0)
conn=2 op=1 BIND authcid="cyradm" 
SASL Authorize [conn=2]:  authorization allowed 

     OK, here it's all right. But then...

send_ldap_sasl: err=0 len=40 
send_ldap_response: msgid=2 tag=97 err=0 
<== slap_sasl_bind: rc=0 
conn=2 op=1 BIND dn="uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" mech=DIGEST-MD5 ssf=128 
do_bind: SASL/DIGEST-MD5 bind: dn="uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" ssf=128 
connection_get(9): got connid=2 
connection_read(9): checking for input on id=2 
ber_get_next on fd 9 failed errno=35 (Resource temporarily unavailable) 
do_extended 
=> get_ctrls 
=> get_ctrls: oid="2.16.840.1.113730.3.4.18" (critical) 
getdn: u:id converted to uid=root,cn=auth 
>>> dnNormalize: <uid=root,cn=auth> 
<<< dnNormalize: <uid=root,cn=auth> 

    And now, where this 'uid=root,cn=auth' comes from?! So, after that

==>slap_sasl2dn: converting SASL name uid=root,cn=auth to a DN 
slap_sasl_regexp: converting SASL name uid=root,cn=auth 
<==slap_sasl2dn: Converted SASL name to <nothing> 
parseProxyAuthz: conn=2 "uid=root,cn=auth" 
==>slap_sasl_authorized: can uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru become uid=root,cn=auth? 
==>slap_sasl_check_authz: does uid=root,cn=auth match saslAuthzTo rule in uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru? 
dn2entry_r: dn: "uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" 
=> dn2id( "uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" ) 
====> cache_find_entry_dn2id("uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru"): 175 (1 tries) 
<= dn2id 175 (in cache) 
=> id2entry_r( 175 ) 
====> cache_find_entry_id( 175 ) "uid=cyradm,node=33(10),ou=users,dc=domain,dc=ru" (found) (1 tries) 
<= id2entry_r( 175 ) 0x8a6b6c0 (cache) 
====> cache_return_entry_r( 175 ): returned (0) 
ldbm_back_attribute: rc=0 nvals=1 
===>slap_sasl_match: comparing DN uid=root,cn=auth to rule uid=.*,node=.*,ou=users,dc=domain,dc=ru 
slap_parseURI: parsing uid=.*,node=.*,ou=users,dc=domain,dc=ru 
>>> dnNormalize: <uid=.*,node=.*,ou=users,dc=domain,dc=ru> 
<<< dnNormalize: <uid=.*,node=.*,ou=users,dc=domain,dc=ru> 
<===slap_sasl_match: comparison returned 48 
<==slap_sasl_check_authz: saslAuthzTo check returning 48 
<== slap_sasl_authorized: return 48 
<= get_ctrls: n=1 rc=47 err="not authorized to assume identity" 
send_ldap_result: conn=2 op=2 p=3 
send_ldap_response: msgid=3 tag=120 err=47 
conn=2 op=2 RESULT tag=120 err=47 text=not authorized to assume identity 
do_extended: get_ctrls failed 
connection_get(9): got connid=2 
connection_read(9): checking for input on id=2 
ber_get_next on fd 9 failed errno=0 (Undefined error: 0) 
connection_read(9): input error=-2 id=2, closing. 
connection_closing: readying conn=2 sd=9 for close 
connection_close: deferring conn=2 sd=9 
do_unbind 
conn=2 op=3 UNBIND 
connection_resched: attempting closing conn=2 sd=9 
connection_close: conn=2 sd=9 
conn=2 fd=9 closed 
=========================================


-- 
Best regards,
 Alexander                            mailto:lan_mailing@startatom.ru
Follow-Ups:
- Re: upgraded and all goes down...
  - From: Igor Brezac <igor@ipass.net>
- RE: [JunkMail] upgraded and all goes down...
  - From: "Howard Chu" <hyc@highlandsun.com>
References:
- SASL error messages - still don't get it
  - From: Alexander Lunyov <lan_mailing@startatom.ru>
- RE: SASL error messages - still don't get it
  - From: "Howard Chu" <hyc@highlandsun.com>
- Re[2]: SASL error messages - still don't get it
  - From: Alexander Lunyov <lan_mailing@startatom.ru>
Prev by Date: RE: openldap/sasl/krb5 authentication question:
Next by Date: Re: upgraded and all goes down...
Index(es):
- Chronological
- Thread