From 0389d4aa561bec06ad2aab70ea5a989f1f2d02c6 Mon Sep 17 00:00:00 2001
From: Nick Mathewson <nickm@torproject.org>
Date: Mon, 17 Mar 2014 14:15:12 -0400
Subject: 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.
---
 changes/bug7164_diagnose_harder |  6 +++++
 src/or/microdesc.c              | 52 ++++++++++++++++++++++++++++++++++++++++-
 src/or/nodelist.c               | 19 +++++++++++++++
 src/or/nodelist.h               |  1 +
 4 files changed, 77 insertions(+), 1 deletion(-)
 create mode 100644 changes/bug7164_diagnose_harder

diff --git a/changes/bug7164_diagnose_harder b/changes/bug7164_diagnose_harder
new file mode 100644
index 000000000..28c36b658
--- /dev/null
+++ b/changes/bug7164_diagnose_harder
@@ -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.
diff --git a/src/or/microdesc.c b/src/or/microdesc.c
index 90ac0ac64..abcf5fc4d 100644
--- a/src/or/microdesc.c
+++ b/src/or/microdesc.c
@@ -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);
     }
diff --git a/src/or/nodelist.c b/src/or/nodelist.c
index 178f084b6..d92ef1733 100644
--- a/src/or/nodelist.c
+++ b/src/or/nodelist.c
@@ -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)
diff --git a/src/or/nodelist.h b/src/or/nodelist.h
index 8a4665a8b..836b2af0c 100644
--- a/src/or/nodelist.h
+++ b/src/or/nodelist.h
@@ -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);
-- 
cgit v1.2.3