[Date Prev][Date Next] [Chronological] [Thread] [Top]
BUG? indices break depending on conf order.

To: openldap-software@OpenLDAP.org
Subject: BUG? indices break depending on conf order.
From: asr@ufl.edu
Date: Tue, 21 Jan 2003 18:38:00 -0500
I've been debugging an absolutely maddening config-file-order index problem
for some time now; Today it became the final obstacle to my taking the
University of Florida's new LDAP (one million people and counting) into
production.  

Here are the symptoms:

# Indices to maintain
#s
index           objectclass             pres,eq
#s
index           uuid                    pres,eq
#s
index           uuid2                   pres,eq
#s
index		uid			pres,eq,sub
#f
index		universityID		pres,eq
#f
index		universityID2		pres,eq
#f
index           cn                      pres,eq,sub
#f
index		mail			pres,eq,sub
#f
index		givenName		pres,eq,sub
#s
index		sn			pres,eq,sub
#s
index		privacy			pres,eq
#s
index		uflEduDn1		pres,eq
#s
index		uflEduDn2		pres,eq
#s
index		dnComponent		pres,eq
#s
index		uidNumber		pres,eq   
#


If the index on uidNumber was placed adjacent to one of the '#f' comments,
then the slapd process would not use indices for many searches, including at
least 'uid', 'universityID', 'uidNumber'.  

If the index on uidNumber was placed adjacent to one of the '#s' comments,
then the slapd process would return as expected (i.e. nearly instantaneously)
for those same searches, repeatably, over several reloads of the database.

I've included log snippets below that cover the interesting period, from a
statement of the base and filter, to the point at which the query's been
indexed down to one candidate, or when the server starts looking through
objects one at a time. :)

In the failing case, the traces deviate when LDAP_INAPPROPRIATE_MATCHING is
returned when the server attempts to open (I presume) objectClass.dbb.  But
the masks reported in the configuration debug are reported identically.  



Any suggestions on where to go code-diving would be quite welcome.


I'm just about ready to add some debug lines to e.g. compare masks and such;
but I'm going to sleep on it first.



Successful debug log

