microdesc.c:378: Bug: microdesc_free() called, but md was still referenced 1 node(s); held_by_nodes == 1

Oct 20 21:14:18.594 [Warning] microdesc_free(): Bug: microdesc_free() called, but md was still referenced 1 node(s); held_by_nodes == 1

Trac:
Username: jaj123

changed milestone to %Tor: unspecified in legacy/trac

added 025-backport in Legacy / Trac 033-removed-20180320 in Legacy / Trac 033-triage-20180320 in Legacy / Trac 043-deferred in Legacy / Trac BugSmashFund in Legacy / Trac component::core tor/tor in Legacy / Trac milestone::Tor: unspecified in Legacy / Trac nickm-should-review in Legacy / Trac points::2 in Legacy / Trac priority::high in Legacy / Trac reporter::jaj123 in Legacy / Trac review-group-24 in Legacy / Trac reviewer::asn in Legacy / Trac severity::normal in Legacy / Trac status::needs-revision in Legacy / Trac tor-client in Legacy / Trac type::defect in Legacy / Trac version::tor 0.2.4.19 in Legacy / Trac labels

Exciting!

Which Tor version?

What bundle were you using? What OS?

Were you a client or a relay or something else?

Any other configuration changes or hints?

Trac:
Component: - Select a component to Tor
Milestone: N/A to Tor: 0.2.3.x-final

See legacy/trac#6429 (moved), legacy/trac#6494 (moved), legacy/trac#3153 (moved), legacy/trac#4118 (moved) for related tickets.

Replying to arma:

Exciting!

Which Tor version?

What bundle were you using? What OS?

Were you a client or a relay or something else?

Any other configuration changes or hints? Tor version 0.2.3.22, Vidalia 0.2.20, No idea about bundle, all Tor & Vidalia stuff installed via Synaptic package manager, OS ubuntu 64-bit 12.04 LTS, updated regularly, all possible unity software removed. I use OS's (perhaps related also to firefox somehow) default proxies.

I'm really a newbie in Tor: now I have been running a relay for about two months. In my previous main system (also a 64 bit Linux machine) I tried to run Tor, but it just kept crashing, so I gave up.

Trac:
Username: jaj123

On the previous system, when it 'kept crashing', do you have any other hints for us?

Trac:
Priority: normal to major
Summary: Tor's request to send a bug report to Bug: microdesc_free() called, but md was still referenced 1 node(s); held_by_nodes == 1

When my old Tor crashed, it seemed random: sometimes it took 5 min, sometimes 1 hour. That was about 1½ years ago. I kept no records, I just thought I'll give Tor another try later.

I installed Ubuntu's updates suggested by the Update manager some 8 hours ago. Tor and Vidalia went completely down, as did Firefox (it had Tor enabled). I had to remove Firefox completely and re-install it to get it up. Vidalia and Tor are now up and running, but I had to start them as root (sudo was not enough), While trying, the whole system crashed several times, but recovered without any tricks, creating automatic bug reports for the Ubuntu team. I think the later is Ubuntu's bug: it just would not let me start anything with Gnome GUI as root, and as a result told me even:"...root does not exist, cant' do anything without it" (Sic!). Please keep me informed, there might be some serious bugs spreading around.

Trac:
Username: jaj123

Trac:
Keywords: N/A deleted, tor-client added

Update: latest message from Vidalia Message log:"Oct 24 13:57:27.610 [Notice] Heartbeat: Tor's uptime is 2 days 17:53 hours, with 36 circuits open. I've sent 10.95 GB and received 2.09 GB." Quite a lot sent compared to received, maybe even a security failure. Only the relay has been running after the crash. I generally use client services very little, basically I have only tested weather they work. Please keep me informed, if there's anything new I should do in order to keep my relay running as it should. I've been away for a couple of days, so I could no report the current status earlier.

Trac:
Username: jaj123

It would be great to have a stack trace from the line in microdesc.c that's giving this message. Do you know how to use gdb?

