More logs to try to diagnose bug 7164

This time, check in microdesc_cache_clean() to see what could be
going wrong with an attempt to clean a microdesc that's held by a node.
This commit is contained in:
Nick Mathewson 2014-03-17 14:15:12 -04:00
parent cbf9e74236
commit 0389d4aa56
4 changed files with 77 additions and 1 deletions

View File

@ -0,0 +1,6 @@
o Minor features:
- Try harder to diagnose a possible cause of bug 7164, which causes
intermittent "microdesc_free() called but md was still referenced"
warnings. We now log more information about the likely error case,
to try to figure out why we might be cleaning a microdescriptor
as old if it's still referenced by a live node.

View File

@ -368,7 +368,9 @@ microdesc_cache_clean(microdesc_cache_t *cache, time_t cutoff, int force)
cutoff = now - TOLERATE_MICRODESC_AGE;
for (mdp = HT_START(microdesc_map, &cache->map); mdp != NULL; ) {
if ((*mdp)->last_listed < cutoff) {
const int is_old = (*mdp)->last_listed < cutoff;
const unsigned held_by_nodes = (*mdp)->held_by_nodes;
if (is_old && !held_by_nodes) {
++dropped;
victim = *mdp;
mdp = HT_NEXT_RMV(microdesc_map, &cache->map, mdp);
@ -376,6 +378,54 @@ microdesc_cache_clean(microdesc_cache_t *cache, time_t cutoff, int force)
bytes_dropped += victim->bodylen;
microdesc_free(victim);
} else {
if (is_old) {
/* It's old, but it has held_by_nodes set. That's not okay. */
/* Let's try to diagnose and fix #7164 . */
smartlist_t *nodes = nodelist_find_nodes_with_microdesc(*mdp);
const networkstatus_t *ns = networkstatus_get_latest_consensus();
int networkstatus_age = -1;
if (ns) {
networkstatus_age = now - ns->valid_after;
}
log_warn(LD_BUG, "Microdescriptor seemed very old "
"(last listed %d hours ago vs %d hour cutoff), but is still "
"marked as being held by %d node(s). I found %d node(s) "
"holding it. Current networkstatus is %d hours old.",
(int)((now - (*mdp)->last_listed) / 3600),
(int)((now - cutoff) / 3600),
held_by_nodes,
smartlist_len(nodes),
(int)(networkstatus_age / 3600));
SMARTLIST_FOREACH_BEGIN(nodes, const node_t *, node) {
const char *rs_match = "No RS";
const char *rs_present = "";
if (node->rs) {
if (tor_memeq(node->rs->descriptor_digest,
(*mdp)->digest, DIGEST256_LEN)) {
rs_match = "Microdesc digest in RS matches";
} else {
rs_match = "Microdesc digest in RS does match";
}
if (ns) {
/* This should be impossible, but let's see! */
rs_present = " RS not present in networkstatus.";
SMARTLIST_FOREACH(ns->routerstatus_list, routerstatus_t *,rs, {
if (rs == node->rs) {
rs_present = " RS okay in networkstatus.";
}
});
}
}
log_warn(LD_BUG, " [%d]: ID=%s. md=%p, rs=%p, ri=%p. %s.%s",
node_sl_idx,
hex_str(node->identity, DIGEST_LEN),
node->md, node->rs, node->ri, rs_match, rs_present);
} SMARTLIST_FOREACH_END(node);
smartlist_free(nodes);
(*mdp)->last_listed = now;
}
++kept;
mdp = HT_NEXT(microdesc_map, &cache->map, mdp);
}

View File

@ -337,6 +337,25 @@ nodelist_drop_node(node_t *node, int remove_from_ht)
node->nodelist_idx = -1;
}
/** Return a newly allocated smartlist of the nodes that have <b>md</b> as
* their microdescriptor. */
smartlist_t *
nodelist_find_nodes_with_microdesc(const microdesc_t *md)
{
smartlist_t *result = smartlist_new();
if (the_nodelist == NULL)
return result;
SMARTLIST_FOREACH_BEGIN(the_nodelist->nodes, node_t *, node) {
if (node->md == md) {
smartlist_add(result, node);
}
} SMARTLIST_FOREACH_END(node);
return result;
}
/** Release storage held by <b>node</b> */
static void
node_free(node_t *node)

View File

@ -26,6 +26,7 @@ void nodelist_set_consensus(networkstatus_t *ns);
void nodelist_remove_microdesc(const char *identity_digest, microdesc_t *md);
void nodelist_remove_routerinfo(routerinfo_t *ri);
void nodelist_purge(void);
smartlist_t *nodelist_find_nodes_with_microdesc(const microdesc_t *md);
void nodelist_free_all(void);
void nodelist_assert_ok(void);