I just uploaded two log file snippets for consideration. One is a failed query to the proxycache database exhibiting this problem, and the other is a successful query to the proxycache database. A gzipp'ed tarball can be found here: ftp://ftp.openldap.org/incoming/ryan-steele-110221.proxycache-logs-for-comparison.tar.gz. 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 are locking the same exact QC index (0x7f50429860f0), trying to fetch the exact same keys ([b49d1940], [807e234d], [8f951c4a]), and comparing the 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. 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 said was "ANSWERABLE" but was unable to find), but the "first=2" and "first=2699" values seem a little strange, especially since the "first=2699" value supposedly matches the bdb_equality_candidates value found at one of the indices for the objectClass searches. I have no idea where the value "2" comes from, but it too seems out of place if it couldn't find the index. Perhaps those values make more sense in the context where it thought it *could* find the values, but then wasn't able to (though I admit that sounds like a pretty big stretch).

## 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 unfortunately don't have enough knowledge about what's going here, or where things go 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.