[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
Re: (ITS#6831) Proxycache database corruption
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.