Sorry, I don't how to use gdb. With Your help, I'm willing to try.

Trac:
Username: jaj123

Update: Tor down, cleanly by itself, on 27.10, reporting (roughly): Interrupt, not accepting new connections, shutting down in 30 seconds. Any advise?

Trac:
Username: jaj123

The "Interrupt, not accepting new connections, shutting down in 30 seconds" thing is what happens if Tor received a SIGINT signal, or a control-c at the command line. It usually doesn't indicate a bug.

Thanks nickm. To my surprise, Tor and vidalia are now working as I expect: they started from the "onion"-button from Gnome when I was logged in as a normal user. Not a single warning or error message, the latest:"Oct 31 13:22:33.228 [Notice] Heartbeat: Tor's uptime is 22:54 hours, with 15 circuits open. I've sent 810.66 MB and received 790.18 MB." There's been an update by Ubuntu Update Manager: the current version is 0.2.3.24-rc. The one that I had problems with was 0.2.3.22-rc. Problem solved?

Trac:
Username: jaj123

It happened again:Nov 06 20:00:46.279 [Warning] microdesc_free(): Bug: microdesc_free() called, but md was still referenced 1 node(s); held_by_nodes == 1. Latest normal log:Nov 06 19:22:33.228 [Notice] Heartbeat: Tor's uptime is 7 days 4:54 hours, with 58 circuits open. I've sent 16.31 GB and received 16.02 GB. I have no idea what's happening. Please help, I want to run Tor without causing any trouble to other users.

Trac:
Username: jaj123

Replying to jaj123:

I want to run Tor without causing any trouble to other users.

For what it's worth, seeing this message is probably harmless. That is, we should track it down, but it's probably not causing any trouble to other users.

Tor 0.2.3.25; I don't recall offhand which bundle I'm using, but I keep them up to date; Ubuntu Linux 12.04.1 LTS; running as a non-exit relay. This is the first time I've encountered this particular error in my years of running Tor. The only thing I've been doing differently lately is running EtherApe.

Trac:
Username: kencf0618

I've also caught this in the wild. Running Trisquel GNU/Linux, TOR version 0.2.3-1~oneric+1. Installed from the TOR PPA.

Trac:
Milestone: Tor: 0.2.3.x-final to Tor: 0.2.4.x-final

I looked over all the microdesc_free() calls again, and none seems super likely here. Maaaybe the one in microdesc_cache_clean? But how would a currently live node reference a microdescriptor that was last listed over 7 days ago? And could something else be going on?

In an attempt to track this down, I did a quick patch to log the fname:lineno that's invoking microdesc_free(). See branch "bug7164_diagnostic" in my public repo. The branch is against 0.2.4.

Trac:
Status: new to needs_review

Replying to nickm:

I looked over all the microdesc_free() calls again, and none seems super likely here. Maaaybe the one in microdesc_cache_clean? But how would a currently live node reference a microdescriptor that was last listed over 7 days ago? And could something else be going on?

In an attempt to track this down, I did a quick patch to log the fname:lineno that's invoking microdesc_free(). See branch "bug7164_diagnostic" in my public repo. The branch is against 0.2.4.

I think it's fine to merge this diagnostic branch.

Okay, merged the diagnostic branch into 0.2.4. If somebody hits this, we can figure out the real fix, I hope.

Trac:
Status: needs_review to needs_information

Closed legacy/trac#8556 (moved) as a duplicate of this.

Trac:
ticket7164.tails.17.1.log

complete log of seeing this bug in tails 17.1 after setting the clock

closed legacy/trac#8871 (moved) as a duplicate of this too

I got same error tor version: 0.2.35 vidalia version: 0.2.21 OS: windows 7 bundle: I installed "Vidalia Relay Bundle" but i changed in settings to a exit relay! I am a client and relay, mostly relay but use client once in a while, got it running but don't use it as much as relay!

I get the error about 10 times every hour! Gonna update to 0.2.4 t test!