Jan 21 17:46:35 dir4en0 slapd[598196]: conn=0 op=1 SRCH base="ou=People,dc=ufl,dc=edu" scope=2 filter="(uid=asr)"
Jan 21 17:46:35 dir4en0 slapd[598196]: => ldbm_back_search
Jan 21 17:46:35 dir4en0 slapd[598196]: dn2entry_r: dn: "ou=people,dc=ufl,dc=edu"
Jan 21 17:46:35 dir4en0 slapd[598196]: => dn2id( "ou=people,dc=ufl,dc=edu" )
Jan 21 17:46:35 dir4en0 slapd[598196]: => ldbm_cache_open( "dn2id.dbb", 9, 600 )
Jan 21 17:46:35 dir4en0 slapd[598196]: <= ldbm_cache_open (opened 0)
Jan 21 17:46:35 dir4en0 slapd[598196]: <= dn2id 3
Jan 21 17:46:35 dir4en0 slapd[598196]: => id2entry_r( 3 )
Jan 21 17:46:35 dir4en0 slapd[598196]: => ldbm_cache_open( "id2entry.dbb", 9, 600 )
Jan 21 17:46:35 dir4en0 slapd[598196]: <= ldbm_cache_open (opened 1)
Jan 21 17:46:35 dir4en0 slapd[598196]: => str2entry
Jan 21 17:46:35 dir4en0 slapd[598196]: >>> dnPrettyNormal: <ou=People,dc=ufl,dc=edu>
Jan 21 17:46:35 dir4en0 slapd[598196]: <<< dnPrettyNormal: <ou=People,dc=ufl,dc=edu>, <ou=people,dc=ufl,dc=edu>
Jan 21 17:46:35 dir4en0 slapd[598196]: <= str2entry(ou=People,dc=ufl,dc=edu) -> 0x2512e3d8
Jan 21 17:46:35 dir4en0 slapd[598196]: <= id2entry_r( 3 ) 0x2512e3d8 (disk)
Jan 21 17:46:35 dir4en0 slapd[598196]: search_candidates: base="ou=people,dc=ufl,dc=edu" s=2 d=0
Jan 21 17:46:35 dir4en0 slapd[598196]: => filter_candidates
Jan 21 17:46:35 dir4en0 slapd[598196]:  AND
Jan 21 17:46:35 dir4en0 slapd[598196]: => list_candidates 0xa0
Jan 21 17:46:35 dir4en0 slapd[598196]: => filter_candidates
Jan 21 17:46:35 dir4en0 slapd[598196]:  DN SUBTREE
Jan 21 17:46:35 dir4en0 slapd[598196]: => dn2idl( "@ou=people,dc=ufl,dc=edu" )
Jan 21 17:46:35 dir4en0 slapd[598196]: => ldbm_cache_open( "dn2id.dbb", 9, 600 )
Jan 21 17:46:35 dir4en0 slapd[598196]: <= ldbm_cache_open (cache 0)
Jan 21 17:46:35 dir4en0 slapd[598196]: => ldbm_cache_open( "nextid.dbb", 9, 600 )
Jan 21 17:46:35 dir4en0 slapd[598196]: <= ldbm_cache_open (opened 2)
Jan 21 17:46:35 dir4en0 slapd[598196]: <= filter_candidates 1141267
Jan 21 17:46:35 dir4en0 slapd[598196]: => filter_candidates
Jan 21 17:46:35 dir4en0 slapd[598196]:  OR
Jan 21 17:46:35 dir4en0 slapd[598196]: => list_candidates 0xa1
Jan 21 17:46:35 dir4en0 slapd[598196]: => filter_candidates
Jan 21 17:46:35 dir4en0 slapd[598196]:  EQUALITY
Jan 21 17:46:35 dir4en0 slapd[598196]: => equality_candidates
Jan 21 17:46:35 dir4en0 slapd[598196]: => ldbm_cache_open( "objectClass.dbb", 9, 600 )
Jan 21 17:46:35 dir4en0 slapd[598196]: <= ldbm_cache_open (opened 3)
Jan 21 17:46:35 dir4en0 slapd[598196]: => key_read
Jan 21 17:46:35 dir4en0 slapd[598196]: <= index_read 0 candidates
Jan 21 17:46:35 dir4en0 slapd[598196]: <= equality_candidates NULL
Jan 21 17:46:35 dir4en0 slapd[598196]: <= equality_candidates 0
Jan 21 17:46:35 dir4en0 slapd[598196]: <= filter_candidates 0
Jan 21 17:46:35 dir4en0 slapd[598196]: => filter_candidates
Jan 21 17:46:35 dir4en0 slapd[598196]:  EQUALITY
Jan 21 17:46:35 dir4en0 slapd[598196]: => equality_candidates
Jan 21 17:46:35 dir4en0 slapd[598196]: => ldbm_cache_open( "uid.dbb", 9, 600 )
Jan 21 17:46:35 dir4en0 slapd[598196]: <= ldbm_cache_open (opened 4)
Jan 21 17:46:35 dir4en0 slapd[598196]: => key_read
Jan 21 17:46:35 dir4en0 slapd[598196]: <= index_read 1 candidates
Jan 21 17:46:35 dir4en0 slapd[598196]: <= equality_candidates 1
Jan 21 17:46:35 dir4en0 slapd[598196]: <= filter_candidates 1
Jan 21 17:46:35 dir4en0 slapd[598196]: <= list_candidates 1
Jan 21 17:46:35 dir4en0 slapd[598196]: <= filter_candidates 1
Jan 21 17:46:35 dir4en0 slapd[598196]: <= list_candidates 1
Jan 21 17:46:35 dir4en0 slapd[598196]: <= filter_candidates 1
Jan 21 17:46:35 dir4en0 slapd[598196]: ====> cache_return_entry_r( 3 ): created (0)

Failing debug log

