On Sun, 23 May 2010 18:35:21 +0200 (CEST), [email protected] 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 [email protected]
Therefore,slapd looks for a user that has [email protected] 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:[email protected]"
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: conn 3
id=u:[email protected] [len=23]
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: u:id converted to
[email protected],cn=DIGEST-MD5,cn=auth
May 24 11:55:30 samchiel slapd[13163]: >>> dnNormalize:
<[email protected],cn=DIGEST-MD5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: <<< dnNormalize:
<[email protected],cn=digest-md5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: ==>slap_sasl2dn: converting SASL
name [email protected],cn=digest-md5,cn=auth to a DN
May 24 11:55:30 samchiel slapd[13163]: [rw] authid:
"[email protected],cn=digest-md5,cn=auth" ->
"ldap:///dc=linuxwall,dc=info??sub([email protected])"
May 24 11:55:30 samchiel slapd[13163]: slap_parseURI: parsing
ldap:///dc=linuxwall,dc=info??sub?([email protected])
----
(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:[email protected]"
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: conn 3
id=u:[email protected] [len=23]
May 24 11:55:30 samchiel slapd[13163]: slap_sasl_getdn: u:id converted to
[email protected],cn=DIGEST-MD5,cn=auth
May 24 11:55:30 samchiel slapd[13163]: >>> dnNormalize:
<[email protected],cn=DIGEST-MD5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: <<< dnNormalize:
<[email protected],cn=digest-md5,cn=auth>
May 24 11:55:30 samchiel slapd[13163]: ==>slap_sasl2dn: converting SASL name
[email protected],cn=digest-md5,cn=auth to a DN
May 24 11:55:30 samchiel slapd[13163]: [rw] authid:
"[email protected],cn=digest-md5,cn=auth" ->
"ldap:///dc=linuxwall,dc=info??sub?([email protected])"
May 24 11:55:30 samchiel slapd[13163]: slap_parseURI: parsing
ldap:///dc=linuxwall,dc=info??sub?([email protected])
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
"[email protected],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
[email protected],cn=digest-md5,cn=auth?
May 24 11:55:30 samchiel slapd[13163]: ==>slap_sasl_check_authz: does
[email protected],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
[email protected],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
