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