[Date Prev][Date Next] [Chronological] [Thread] [Top]
Re: ACL Evaluation bug (ITS#3173)

To: openldap-its@OpenLDAP.org
Subject: Re: ACL Evaluation bug (ITS#3173)
From: quanah@stanford.edu
Date: Thu, 17 Jun 2004 06:31:41 GMT

--On Tuesday, June 08, 2004 4:32 PM -0700 "Kurt D. Zeilenga" 
<Kurt@OpenLDAP.org> wrote:

> Could this simply be due to the separator between 5 and 6
> in the RegistryDataAuditor by clause?

This continues in OL 2.2.13, with my ACL's set either way.

At least now I have debugging output.

My current theory is:

I perform WRITE op to OL master
syncRepl begins
DB gets locked, so ACL evaluation locks
everything gets hung.

Notes:
ldap-dev0 = master
ldap-dev2 = replica
ldap-dev3 = replica

Both replica's are started, both in synch with master.
ADD is initiated

debug -1 output:

conn=2 op=4 ADD dn="cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu"
bdb_dn2entry("cn=proxy5,cn=webauth,cn=applications,dc=stanford,dc=edu")
=> bdb_dn2id( "cn=applications,dc=stanford,dc=edu" )
<= bdb_dn2id: got id=0x00000004
=> bdb_dn2id( "cn=webauth,cn=applications,dc=stanford,dc=edu" )
<= bdb_dn2id: got id=0x00045518
=> bdb_dn2id( "cn=proxy5,cn=webauth,cn=applications,dc=stanford,dc=edu" )
<= bdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found 
(-30990)
entry_decode: "cn=Webauth,cn=Applications,dc=stanford,dc=edu"
<= entry_decode(cn=Webauth,cn=Applications,dc=stanford,dc=edu)
bdb_referrals: op=104 
target="cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu" 
matched="cn=W
ebauth,cn=Applications,dc=stanford,dc=edu"
>>> dnPretty: 
<suRegID=cd67ebdae76c11d1b7532436000baa77,cn=People,dc=stanford,dc=edu>
=> 
ldap_bv2dn(suRegID=cd67ebdae76c11d1b7532436000baa77,cn=People,dc=stanford,dc=edu,0)
<= 
ldap_bv2dn(suRegID=cd67ebdae76c11d1b7532436000baa77,cn=People,dc=stanford,dc=edu,0)=0
=> ldap_dn2bv(272)
<= 
ldap_dn2bv(suRegID=cd67ebdae76c11d1b7532436000baa77,cn=People,dc=stanford,dc=edu,272)=0
<<< dnPretty: 
<suRegID=cd67ebdae76c11d1b7532436000baa77,cn=People,dc=stanford,dc=edu>
>>> dnNormalize: 
<suRegID=cd67ebdae76c11d1b7532436000baa77,cn=People,dc=stanford,dc=edu>
=> 
ldap_bv2dn(suRegID=cd67ebdae76c11d1b7532436000baa77,cn=People,dc=stanford,dc=edu,0)
<= 
ldap_bv2dn(suRegID=cd67ebdae76c11d1b7532436000baa77,cn=People,dc=stanford,dc=edu,0)=0
=> ldap_dn2bv(272)
<= 
ldap_dn2bv(suRegID=cd67ebdae76c11d1b7532436000baa77,cn=people,dc=stanford,dc=edu,272)=0
<<< dnNormalize: 
<suRegID=cd67ebdae76c11d1b7532436000baa77,cn=people,dc=stanford,dc=edu>
==> bdb_add: cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu
oc_check_required entry 
(cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu), objectClass "appl
icationProcess"
oc_check_required entry 
(cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu), objectClass "suAp
plication"
oc_check_required entry 
(cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu), objectClass "krb5
Principal"
oc_check_allowed type "objectClass"
oc_check_allowed type "cn"
oc_check_allowed type "description"
oc_check_allowed type "krb5PrincipalName"
oc_check_allowed type "owner"
oc_check_allowed type "suAdministrator"
oc_check_allowed type "structuralObjectClass"
oc_check_allowed type "entryUUID"
oc_check_allowed type "creatorsName"
oc_check_allowed type "createTimestamp"
oc_check_allowed type "entryCSN"
oc_check_allowed type "modifiersName"
oc_check_allowed type "modifyTimestamp"
bdb_dn2entry("cn=proxy5,cn=webauth,cn=applications,dc=stanford,dc=edu")
=> bdb_dn2id( "cn=proxy5,cn=webauth,cn=applications,dc=stanford,dc=edu" )
<= bdb_dn2id: get failed: DB_NOTFOUND: No matching key/data pair found 
(-30990)
=> access_allowed: write access to 
"cn=Webauth,cn=Applications,dc=stanford,dc=edu" "children" reques
ted
=> dn: [1]
=> dn: [2] cn=monitor
=> acl_get: [3] attr children
=> acl_mask: access to entry 
"cn=Webauth,cn=Applications,dc=stanford,dc=edu", attr "children" reques
ted
=> acl_mask: to all values by "uid=quanah,cn=accounts,dc=stanford,dc=edu", 
(=n)
<= check a_dn_pat: 
cn=replicator,cn=service,cn=applications,dc=stanford,dc=edu
=> bdb_entry_get: ndn: "cn=supervisor,cn=applications,dc=stanford,dc=edu"
=> bdb_entry_get: oc: "groupOfNames", at: "member"
bdb_dn2entry("cn=supervisor,cn=applications,dc=stanford,dc=edu")
=> bdb_dn2id( "cn=supervisor,cn=applications,dc=stanford,dc=edu" )
<= bdb_dn2id: got id=0x00000005
entry_decode: "cn=supervisor,cn=Applications,dc=stanford,dc=edu"
<= entry_decode(cn=supervisor,cn=Applications,dc=stanford,dc=edu)
=> bdb_entry_get: found entry: 
"cn=supervisor,cn=applications,dc=stanford,dc=edu"
bdb_entry_get: rc=0
dnMatch 1
        "uid=chandau,cn=accounts,dc=stanford,dc=edu"
        "uid=quanah,cn=accounts,dc=stanford,dc=edu"
dnMatch 0
        "uid=quanah,cn=accounts,dc=stanford,dc=edu"
        "uid=quanah,cn=accounts,dc=stanford,dc=edu"
<= check a_authz.sai_sasl_ssf: ACL 56 > OP 56
<= acl_mask: [2] applying write(=wrscx) (stop)
<= acl_mask: [2] mask: write(=wrscx)
=> access_allowed: write access granted by write(=wrscx)
=> access_allowed: write access to 
"cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu" "entry"
 requested
=> dn: [1]
=> dn: [2] cn=monitor
=> acl_get: [3] attr entry
=> acl_mask: access to entry 
"cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu", attr "entry"
 requested
=> acl_mask: to all values by "uid=quanah,cn=accounts,dc=stanford,dc=edu", 
(=n)
<= check a_dn_pat: 
cn=replicator,cn=service,cn=applications,dc=stanford,dc=edu
<= check a_authz.sai_sasl_ssf: ACL 56 > OP 56
<= acl_mask: [2] applying write(=wrscx) (stop)
<= acl_mask: [2] mask: write(=wrscx)
=> access_allowed: write access granted by write(=wrscx)
=> bdb_dn2id_add( 
"cn=proxy5,cn=webauth,cn=applications,dc=stanford,dc=edu", 0x0004efb1 )
bdb_idl_insert_key: 4efb1 %cn=webauth,cn=applications,dc=stanford,dc=edu
bdb_idl_insert_key: 4efb1 @cn=webauth,cn=applications,dc=stanford,dc=edu
bdb_idl_insert_key: 4efb1 @cn=applications,dc=stanford,dc=edu
<= bdb_dn2id_add: 0
=> entry_encode(0x0004efb1): 
cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu
=> index_entry_add( 323505, 
"cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu" )
=> key_change(ADD,4efb1)
bdb_idl_insert_key: 4efb1 [0283e35a]
<= key_change 0
=> key_change(ADD,4efb1)
bdb_idl_insert_key: 4efb1 [0b9cc936]
<= key_change 0
=> key_change(ADD,4efb1)
bdb_idl_insert_key: 4efb1 [43f33743]
<= key_change 0
=> key_change(ADD,4efb1)
bdb_idl_insert_key: 4efb1 [0096defd]
<= key_change 0
=> key_change(ADD,4efb1)
bdb_idl_insert_key: 4efb1 [2543ee9e]
<= key_change 0
=> key_change(ADD,4efb1)
bdb_idl_insert_key: 4efb1 [5d735fab]
<= key_change 0
<= index_entry_add( 323505, 
"cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu" ) success
bdb_dn2entry("cn=ldapsync,dc=stanford,dc=edu")
bdb_modify_internal: 0x0004efb0: cn=ldapsync,dc=stanford,dc=edu
acl: no-user-mod contextCSN: modify access granted
bdb_modify_internal: replace
oc_check_required entry (cn=ldapsync,dc=stanford,dc=edu), objectClass 
"subentry"
oc_check_required entry (cn=ldapsync,dc=stanford,dc=edu), objectClass 
"syncProviderSubentry"
oc_check_allowed type "objectClass"
oc_check_allowed type "structuralObjectClass"
oc_check_allowed type "cn"
oc_check_allowed type "subtreeSpecification"
oc_check_allowed type "contextCSN"
=> entry_encode(0x0004efb0): cn=ldapsync,dc=stanford,dc=edu
=> bdb_search
bdb_dn2entry("dc=stanford,dc=edu")
search_candidates: base="dc=stanford,dc=edu" (0x00000001) scope=2
=> bdb_dn2idl( "dc=stanford,dc=edu" )
=> bdb_filter_candidates
        AND
=> bdb_list_candidates 0xa0
=> bdb_filter_candidates
        PRESENT
=> bdb_presence_candidates (objectClass)
<= bdb_filter_candidates: id=-1 first=1 last=323505
<= bdb_list_candidates: id=-1 first=1 last=323505
<= bdb_filter_candidates: id=-1 first=1 last=323505
bdb_search_candidates: id=-1 first=1 last=323505
=> test_filter
    AND
=> test_filter_and
=> test_filter
    NOT
=> test_filter
    EQUALITY
=> access_allowed: search access to 
"cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu" "entry
CSN" requested
=> dn: [1]
=> dn: [2] cn=monitor
=> acl_get: [3] attr entryCSN
=> acl_mask: access to entry 
"cn=proxy5,cn=Webauth,cn=applications,dc=stanford,dc=edu", attr "entryC
SN" requested
=> acl_mask: to value by 
"cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu", (=n)
<= check a_dn_pat: 
cn=replicator,cn=service,cn=applications,dc=stanford,dc=edu
=> bdb_entry_get: ndn: "cn=supervisor,cn=applications,dc=stanford,dc=edu"
=> bdb_entry_get: oc: "groupOfNames", at: "member"
bdb_dn2entry("cn=supervisor,cn=applications,dc=stanford,dc=edu")
=> bdb_entry_get: found entry: 
"cn=supervisor,cn=applications,dc=stanford,dc=edu"
bdb_entry_get: rc=0
dnMatch -12
        "uid=chandau,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -13
        "uid=quanah,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -13
        "uid=wjones,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -12
        "uid=caseyd1,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -15
        "uid=mpmw,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -16
        "uid=rra,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -15
        "uid=torg,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -11
        "uid=svuyyuru,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -14
        "uid=hallk,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -11
        "uid=jonpilat,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
=> bdb_entry_get: ndn: "cn=ldapadmin,cn=applications,dc=stanford,dc=edu"
=> bdb_entry_get: oc: "groupOfNames", at: "member"
bdb_dn2entry("cn=ldapadmin,cn=applications,dc=stanford,dc=edu")
=> bdb_dn2id( "cn=ldapadmin,cn=applications,dc=stanford,dc=edu" )
<= bdb_dn2id: got id=0x00000006
entry_decode: "cn=ldapAdmin,cn=Applications,dc=stanford,dc=edu"
<= entry_decode(cn=ldapAdmin,cn=Applications,dc=stanford,dc=edu)
=> bdb_entry_get: found entry: 
"cn=ldapadmin,cn=applications,dc=stanford,dc=edu"
bdb_entry_get: rc=0
dnMatch -12
        "uid=chandau,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -13
        "uid=quanah,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -12
        "uid=phoenix,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -13
        "uid=wjones,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -15
        "uid=mpmw,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -15
        "uid=torg,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -11
        "uid=morpheus,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -16
        "uid=rra,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -11
        "uid=jonpilat,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -13
        "uid=antonu,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -12
        "uid=jlucker,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -14
        "uid=sfeng,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -14
        "uid=hallk,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -12
        "uid=meeilee,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -12
        "uid=cjurney,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -13
        "uid=riepel,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch 3
        "cn=regadmin,cn=service,cn=applications,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -11
        "uid=svuyyuru,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -12
        "uid=priimak,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -12
        "uid=dbender,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
dnMatch -13
        "uid=molive,cn=accounts,dc=stanford,dc=edu"
        "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
=> bdb_entry_get: ndn: "cn=ldapreplica,cn=applications,dc=stanford,dc=edu"
=> bdb_entry_get: oc: "groupOfNames", at: "member"
bdb_dn2entry("cn=ldapreplica,cn=applications,dc=stanford,dc=edu")
=> bdb_dn2id( "cn=ldapreplica,cn=applications,dc=stanford,dc=edu" )
<= bdb_dn2id: got id=0x0004efae


At this point, it hangs, with the occasional:

daemon: select timeout - yielding
daemon: select: listen=6 active_threads=1 tvp=zero
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: select timeout - yielding
daemon: select: listen=6 active_threads=1 tvp=zero
daemon: select: listen=7 active_threads=1 tvp=zero
daemon: select timeout - yielding
daemon: select: listen=6 active_threads=1 tvp=zero
daemon: select: listen=7 active_threads=1 tvp=zero

messages.

ACL's:

# $Id: slapd.acl.master,v 1.27 2004/02/27 07:25:17 quanah Exp $
# ACL include file for slapd
#
# this is specific to the master

access to dn.base=""
        by * read

access to dn.subtree="cn=monitor"
        by * read

access to *
        by 
dn.base="cn=replicator,cn=service,cn=Applications,dc=stanford,dc=edu" 
sasl_ssf=56 write
        by group.base="cn=Supervisor,cn=Applications,dc=stanford,dc=edu" 
sasl_ssf=56 write
        by group.base="cn=ldapAdmin,cn=Applications,dc=stanford,dc=edu" 
sasl_ssf=56 read
        by group.base="cn=ldapReplica,cn=Applications,dc=stanford,dc=edu" 
sasl_ssf=56 read
        by 
dn.base="cn=RegistryDataAuditor,cn=service,cn=Applications,dc=stanford,dc=edu" 
sasl_ssf=56 read
        by * break


ldapreplica group:

ldapsearch -h ldap-dev0 cn=ldapreplicator
SASL/GSSAPI authentication started
SASL username: quanah@stanford.edu
SASL SSF: 56
SASL installing layers
# extended LDIF
#
# LDAPv3
# base <> with scope sub
# filter: cn=ldapreplicator
# requesting: ALL
#

# search result
search: 5
result: 0 Success

# numResponses: 1
ldap-dev0:~> ldapsearch -h ldap-dev0 cn=ldapreplica
SASL/GSSAPI authentication started
SASL username: quanah@stanford.edu
SASL SSF: 56
SASL installing layers
# extended LDIF
#
# LDAPv3
# base <> with scope sub
# filter: cn=ldapreplica
# requesting: ALL
#

# ldapReplica, Applications, stanford.edu
dn: cn=ldapReplica,cn=Applications,dc=stanford,dc=edu
objectClass: groupOfNames
cn: ldapReplica
member: cn=ldap-dev1,cn=ldap,cn=operational,dc=stanford,dc=edu
member: cn=ldap-dev2,cn=ldap,cn=operational,dc=stanford,dc=edu
member: cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu

# search result
search: 5
result: 0 Success

# numResponses: 2
# numEntries: 1


Note: It's bind ID is definitely 
cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu:


>>> dnPrettyNormal: <cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu>
=> ldap_bv2dn(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,0)
<= ldap_bv2dn(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,0)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,272)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,272)=0
<<< dnPrettyNormal: 
<cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu>, 
<cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu>
do_sasl_bind: dn (cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu) 
mech GSSAPI
conn=1 op=0 BIND 
dn="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" method=163
==> sasl_bind: dn="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" 
mech=GSSAPI datalen=535
connection_get(13)
connection_get(13): got connid=1
connection_read(13): checking for input on id=1
>>> dnPrettyNormal: <cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu>
=> ldap_bv2dn(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,0)
<= ldap_bv2dn(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,0)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,272)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,272)=0
<<< dnPrettyNormal: 
<cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu>, 
<cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu>
do_sasl_bind: dn (cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu) 
mech GSSAPI
conn=1 op=1 BIND 
dn="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" method=163
==> sasl_bind: dn="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" 
mech=<continuing> datalen=0
>>> dnPrettyNormal: <cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu>
=> ldap_bv2dn(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,0)
<= ldap_bv2dn(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,0)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,272)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu,272)=0
<<< dnPrettyNormal: 
<cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu>, 
<cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu>
do_sasl_bind: dn (cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu) 
mech GSSAPI
conn=1 op=2 BIND 
dn="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" method=163
==> sasl_bind: dn="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" 
mech=<continuing> datalen=53
SASL Canonicalize [conn=1]: authcid="ldap/ldap-dev3.stanford.edu"
slap_sasl_getdn: id=ldap/ldap-dev3.stanford.edu [len=27]
slap_sasl_getdn: u:id converted to 
uid=ldap/ldap-dev3.stanford.edu,cn=stanford.edu,cn=GSSAPI,cn=auth
>>> dnNormalize: 
<uid=ldap/ldap-dev3.stanford.edu,cn=stanford.edu,cn=GSSAPI,cn=auth>
=> 
ldap_bv2dn(uid=ldap/ldap-dev3.stanford.edu,cn=stanford.edu,cn=GSSAPI,cn=auth,0)
<= 
ldap_bv2dn(uid=ldap/ldap-dev3.stanford.edu,cn=stanford.edu,cn=GSSAPI,cn=auth,0)=0
=> ldap_dn2bv(272)
<= 
ldap_dn2bv(uid=ldap/ldap-dev3.stanford.edu,cn=stanford.edu,cn=gssapi,cn=auth,272)=0
<<< dnNormalize: 
<uid=ldap/ldap-dev3.stanford.edu,cn=stanford.edu,cn=gssapi,cn=auth>
==>slap_sasl2dn: converting SASL name 
uid=ldap/ldap-dev3.stanford.edu,cn=stanford.edu,cn=gssapi,cn=auth to a DN
slap_sasl_regexp: converting SASL name 
uid=ldap/ldap-dev3.stanford.edu,cn=stanford.edu,cn=gssapi,cn=auth
slap_sasl_regexp: converted SASL name to 
ldaps:///cn=ldap,cn=Operational,dc=stanford,dc=edu??sub?krb5PrincipalName=ldap/ldap-dev3.stanford.edu@stanford.edu
slap_parseURI: parsing 
ldaps:///cn=ldap,cn=Operational,dc=stanford,dc=edu??sub?krb5PrincipalName=ldap/ldap-dev3.stanford.edu@stanford.edu
ldap_url_parse_ext(ldaps:///cn=ldap,cn=Operational,dc=stanford,dc=edu??sub?krb5PrincipalName=ldap/ldap-dev3.stanford.edu@stanford.edu)
str2filter "krb5PrincipalName=ldap/ldap-dev3.stanford.edu@stanford.edu"
put_filter: "krb5PrincipalName=ldap/ldap-dev3.stanford.edu@stanford.edu"
put_filter: default
put_simple_filter: 
"krb5PrincipalName=ldap/ldap-dev3.stanford.edu@stanford.edu"
begin get_filter
EQUALITY
>>> dnNormalize: <cn=ldap,cn=Operational,dc=stanford,dc=edu>
=> ldap_bv2dn(cn=ldap,cn=Operational,dc=stanford,dc=edu,0)
<= ldap_bv2dn(cn=ldap,cn=Operational,dc=stanford,dc=edu,0)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(cn=ldap,cn=operational,dc=stanford,dc=edu,272)=0
<<< dnNormalize: <cn=ldap,cn=operational,dc=stanford,dc=edu>
slap_sasl2dn: performing internal search 
(base=cn=ldap,cn=operational,dc=stanford,dc=edu, scope=2)
=> bdb_search
bdb_dn2entry("cn=ldap,cn=operational,dc=stanford,dc=edu")
search_candidates: base="cn=ldap,cn=operational,dc=stanford,dc=edu" 
(0x0004ccef) scope=2
=> bdb_dn2idl( "cn=ldap,cn=operational,dc=stanford,dc=edu" )
bdb_idl_fetch_key: @cn=ldap,cn=operational,dc=stanford,dc=edu
<= bdb_dn2idl: id=4 first=314607 last=323501
=> bdb_filter_candidates
    AND
=> bdb_list_candidates 0xa0
=> bdb_filter_candidates
    OR
=> bdb_list_candidates 0xa1
=> bdb_filter_candidates
    EQUALITY
=> bdb_equality_candidates (objectClass)
=> key_read
bdb_idl_fetch_key: [b49d1940]
<= bdb_index_read: failed (-30990)
<= bdb_equality_candidates: id=0, first=0, last=0
<= bdb_filter_candidates: id=0 first=0 last=0
=> bdb_filter_candidates
    EQUALITY
=> bdb_equality_candidates (krb5PrincipalName)
=> key_read
bdb_idl_fetch_key: [4121fd40]
<= bdb_index_read 1 candidates
<= bdb_equality_candidates: id=1, first=323501, last=323501
<= bdb_filter_candidates: id=1 first=323501 last=323501
<= bdb_list_candidates: id=1 first=323501 last=323501
<= bdb_filter_candidates: id=1 first=323501 last=323501
<= bdb_list_candidates: id=1 first=323501 last=323501
<= bdb_filter_candidates: id=1 first=323501 last=323501
bdb_search_candidates: id=1 first=323501 last=323501
entry_decode: "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
<= entry_decode(cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu)
=> bdb_dn2id( "cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" )
<= bdb_dn2id: got id=0x0004efad
=> test_filter
    EQUALITY
=> access_allowed: auth access to 
"cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" 
"krb5PrincipalName" requested
=> dn: [1]
=> dn: [2] cn=monitor
=> acl_get: [3] attr krb5PrincipalName
=> acl_mask: access to entry 
"cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu", attr 
"krb5PrincipalName" requested
=> acl_mask: to value by "", (=n)
<= check a_dn_pat: 
cn=replicator,cn=service,cn=applications,dc=stanford,dc=edu
<= check a_dn_pat: 
cn=registrydataauditor,cn=service,cn=applications,dc=stanford,dc=edu
<= check a_dn_pat: *
<= acl_mask: [6] applying +0 (break)
<= acl_mask: [6] mask: =n
=> acl_get: [5] attr krb5PrincipalName
=> acl_mask: access to entry 
"cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu", attr 
"krb5PrincipalName" requested
=> acl_mask: to value by "", (=n)
<= check a_dn_pat: 
cn=slog-accounts,cn=service,cn=applications,dc=stanford,dc=edu
<= check a_dn_pat: 
cn=rr-accounts-rw,cn=service,cn=applications,dc=stanford,dc=edu
<= check a_dn_pat: 
cn=rr-accounts-ro,cn=service,cn=applications,dc=stanford,dc=edu
<= check a_dn_pat: *
<= acl_mask: [4] applying search(=scx) (stop)
<= acl_mask: [4] mask: search(=scx)
=> access_allowed: auth access granted by search(=scx)
<= test_filter 6
send_ldap_result: conn=1 op=0 p=3
send_ldap_result: err=0 matched="" text=""
<==slap_sasl2dn: Converted SASL name to 
cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu
getdn: dn:id converted to 
cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu
SASL Canonicalize [conn=1]: 
slapAuthcDN="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
SASL proxy authorize [conn=1]: 
authcid="ldap/ldap-dev3.stanford.edu@stanford.edu" 
authzid="ldap/ldap-dev3.stanford.edu@stanford.edu"
conn=1 op=2 BIND authcid="ldap/ldap-dev3.stanford.edu@stanford.edu"
SASL Authorize [conn=1]:  proxy authorization allowed
send_ldap_sasl: err=0 len=-1
send_ldap_response: msgid=3 tag=97 err=0
ber_flush: 14 bytes to sd 13
  0000:  30 0c 02 01 03 61 07 0a  01 00 04 00 04 00         0....a........
ldap_write: want=14, written=14
  0000:  30 0c 02 01 03 61 07 0a  01 00 04 00 04 00         0....a........
<== slap_sasl_bind: rc=0
conn=1 op=2 BIND 
dn="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" mech=GSSAPI 
ssf=56
do_bind: SASL/GSSAPI bind: 
dn="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu" ssf=56
daemon: activity on 1 descriptors
daemon: activity on: 13r
daemon: read activity on 13
connection_get(13)
connection_get(13): got connid=1
connection_read(13): checking for input on id=1
ldap_pvt_sasl_install
ber_get_next
sasl_read: want=4, got=4
<= get_ctrls: n=1 rc=0 err=""
    attrs: * objectClass structuralObjectClass entryCSN
conn=1 op=3 SRCH base="dc=stanford,dc=edu" scope=2 deref=0 
filter="(objectClass=*)"
conn=1 op=3 SRCH attr=* objectClass structuralObjectClass entryCSN
==> limits_get: conn=1 op=3 
dn="cn=ldap-dev3,cn=ldap,cn=operational,dc=stanford,dc=edu"
=> bdb_search
bdb_dn2entry("dc=stanford,dc=edu")
bdb_dn2entry("cn=ldapsync,dc=stanford,dc=edu")



What I don't get, is it never iterates through the ACL's to determine if 
the bound replica has permissions to read *, objectClass, 
structuralObjectClass or entryCSN.  Or if it is, that definitely isn't 
logged (see above).

I've updated the complete log as:

3173-quanah-20040616.gz

in ftp.openldap.org/incoming

--Quanah

--
Quanah Gibson-Mount
Principal Software Developer
ITSS/Shared Services
Stanford University
GnuPG Public Key: http://www.stanford.edu/~quanah/pgp.html
Prev by Date: Re: SASL causes segmentation fault (ITS#3172)
Next by Date: Re: slapd (back-bdb) crashing during high modify load (ITS#3188)
Index(es):
- Chronological
- Thread