Re: (ITS#5221) cache? of parent failes for hdb

[Dan.Oscarsson@tietoenator.com]

mån 2007-11-12 klockan 23:17 +0000 skrev quanah@zimbra.com:
> --On Monday, November 12, 2007 7:02 AM +0000 hyc@symas.com wrote:
> 
> > Dan.Oscarsson@tietoenator.com wrote:
> >> Full_Name: Dan Oscarsson
> >> Version: 2.3.32
> >> OS: SLES 10
> >> URL: ftp://ftp.openldap.org/incoming/
> >> Submission from: (NULL) (193.15.240.60)
> >
> Also, Just some general data on what it is you are doing that is a bit more 
> explanative.  For example, what does your tree layout look like?  A single 
> root with 20,000+ subtrees off of the root?  A root with 10 subtrees, with 
> thousands of subtrees off of those?  How are you doing these modrdn's? 
> Why, exactly?  Anything that can help us to possibly come up with a 
> progamatic generation of dummy data.

The tree is based on a company organisation structure, branching at each
organisational level util you get to a person. So the root has only a
few subtrees, and each subtree only a few (say 1-30) subtrees. Most
entries will probably a subtree for a unit with the persons beloning to
that unit. People will always be leafs but an entry may contain both
people and subtrees as children.

I have triggered the bug when doing major reorganisation of people. Then
very many of the people are moved around to a new place in the tree.
Many to newly created subtrees.

I have now used 2.3.38 compiled myself so I can add tracing to the code
if needed. Running a move of people, with logging set to any,
and then running my simple check program, the search at a subtree that
goes wrong (entries are missing) is logged as:
filter: (&(objectClass=enterprisePerson)(ba=telecom & media)(bu=telecom
solutions))
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: search_candidates: base=\"bu=telecom solutions,ba=telecom & media,cn=organisation,o=xx\" (0x0000513a) scope=2
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => hdb_dn2idl(\"bu=telecom solutions,ba=telecom & media,cn=organisation,o=xx\")
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_filter_candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]:     AND
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_list_candidates 0xa0
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_filter_candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]:     OR
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_list_candidates 0xa1
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_filter_candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]:     EQUALITY
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_equality_candidates (objectClass)
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => key_read
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: bdb_idl_fetch_key: [b49d1940]
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_index_read: failed (-30989)
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_equality_candidates: id=0, first=0, last=0
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_filter_candidates: id=0 first=0 last=0
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_filter_candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]:     AND
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_list_candidates 0xa0
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_filter_candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]:     EQUALITY
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_equality_candidates (objectClass)
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => key_read
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: bdb_idl_fetch_key: [a98323a6]
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_index_read 20569 candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_equality_candidates: id=20569, first=1483, last=26650
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_filter_candidates: id=20569 first=1483 last=26650
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_filter_candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]:     EQUALITY
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_equality_candidates (ba)
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => key_read
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: bdb_idl_fetch_key: [410ca247]
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_index_read 6991 candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_equality_candidates: id=6991, first=15620, last=26644
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_filter_candidates: id=6991 first=15620 last=26644
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_filter_candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]:     EQUALITY
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => bdb_equality_candidates (bu)
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: => key_read
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: bdb_idl_fetch_key: [8b819570]
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_index_read 2195 candidates
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_equality_candidates: id=2195, first=30, last=26614
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_filter_candidates: id=2195 first=30 last=26614
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_list_candidates: id=2144 first=20813 last=26614
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_filter_candidates: id=2144 first=20813 last=26614
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_list_candidates: id=2144 first=20813 last=26614
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_filter_candidates: id=2144 first=20813 last=26614
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_list_candidates: id=2130 first=20813 last=26614
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: <= bdb_filter_candidates: id=2130 first=20813 last=26614
2007-11-13 15.19.05 ra [local4.debug] slapd[27292]: bdb_search_candidates: id=2130 first=20813 last=26614

Stopping and starting the server. The check now works. The above search is logged the same
except for the last part:

2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: bdb_idl_fetch_key: [8b819570]
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: <= bdb_index_read 2195 candidates
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: <= bdb_equality_candidates: id=2195, first=30, last=26614
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: <= bdb_filter_candidates: id=2195 first=30 last=26614
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: <= bdb_list_candidates: id=2144 first=20813 last=26614
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: <= bdb_filter_candidates: id=2144 first=20813 last=26614
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: <= bdb_list_candidates: id=2144 first=20813 last=26614
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: <= bdb_filter_candidates: id=2144 first=20813 last=26614
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: <= bdb_list_candidates: id=2141 first=20813 last=26614
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: <= bdb_filter_candidates: id=2141 first=20813 last=26614
2007-11-13 15.19.41 ra [local4.debug] slapd[27460]: bdb_search_candidates: id=2141 first=20813 last=26614

In both above cases, with the same filter but search base
set to o=xx witch is the database prefix, it works as it should.
In this case the entries that were missing above is found.

I do not know it this might give you some clue to what the problem is.

Any suggestions on what I should look for or any suitable place
in the code where I could add debug logging, would be nice.

The logs get very large when running with logging set to any.

   Dan

-- 
Dan Oscarsson
TietoEnator                   Email: Dan.Oscarsson@tietoenator.com
Box 85
201 20  Malmo, Sweden