Trac:
Username: tryy3

0.2.4 fixed it!

Trac:
Username: tryy3

Trac:
Milestone: Tor: 0.2.4.x-final to Tor: 0.2.5.x-final
Keywords: tor-client deleted, tor-client 024-backport added

Replying to nickm:

Okay, merged the diagnostic branch into 0.2.4. If somebody hits this, we can figure out the real fix, I hope.

See legacy/trac#10638 (moved) and legacy/trac#9813 (moved) for examples of 0.2.4 clients that hit it.

src/or/microdesc.c:378 and src/or/microdesc.c:379 respectively.

legacy/trac#10630 (moved) also saw that line

Trac:
Status: needs_information to new
Milestone: Tor: 0.2.5.x-final to Tor: 0.2.4.x-final
Version: Tor: 0.2.3.22-rc to Tor: 0.2.4.19
Summary: Bug: microdesc_free() called, but md was still referenced 1 node(s); held_by_nodes == 1 to microdesc.c:378: Bug: microdesc_free() called, but md was still referenced 1 node(s); held_by_nodes == 1

Nick: just to make it explicit, it looks like 0.2.4.x clients are seeing this, and the new line numbers in the debug logs should give us our hints.

I have just found this bug again in RT#22370

I have asked the user for exact version information and OS version information.

[sex 14. mar 19:32:52 2014] Tor Software Error - The Tor software encountered an internal bug. Please report the following error message to the Tor developers at bugs.torproject.org: "microdesc_free(): Bug: microdesc_free() called, but md was still referenced 1 node(s); held_by_nodes == 1 "

Trac:
Username: Envite

The line number suggests that this is happening in microdesc_cache_clean():

  for (mdp = HT_START(microdesc_map, &cache->map); mdp != NULL; ) {
    if ((*mdp)->last_listed < cutoff) {
      ++dropped;
      victim = *mdp;
      mdp = HT_NEXT_RMV(microdesc_map, &cache->map, mdp);
      victim->held_in_map = 0;
      bytes_dropped += victim->bodylen;
      microdesc_free(victim);
    } else {
      ++kept;
      mdp = HT_NEXT(microdesc_map, &cache->map, mdp);
    }
  }

So, there's a microdesc that is (probably) held by a node, but its last-listed is more than one week ago. Interesting!

In theory:

• A node should not exist unless it has a routerstatus or a routerinfo.
• A node should not have a microdescriptor unless it has a routerstatus.
• Whenever a networkstatus is loaded, we should be updating the last_seen field of the microdescriptors.

So something has gone wrong with the theory.

I'm not too sure what -- if somebody has ideas, that would be great. I've tried to write an improved diagnostic branch. Please review "bug7164_diagnose_harder" in my public repository. It's more logs, not a fix.

Trac:
Status: new to needs_review
Milestone: Tor: 0.2.4.x-final to Tor: 0.2.5.x-final

RT#22370 happens in Tor 0.2.3.25

Trac:
Username: Envite
Milestone: Tor: 0.2.5.x-final to Tor: 0.2.4.x-final

Please don't mess with the milestones. The "024-backport" tag is what means "backport this to 0.2.4 when it's done". All bugfixes for 0.2.4 or 0.2.3 need to get tested in 0.2.4 (the latest branch) before they can get get backported.

Trac:
Milestone: Tor: 0.2.4.x-final to Tor: 0.2.5.x-final

Replying to nickm:

The line number suggests that this is happening in microdesc_cache_clean():

  for (mdp = HT_START(microdesc_map, &cache->map); mdp != NULL; ) {
    if ((*mdp)->last_listed < cutoff) {
      ++dropped;
      victim = *mdp;
      mdp = HT_NEXT_RMV(microdesc_map, &cache->map, mdp);
      victim->held_in_map = 0;
      bytes_dropped += victim->bodylen;
      microdesc_free(victim);
    } else {
      ++kept;
      mdp = HT_NEXT(microdesc_map, &cache->map, mdp);
    }
  }
}}}

