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