Re: (ITS#6217) proxycache not returning cached data

[ryans@aweber.com]

I just uploaded two log file snippets for consideration (also posted to ITS#6831, since there has not been a formal
merge or acceptance of the two being one and the same).  One is a failed query to the proxycache database exhibiting
this problem, and the other is a successful query to the same proxycache database.  A gzipp'ed tarball can be found
here: ftp://ftp.openldap.org/incoming/ryan-steele-110221.proxycache-logs-for-comparison.tar.gz.

For reference, the queries issued and results for each were:

## Failed query
ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomUtilityUser)(objectClass=examplecomEmployee))(uid=jdoe1))' uid

## Successful query
ldapsearch -x -H ldaps://localhost -LLL -b ou=Users,dc=example,dc=com
'(&(|(objectClass=examplecomUtilityUser)(objectClass=examplecomEmployee))(uid=jdoe2))' uid
dn: uid=jdoe2,ou=Users,dc=example,dc=com
uid: jdoe2

The cache reported both to be "ANSWERABLE" before attempting to retrieve the data.


Up until the point where the unsuccessful query fails to read the key for the UID equality candidate, both the failed
query and the successful query lock the same exact QC index (0x7f50429860f0), attempt to fetch the exact same keys
([b49d1940], [807e234d], [8f951c4a]), and compare the exact same equality/filter/list candidates ("id=9, first=2699,
last=2731").  This is what I would expect, since the values for the two objectClasses in the search filter are the same.

However, once it gets to the point where it compares the bdb_equality_candidates for the UID, the values of the
bdb_filter_candidates, bdb_equality_candidates, and bdb_list_candidates in logs for the unsuccessful query are a little
confusing:

## UID portion of unsuccessful query

Feb 21 10:02:00 blog2 slapd[18797]: bdb_idl_fetch_key: [8f951c4a]
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_index_read 9 candidates
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_equality_candidates: id=9, first=2699, last=2731
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=9 first=2699 last=2731
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_list_candidates: id=9 first=2699 last=2731
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=9 first=2699 last=2731
Feb 21 10:02:00 blog2 slapd[18797]: => bdb_filter_candidates
Feb 21 10:02:00 blog2 slapd[18797]:     EQUALITY
Feb 21 10:02:00 blog2 slapd[18797]: => bdb_equality_candidates (uid)
Feb 21 10:02:00 blog2 slapd[18797]: => key_read
Feb 21 10:02:00 blog2 slapd[18797]: bdb_idl_fetch_key: [efb8b856]
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_equality_candidates: id=0, first=0, last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=0 first=0 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_list_candidates: id=0 first=2699 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=0 first=2699 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_list_candidates: id=0 first=0 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=0 first=0 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_list_candidates: id=0 first=2 last=0
Feb 21 10:02:00 blog2 slapd[18797]: <= bdb_filter_candidates: id=0 first=2 last=0
Feb 21 10:02:00 blog2 slapd[18797]: bdb_search_candidates: id=0 first=2 last=0
Feb 21 10:02:00 blog2 slapd[18797]: hdb_search: no candidates


## UID portion of successful query

Feb 21 10:06:22 blog2 slapd[18797]: bdb_idl_fetch_key: [8f951c4a]
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_index_read 9 candidates
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_equality_candidates: id=9, first=2699, last=2731
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=9 first=2699 last=2731
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_list_candidates: id=9 first=2699 last=2731
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=9 first=2699 last=2731
Feb 21 10:06:22 blog2 slapd[18797]: => bdb_filter_candidates
Feb 21 10:06:22 blog2 slapd[18797]:     EQUALITY
Feb 21 10:06:22 blog2 slapd[18797]: => bdb_equality_candidates (uid)
Feb 21 10:06:22 blog2 slapd[18797]: => key_read
Feb 21 10:06:22 blog2 slapd[18797]: bdb_idl_fetch_key: [ea38ed84]
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_index_read 1 candidates
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_equality_candidates: id=1, first=2701, last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_list_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_list_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_list_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: <= bdb_filter_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: bdb_search_candidates: id=1 first=2701 last=2701
Feb 21 10:06:22 blog2 slapd[18797]: => test_filter

I gather that a value of "0" for id/first/last is normal when it cannot find the index in question (as it does for the
UID value that it had deemed to be answerable), but the "first=2" and "first=2699" values seem a little strange,
especially since the "first=2699" value supposedly matches the bdb_equality_candidates "first" value found at one of the
indices searched for the objectClass attribute(s).  I have no idea where the value "2" comes from, but it too seems
incorrect if it couldn't find the index.  Perhaps those values make more sense in the context of it thinking it could
find the values, but then ultimately not being able to (though I admit that sounds like a pretty big stretch).


Unfortunately, I don't understand enough about what's going here, or where things might be going awry in the codebase,
to abstract something more meaningful from these logs, but hopefully this provides a little bit of framing/contextual
information to someone else that does.


Cheers