Jan 21 17:46:58 dir4en0 slapd[614494]: conn=0 op=1 SRCH base="ou=People,dc=ufl,dc=edu" scope=2 filter="(uid=asr)"
Jan 21 17:46:58 dir4en0 slapd[614494]: => ldbm_back_search
Jan 21 17:46:58 dir4en0 slapd[614494]: dn2entry_r: dn: "ou=people,dc=ufl,dc=edu"
Jan 21 17:46:58 dir4en0 slapd[614494]: => dn2id( "ou=people,dc=ufl,dc=edu" )
Jan 21 17:46:58 dir4en0 slapd[614494]: => ldbm_cache_open( "dn2id.dbb", 9, 600 )
Jan 21 17:46:58 dir4en0 slapd[614494]: <= ldbm_cache_open (opened 0)
Jan 21 17:46:58 dir4en0 slapd[614494]: <= dn2id 3
Jan 21 17:46:58 dir4en0 slapd[614494]: => id2entry_r( 3 )
Jan 21 17:46:58 dir4en0 slapd[614494]: => ldbm_cache_open( "id2entry.dbb", 9, 600 )
Jan 21 17:46:58 dir4en0 slapd[614494]: <= ldbm_cache_open (opened 1)
Jan 21 17:46:58 dir4en0 slapd[614494]: => str2entry
Jan 21 17:46:58 dir4en0 slapd[614494]: >>> dnPrettyNormal: <ou=People,dc=ufl,dc=edu>
Jan 21 17:46:58 dir4en0 slapd[614494]: <<< dnPrettyNormal: <ou=People,dc=ufl,dc=edu>, <ou=people,dc=ufl,dc=edu>
Jan 21 17:46:58 dir4en0 slapd[614494]: <= str2entry(ou=People,dc=ufl,dc=edu) -> 0x2512e3d8
Jan 21 17:46:58 dir4en0 slapd[614494]: <= id2entry_r( 3 ) 0x2512e3d8 (disk)
Jan 21 17:46:58 dir4en0 slapd[614494]: search_candidates: base="ou=people,dc=ufl,dc=edu" s=2 d=0
Jan 21 17:46:58 dir4en0 slapd[614494]: => filter_candidates
Jan 21 17:46:58 dir4en0 slapd[614494]:  AND
Jan 21 17:46:58 dir4en0 slapd[614494]: => list_candidates 0xa0
Jan 21 17:46:58 dir4en0 slapd[614494]: => filter_candidates
Jan 21 17:46:58 dir4en0 slapd[614494]:  DN SUBTREE
Jan 21 17:46:58 dir4en0 slapd[614494]: => dn2idl( "@ou=people,dc=ufl,dc=edu" )
Jan 21 17:46:58 dir4en0 slapd[614494]: => ldbm_cache_open( "dn2id.dbb", 9, 600 )
Jan 21 17:46:58 dir4en0 slapd[614494]: <= ldbm_cache_open (cache 0)
Jan 21 17:46:58 dir4en0 slapd[614494]: => ldbm_cache_open( "nextid.dbb", 9, 600 )
Jan 21 17:46:58 dir4en0 slapd[614494]: <= ldbm_cache_open (opened 2)
Jan 21 17:46:58 dir4en0 slapd[614494]: <= filter_candidates 1141267
Jan 21 17:46:58 dir4en0 slapd[614494]: => filter_candidates
Jan 21 17:46:58 dir4en0 slapd[614494]:  OR
Jan 21 17:46:58 dir4en0 slapd[614494]: => list_candidates 0xa1
Jan 21 17:46:58 dir4en0 slapd[614494]: => filter_candidates
Jan 21 17:46:58 dir4en0 slapd[614494]:  EQUALITY
Jan 21 17:46:58 dir4en0 slapd[614494]: => equality_candidates
Jan 21 17:46:58 dir4en0 slapd[614494]: <= equality_candidates: index_param returned=18
Jan 21 17:46:58 dir4en0 slapd[614494]: <= filter_candidates 1141267
Jan 21 17:46:58 dir4en0 slapd[614494]: => filter_candidates
Jan 21 17:46:58 dir4en0 slapd[614494]:  EQUALITY
Jan 21 17:46:58 dir4en0 slapd[614494]: => equality_candidates
Jan 21 17:46:58 dir4en0 slapd[614494]: => ldbm_cache_open( "uid.dbb", 9, 600 )
Jan 21 17:46:58 dir4en0 slapd[614494]: <= ldbm_cache_open (opened 3)
Jan 21 17:46:58 dir4en0 slapd[614494]: => key_read
Jan 21 17:46:58 dir4en0 slapd[614494]: <= index_read 1 candidates
Jan 21 17:46:58 dir4en0 slapd[614494]: <= equality_candidates 1
Jan 21 17:46:58 dir4en0 slapd[614494]: <= filter_candidates 1
Jan 21 17:46:58 dir4en0 slapd[614494]: <= list_candidates 1141267
Jan 21 17:46:58 dir4en0 slapd[614494]: <= filter_candidates 1141267
Jan 21 17:46:58 dir4en0 slapd[614494]: <= list_candidates 1141267
Jan 21 17:46:58 dir4en0 slapd[614494]: <= filter_candidates 1141267
Jan 21 17:46:58 dir4en0 slapd[614494]: ====> cache_return_entry_r( 3 ): created (0)
Prev by Date: Re: Problems upgrading from 2.0.x to 2.1.x
Next by Date: Re: SSL problems with some clients
Index(es):
- Chronological
- Thread