[Date Prev][Date Next] [Chronological] [Thread] [Top]

Re: Proxy authorization fail with cyrus-sasl and postfix

To: <masarati@aero.polimi.it>
Subject: Re: Proxy authorization fail with cyrus-sasl and postfix
From: Julien Vehent <julien@linuxwall.info>
Date: Mon, 24 May 2010 12:07:38 +0200
Cc: Openldap technical <openldap-technical@openldap.org>
Dkim-signature: v=1; a=rsa-sha256; c=relaxed; d=linuxwall.info; h= mime-version:content-type:date:from:to:cc:subject:in-reply-to :references:message-id; s=lnw-dkim; bh=xQDNRDbDU/UgdHZJCIlN5Yx3Y k8F6p2JSCUvXbdoJoo=; b=i2S0C+dPfL+49n5ppQwTZAsT2ehNSKhOXaK6sVdnX As8PH0ko6SCDFyV00FblvFxdXVnqENAbn0JIObqPluwCzlbsKWsKVEnqLsFlJuRb BP3C/hk9FWBeSwqrTGOjD+UmW8LLzc9Co4SqAs1UHSiGSdSWoRiOjlFkleJ3TvJS 5w=
In-reply-to: <efd29027d826ca1582f1cdf08f5653b0.squirrel@www.aero.polimi.it>
Organization: linuxwall.info
References: <eddade65fcbcb23e2ce269180c9608a2@localhost> <efd29027d826ca1582f1cdf08f5653b0.squirrel@www.aero.polimi.it>
User-agent: Linuxwall Roundcube Webmail/0.4-beta

On Sun, 23 May 2010 18:35:21 +0200 (CEST), masarati@aero.polimi.it wrote:
> Can you check what exact operation is being attempted?  I mean: what
> identity "cn=postfix
administrator,ou=infrastructure,dc=linuxwall,dc=info"
> is trying to authorize as during conn=109 op=2?  You should try to
> reproduce the authorization part of it, e.g. using ldapwhoami as the
> postfix administrator, and authorizing with exactly the same identity is
> being used in that operation, using "stats,trace,args" log level to see
> where it fails.
> 

Sweet, thanks for your help at debugging, I found the issue !

In the Slapd logs, when Postfix sends the UID of the user it wants to
authenticate as, it sends the email address of the user, ie, for julien, it
would send julien@linuxwall.info
Therefore,slapd looks for a user that has julien@linuxwall.info in its
UID, and obviously doesn't find it...

I asked the folks at the postfix mailing if they know anything about that,
and if they have a correction for me.

----
May 24 11:55:30 samchiel slapd[13163]: => get_ctrls
May 24 11:55:30 samchiel slapd[13163]: => get_ctrls:
oid="2.16.840.1.113730.3.4.18" (critical)
May 24 11:55:30 samchiel slapd[13163]: parseProxyAuthz: conn 3
authzid="u:julien@linuxwall.info"
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: conn 3
id=u:julien@linuxwall.info [len=23]
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: u:id converted to
uid=julien@linuxwall.info,cn=DIGEST-MD5,cn=auth
May 24 11:55:30 samchiel slapd[13163]: >>> dnNormalize:
<uid=julien@linuxwall.info,cn=DIGEST-MD5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: <<< dnNormalize:
<uid=julien@linuxwall.info,cn=digest-md5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: ==>slap_sasl2dn: converting SASL
name uid=julien@linuxwall.info,cn=digest-md5,cn=auth to a DN
May 24 11:55:30 samchiel slapd[13163]: [rw] authid:
"uid=julien@linuxwall.info,cn=digest-md5,cn=auth" ->
"ldap:///dc=linuxwall,dc=info??sub(uid=julien@linuxwall.info)"
May 24 11:55:30 samchiel slapd[13163]: slap_parseURI: parsing
ldap:///dc=linuxwall,dc=info??sub?(uid=julien@linuxwall.info)
----

(complete trace is attached)

Thanks,
Julien