So, there's a microdesc that is (probably) held by a node, but its last-listed is more than one week ago.  Interesting!

In theory:
  * A node should not exist unless it has a routerstatus or a routerinfo.
  * A node should not have a microdescriptor unless it has a routerstatus.
  * Whenever a networkstatus is loaded, we should be updating the last_seen field of the microdescriptors.

So something has gone wrong with the theory.

I'm not too sure what -- if somebody has ideas, that would be great.  I've tried to write an improved diagnostic branch.  Please review "bug7164_diagnose_harder" in my public repository.  It's more logs, not a fix.

Doesn't this also change the behavior as well?

{{{

• 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) {

The test that would match the old behavior would be just if (is_old), surely?

Also, the wording of the log messages ("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.") suggests you only want to emit for old microdescriptors, but the enclosing test is just if (held_by_nodes) rather than if (is_old && held_by_nodes). Am I missing something here?

I think the actual logging code is okay as long as we're sure the tests are right; making them over-eager means a lot of searching the whole list of nodes in nodelist_find_nodes_with_microdesc() whenever we run microdesc_cache_clean()

The test that would match the old behavior would be just if (is_old), surely?

The old behavior was to call "microdesc_free()" if the microdescriptor was old... and then the warning would be produced because held_by_nodes was nonzero, and we wouldn't free the thing. The change here has the old behavior in the non-warning case, and the new behavior in the case where we would have given a warning.

Also, the wording of the log messages ("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.") suggests you only want to emit for old microdescriptors, but the enclosing test is just if (held_by_nodes) rather than if (is_old && held_by_nodes). Am I missing something here?

Oops. Yeah, adding a fixup commit. Better now?

22:12 < nickm> athena: okay to merge now IYO?
22:12 < athena> yeah

I shoudl squash and merge rsn then.

Trac:
Keywords: tor-client 024-backport deleted, tor-client 024-backport 025-triaged added

Squashed and merged; thanks, all!

Trac:
Resolution: N/A to fixed
Status: needs_review to closed

Trac:
Status: closed to reopened
Resolution: fixed to N/A

Oops, that should have gone into needs_information. That was a diagnostic message improvement, not a total fix.

Trac:
Status: reopened to needs_information

Putting this in 0.2.???; they should get moved back into a more timed milestone once they're no longer in needs_information.

Trac:
Milestone: Tor: 0.2.5.x-final to Tor: 0.2.???

Should we sneak in a log severity downgrade in 0.2.4.21?

It's my understanding that the more useful log message change went into 0.2.5, leaving the 0.2.4 with nothing useful to us but their logs still yell at them.

I was reminded of this idea from legacy/trac#11668 (closed).

Should we sneak in a log severity downgrade in 0.2.4.21?

(ITYM 0.2.4.22.) Sure, that's fine with me.

Replying to nickm:

Should we sneak in a log severity downgrade in 0.2.4.21?

(ITYM 0.2.4.22.) Sure, that's fine with me.

Done as 6a4f5d9b in 0.2.3 and 0.2.4

7 days to trigger bug: day 0: user launches Tor, fetches md (which later fails) and caches it with last_listed = 0 to disk; day 1: user online; restarting, shutdowning etc; day 2: user online, relay still announcing the same keys as for md from cache, no cached md changes; day 3: the same; day 4: the same; day 5: user offline; day 6: user offline;

day 7: user starting Tor, cached consensus is several days old; md's last_listed stored on disk is zero; update_microdescs_from_networkstatus can't to update last_listed field in memory anymore; if microdesc_cache_clean launched before new consensus arrived and "last_listed < today - 7days" then bug triggeres.

Replying to cypherpunks:

7 days to trigger bug:

It was wrong idea. It' impossible to clean md cache with non reasonably live consensus

  if (! force &&
      ! networkstatus_get_reasonably_live_consensus(now, FLAV_MICRODESC))
      return;

No live consensus no call of microdesc_free