May 24 11:55:30 samchiel slapd[13163]: slap_listener_activate(8):
May 24 11:55:30 samchiel slapd[13163]: >>> slap_listener(ldap://127.0.0.1:389/)
May 24 11:55:30 samchiel slapd[13163]: conn=3 fd=16 ACCEPT from IP=127.0.0.1:34014 (IP=127.0.0.1:389)
May 24 11:55:30 samchiel slapd[13163]: connection_get(16)
May 24 11:55:30 samchiel slapd[13163]: connection_get(16): got connid=3
May 24 11:55:30 samchiel slapd[13163]: connection_read(16): checking for input on id=3
May 24 11:55:30 samchiel slapd[13163]: op tag 0x60, time 1274694930
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=0 do_bind
May 24 11:55:30 samchiel slapd[13163]: >>> dnPrettyNormal: <>
May 24 11:55:30 samchiel slapd[13163]: <<< dnPrettyNormal: <>, <>
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=0 BIND dn="" method=163
May 24 11:55:30 samchiel slapd[13163]: do_bind: dn () SASL mech DIGEST-MD5
May 24 11:55:30 samchiel slapd[13163]: ==> sasl_bind: dn="" mech=DIGEST-MD5 datalen=0
May 24 11:55:30 samchiel slapd[13163]: SASL [conn=3] Debug: DIGEST-MD5 server step 1
May 24 11:55:30 samchiel slapd[13163]: send_ldap_sasl: err=14 len=196
May 24 11:55:30 samchiel slapd[13163]: send_ldap_response: msgid=1 tag=97 err=14
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=0 RESULT tag=97 err=14 text=SASL(0): successful result:
May 24 11:55:30 samchiel slapd[13163]: <== slap_sasl_bind: rc=14
May 24 11:55:30 samchiel slapd[13163]: connection_get(16)
May 24 11:55:30 samchiel slapd[13163]: connection_get(16): got connid=3
May 24 11:55:30 samchiel slapd[13163]: connection_read(16): checking for input on id=3
May 24 11:55:30 samchiel slapd[13163]: op tag 0x60, time 1274694930
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=1 do_bind
May 24 11:55:30 samchiel slapd[13163]: >>> dnPrettyNormal: <>
May 24 11:55:30 samchiel slapd[13163]: <<< dnPrettyNormal: <>, <>
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=1 BIND dn="" method=163
May 24 11:55:30 samchiel slapd[13163]: do_bind: dn () SASL mech DIGEST-MD5
May 24 11:55:30 samchiel slapd[13163]: ==> sasl_bind: dn="" mech=<continuing> datalen=294
May 24 11:55:30 samchiel slapd[13163]: SASL [conn=3] Debug: DIGEST-MD5 server step 2
May 24 11:55:30 samchiel slapd[13163]: SASL Canonicalize [conn=3]: authcid="postfix"
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: conn 3 id=postfix [len=7]
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: u:id converted to uid=postfix,cn=DIGEST-MD5,cn=auth
May 24 11:55:30 samchiel slapd[13163]: >>> dnNormalize: <uid=postfix,cn=DIGEST-MD5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: <<< dnNormalize: <uid=postfix,cn=digest-md5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: ==>slap_sasl2dn: converting SASL name uid=postfix,cn=digest-md5,cn=auth to a DN
May 24 11:55:30 samchiel slapd[13163]: [rw] authid: "uid=postfix,cn=digest-md5,cn=auth" -> "ldap:///dc=linuxwall,dc=info??sub?(uid=postfix)"
May 24 11:55:30 samchiel slapd[13163]: slap_parseURI: parsing ldap:///dc=linuxwall,dc=info??sub?(uid=postfix)
May 24 11:55:30 samchiel slapd[13163]: >>> dnNormalize: <dc=linuxwall,dc=info>
May 24 11:55:30 samchiel slapd[13163]: <<< dnNormalize: <dc=linuxwall,dc=info>
May 24 11:55:30 samchiel slapd[13163]: slap_sasl2dn: performing internal search (base=dc=linuxwall,dc=info, scope=2)
May 24 11:55:30 samchiel slapd[13163]: => hdb_search
May 24 11:55:30 samchiel slapd[13163]: bdb_dn2entry("dc=linuxwall,dc=info")
May 24 11:55:30 samchiel slapd[13163]: search_candidates: base="dc=linuxwall,dc=info" (0x00000001) scope=2
May 24 11:55:30 samchiel slapd[13163]: => hdb_dn2idl("dc=linuxwall,dc=info")
May 24 11:55:30 samchiel slapd[13163]: => bdb_equality_candidates (objectClass)
May 24 11:55:30 samchiel slapd[13163]: => key_read
May 24 11:55:30 samchiel slapd[13163]: bdb_idl_fetch_key: [b49d1940]
May 24 11:55:30 samchiel slapd[13163]: <= bdb_index_read: failed (-30988)
May 24 11:55:30 samchiel slapd[13163]: <= bdb_equality_candidates: id=0, first=0, last=0
May 24 11:55:30 samchiel slapd[13163]: => bdb_equality_candidates (uid)
May 24 11:55:30 samchiel slapd[13163]: => key_read
May 24 11:55:30 samchiel slapd[13163]: bdb_idl_fetch_key: [b83a7e64]
May 24 11:55:30 samchiel slapd[13163]: <= bdb_index_read 1 candidates
May 24 11:55:30 samchiel slapd[13163]: <= bdb_equality_candidates: id=1, first=10, last=10
May 24 11:55:30 samchiel slapd[13163]: bdb_search_candidates: id=1 first=10 last=10
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: conn=3 op=1 p=3
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: err=0 matched="" text=""
May 24 11:55:30 samchiel slapd[13163]: <==slap_sasl2dn: Converted SASL name to cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: dn:id converted to cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info
May 24 11:55:30 samchiel slapd[13163]: SASL Canonicalize [conn=3]: slapAuthcDN="cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info"
May 24 11:55:30 samchiel slapd[13163]: => hdb_search
May 24 11:55:30 samchiel slapd[13163]: bdb_dn2entry("cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info")
May 24 11:55:30 samchiel slapd[13163]: base_candidates: base: "cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info" (0x0000000a)
May 24 11:55:30 samchiel slapd[13163]: slap_ap_lookup: str2ad(cmusaslsecretDIGEST-MD5): attribute type undefined
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: conn=3 op=1 p=3
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: err=0 matched="" text=""
May 24 11:55:30 samchiel slapd[13163]: SASL Canonicalize [conn=3]: authzid="postfix"
May 24 11:55:30 samchiel slapd[13163]: SASL proxy authorize [conn=3]: authcid="postfix" authzid="postfix"
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=1 BIND authcid="postfix" authzid="postfix"
May 24 11:55:30 samchiel slapd[13163]: SASL Authorize [conn=3]:  proxy authorization allowed authzDN=""
May 24 11:55:30 samchiel slapd[13163]: send_ldap_sasl: err=0 len=40
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=1 BIND dn="cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info" mech=DIGEST-MD5 sasl_ssf=128 ssf=128
May 24 11:55:30 samchiel slapd[13163]: do_bind: SASL/DIGEST-MD5 bind: dn="cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info" sasl_ssf=128
May 24 11:55:30 samchiel slapd[13163]: send_ldap_response: msgid=2 tag=97 err=0
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=1 RESULT tag=97 err=0 text=
May 24 11:55:30 samchiel slapd[13163]: <== slap_sasl_bind: rc=0
May 24 11:55:30 samchiel slapd[13163]: connection_get(16)
May 24 11:55:30 samchiel slapd[13163]: connection_get(16): got connid=3
May 24 11:55:30 samchiel slapd[13163]: connection_read(16): checking for input on id=3
May 24 11:55:30 samchiel slapd[13163]: op tag 0x77, time 1274694930
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=2 do_extended
May 24 11:55:30 samchiel slapd[13163]: => get_ctrls
May 24 11:55:30 samchiel slapd[13163]: => get_ctrls: oid="2.16.840.1.113730.3.4.18" (critical)
May 24 11:55:30 samchiel slapd[13163]: parseProxyAuthz: conn 3 authzid="u:julien@linuxwall.info"
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: conn 3 id=u:julien@linuxwall.info [len=23]
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: u:id converted to uid=julien@linuxwall.info,cn=DIGEST-MD5,cn=auth
May 24 11:55:30 samchiel slapd[13163]: >>> dnNormalize: <uid=julien@linuxwall.info,cn=DIGEST-MD5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: <<< dnNormalize: <uid=julien@linuxwall.info,cn=digest-md5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: ==>slap_sasl2dn: converting SASL name uid=julien@linuxwall.info,cn=digest-md5,cn=auth to a DN
May 24 11:55:30 samchiel slapd[13163]: [rw] authid: "uid=julien@linuxwall.info,cn=digest-md5,cn=auth" -> "ldap:///dc=linuxwall,dc=info??sub?(uid=julien@linuxwall.info)"
May 24 11:55:30 samchiel slapd[13163]: slap_parseURI: parsing ldap:///dc=linuxwall,dc=info??sub?(uid=julien@linuxwall.info)
May 24 11:55:30 samchiel slapd[13163]: >>> dnNormalize: <dc=linuxwall,dc=info>
May 24 11:55:30 samchiel slapd[13163]: <<< dnNormalize: <dc=linuxwall,dc=info>
May 24 11:55:30 samchiel slapd[13163]: slap_sasl2dn: performing internal search (base=dc=linuxwall,dc=info, scope=2)
May 24 11:55:30 samchiel slapd[13163]: => hdb_search
May 24 11:55:30 samchiel slapd[13163]: bdb_dn2entry("dc=linuxwall,dc=info")
May 24 11:55:30 samchiel slapd[13163]: search_candidates: base="dc=linuxwall,dc=info" (0x00000001) scope=2
May 24 11:55:30 samchiel slapd[13163]: => hdb_dn2idl("dc=linuxwall,dc=info")
May 24 11:55:30 samchiel slapd[13163]: => bdb_equality_candidates (objectClass)
May 24 11:55:30 samchiel slapd[13163]: => key_read
May 24 11:55:30 samchiel slapd[13163]: bdb_idl_fetch_key: [b49d1940]
May 24 11:55:30 samchiel slapd[13163]: <= bdb_index_read: failed (-30988)
May 24 11:55:30 samchiel slapd[13163]: <= bdb_equality_candidates: id=0, first=0, last=0
May 24 11:55:30 samchiel slapd[13163]: => bdb_equality_candidates (uid)
May 24 11:55:30 samchiel slapd[13163]: => key_read
May 24 11:55:30 samchiel slapd[13163]: bdb_idl_fetch_key: [128d5d60]
May 24 11:55:30 samchiel slapd[13163]: <= bdb_index_read: failed (-30988)
May 24 11:55:30 samchiel slapd[13163]: <= bdb_equality_candidates: id=0, first=0, last=0
May 24 11:55:30 samchiel slapd[13163]: bdb_search_candidates: id=0 first=1 last=0
May 24 11:55:30 samchiel slapd[13163]: hdb_search: no candidates
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: conn=3 op=2 p=3
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: err=0 matched="" text=""
May 24 11:55:30 samchiel slapd[13163]: <==slap_sasl2dn: Converted SASL name to <nothing>
May 24 11:55:30 samchiel slapd[13163]: parseProxyAuthz: conn=3 "uid=julien@linuxwall.info,cn=digest-md5,cn=auth"
May 24 11:55:30 samchiel slapd[13163]: ==>slap_sasl_authorized: can cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info become uid=julien@linuxwall.info,cn=digest-md5,cn=auth?
May 24 11:55:30 samchiel slapd[13163]: ==>slap_sasl_check_authz: does uid=julien@linuxwall.info,cn=digest-md5,cn=auth match authzTo rule in cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info?
May 24 11:55:30 samchiel slapd[13163]: => bdb_entry_get: ndn: "cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info"
May 24 11:55:30 samchiel slapd[13163]: => bdb_entry_get: oc: "(null)", at: "authzTo"
May 24 11:55:30 samchiel slapd[13163]: bdb_dn2entry("cn=postfix administrator,ou=infrastructure,dc=linuxwall,dc=info")
May 24 11:55:30 samchiel slapd[13163]: bdb_entry_get: rc=0
May 24 11:55:30 samchiel slapd[13163]: ===>slap_sasl_match: comparing DN uid=julien@linuxwall.info,cn=digest-md5,cn=auth to rule ldap:///dc=linuxwall,dc=info??sub?(objectClass=inetOrgPerson)
May 24 11:55:30 samchiel slapd[13163]: slap_parseURI: parsing ldap:///dc=linuxwall,dc=info??sub?(objectClass=inetOrgPerson)
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_match: performing internal search (base=dc=linuxwall,dc=info, scope=2)
May 24 11:55:30 samchiel slapd[13163]: => hdb_search
May 24 11:55:30 samchiel slapd[13163]: bdb_dn2entry("dc=linuxwall,dc=info")
May 24 11:55:30 samchiel slapd[13163]: search_candidates: base="dc=linuxwall,dc=info" (0x00000001) scope=2
May 24 11:55:30 samchiel slapd[13163]: => hdb_dn2idl("dc=linuxwall,dc=info")
May 24 11:55:30 samchiel slapd[13163]: => bdb_equality_candidates (objectClass)
May 24 11:55:30 samchiel slapd[13163]: => key_read
May 24 11:55:30 samchiel slapd[13163]: bdb_idl_fetch_key: [b49d1940]
May 24 11:55:30 samchiel slapd[13163]: <= bdb_index_read: failed (-30988)
May 24 11:55:30 samchiel slapd[13163]: <= bdb_equality_candidates: id=0, first=0, last=0
May 24 11:55:30 samchiel slapd[13163]: => bdb_equality_candidates (objectClass)
May 24 11:55:30 samchiel slapd[13163]: => key_read
May 24 11:55:30 samchiel slapd[13163]: bdb_idl_fetch_key: [860433ad]
May 24 11:55:30 samchiel slapd[13163]: <= bdb_index_read 4 candidates
May 24 11:55:30 samchiel slapd[13163]: <= bdb_equality_candidates: id=4, first=5, last=10
May 24 11:55:30 samchiel slapd[13163]: bdb_search_candidates: id=4 first=5 last=10
May 24 11:55:30 samchiel slapd[13163]: entry_decode: ""
May 24 11:55:30 samchiel slapd[13163]: <= entry_decode()
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: conn=3 op=2 p=3
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: err=0 matched="" text=""
May 24 11:55:30 samchiel slapd[13163]: <===slap_sasl_match: comparison returned 48
May 24 11:55:30 samchiel slapd[13163]: <==slap_sasl_check_authz: authzTo check returning 48
May 24 11:55:30 samchiel slapd[13163]: <== slap_sasl_authorized: return 48
May 24 11:55:30 samchiel slapd[13163]: <= get_ctrls: n=1 rc=123 err="not authorized to assume identity"
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: conn=3 op=2 p=3
May 24 11:55:30 samchiel slapd[13163]: send_ldap_result: err=123 matched="" text="not authorized to assume identity"
May 24 11:55:30 samchiel slapd[13163]: send_ldap_response: msgid=3 tag=120 err=123
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=2 RESULT tag=120 err=123 text=not authorized to assume identity
May 24 11:55:30 samchiel slapd[13163]: connection_get(16)
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=2 do_extended: get_ctrls failed
May 24 11:55:30 samchiel slapd[13163]: connection_get(16): got connid=3
May 24 11:55:30 samchiel slapd[13163]: connection_read(16): checking for input on id=3
May 24 11:55:30 samchiel slapd[13163]: op tag 0x42, time 1274694930
May 24 11:55:30 samchiel slapd[13163]: ber_get_next on fd 16 failed errno=0 (Success)
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=3 do_unbind
May 24 11:55:30 samchiel slapd[13163]: conn=3 op=3 UNBIND
May 24 11:55:30 samchiel slapd[13163]: connection_close: conn=3 sd=16
May 24 11:55:30 samchiel slapd[13163]: conn=3 fd=16 closed

Follow-Ups:
- Re: Proxy authorization fail with cyrus-sasl and postfix
  - From: masarati@aero.polimi.it

References:
- Proxy authorization fail with cyrus-sasl and postfix
  - From: Julien Vehent <julien@linuxwall.info>
- Re: Proxy authorization fail with cyrus-sasl and postfix
  - From: masarati@aero.polimi.it

Prev by Date: Re: More on dynamic group searches
Next by Date: Re: Proxy authorization fail with cyrus-sasl and postfix
Index(es):
- Chronological
- Thread