Unbuilt one-hop circuits sometimes hang around forever
I've noticed that with tor 0.2.4.10-ish, Vidalia can accumulate a lot of "Path Empty" circuits after a while. According to my control port, these are ONEHOP_TUNNEL circuits that haven't yet connected to a guard. They seem to stick around for days unless I close them.
I suppose this could be due to the circuit build timeout changes in #7341 (moved), or Roger's "let circuits last forever if you have none open" hack from #3443 (moved), or directory guards, or $RANDOM_GUESS.
I'll poke at it with gdb next time I notice it.
Activity
changed milestone to %Tor: unspecified
This is painful to reproduce and takes days of me watching the Vidalia window with an alpha build.. And that's just to get a case where I might be able to find out what has happened.
Do we have any ability to write a stem or torperf to watch for this and other cases of leaked/unculled circuits? Such a stress test would making gathering more instances of this easier. There might be also be other cases where circuits sit around unkilled, given the complexity of our timeout code :/.
Trac:
Cc: N/A to atagar, karstenDo we have any ability to write a stem or torperf to watch for this and other cases of leaked/unculled circuits? Such a stress test would making gathering more instances of this easier.
I'm not sure if I completely follow. The trouble is that tor continually makes circuits and should reclaim them when they grow above a certain pool size, but the reclamation isn't working. Is that right? If so then are you looking for something like the following? (pardon typos, not actually ran)
import stem.control with stem.control.from_port() as controller: controller.authenticate() for i in xrange(50): controller.new_circuit() circ_count = len(controller.get_circuits()) # not sure of the actual pool size... if circ_count > 5: print "too many circuits, we have %i... :(" % circ_count-
I think what I am asking is for a way to create a bunch of circuits (perhaps with a wget loop plus MaxCircuitDirtiness 10) over a long period of time, and spit out an alert if any currently unused circuits are older than an hour.
I'm not sure how far along our stem-based integration testing plan is, but this is something that I think we should eventually include in that test suite. Nick has previously pointed out that circuit_expire_building (our circuit timeout function) is the 11th most cyclomatically complex functions in tor-core, and we have a few other bugs like this that smell a lot like timeout-related issues...
If the circuits need to be onehop, or if this bug only affects onehop circuits, we won't provoke it by launching circuits with wget or via the controller. But if it affects other circuits too, maybe we will! Wget-launched circuits are likelier to be right here: there is some special-casing for controller-managed circuits if I recall aright.
As for the "see if a circuit sticks around far too long" logic... I wonder if we can think about "what then"? If we see that an circuit which is (we think) unused is still around after a long time, that's something that we could check for even in Tor, even with a log message: but if we're going to add a log message for that, we should ask ourselves what information we'd need it to give to make this degbuggable.
-
So the specific change from #3443 (moved) that I think is likely the culprit here is the check TO_ORIGIN_CIRCUIT(victim)->cpath->state == CPATH_STATE_CLOSED at the top of the circuit culling loop of circuit_expire_building(). I added that check to allow circuits to exist until we sent their create cell, with the expectation that the orconn pruning code would eventually clean them up.
It looks like run_connection_housekeeping() is the function that should prune connections in this case... Unless these connections haven't set their type to CONN_TYPE_DIR, it looks very much like they should still be getting closed there... Hrmm..
I like Nick's idea of adding a function to tell us if we have any stale circuits and/or connections in normal usage, but I am not sure I could craft such a check myself to both cover all the cases of 'stale' and not introduce a bunch of false positive warns.. Probably 0.2.5.x material for that reason, unless Nick is more confident about exactly what checks we should do in such a case.
In fact, it looks like run_connection_housekeeping() has one instance of such a check for wedged orconns (but not dirconns.. it seems to just have code to close those), but I've never seen its warns emitted for this bug.
-
Code in bug8387_diagnostic . Needs review. Also, Roger & Mike: do you think there's more info about the circuits it should log beyond what I have there? Right now it looks like (dummy output with interval set to 1 second):
Apr 29 13:54:37.000 [notice] Problem: Found 4 one-hop circuits more than 1 seconds old! Logging 4... Apr 29 13:54:37.000 [notice] #0 created at 2014-04-29 13:54:30. open, General-purpose client. Not marked for close. usable for new conns. Apr 29 13:54:37.000 [notice] #1 created at 2014-04-29 13:54:10. open, General-purpose client. Not marked for close. Not usable for new conns. Apr 29 13:54:37.000 [notice] #2 created at 2014-04-29 13:53:59. open, General-purpose client. Not marked for close. usable for new conns. Apr 29 13:54:37.000 [notice] #3 created at 2014-04-29 13:53:59. open, General-purpose client. Not marked for close. usable for new conns.Trac:
Status: assigned to needs_review -
Roger suggests that ""Diagnostic for issue #8387 (moved):" is a better phrase than "Problem:".
Looking at the code, a backport to 0.2.4 appears nontrivial due to data structure issues. And if this is really an endemic problem, adding the diagnostic code to 0.2.5 only should be okay.
-
Merged the diagnostic branch to master. Not backporting. A solution here will depend on getting good info from the log messages we added, and some insight about what to do about them. It's still not too late to review those messages: Please comment (or give me a patch) if you think there's more stuff we should be logging.
Trac:
Keywords: MikePerry201405R, tor-client 024-backport 025-triaged deleted, tor-client MikePerry201405R added
Status: needs_review to new
Milestone: Tor: 0.2.5.x-final to Tor: 0.2.??? 
Jun 02 00:59:43.614 [notice] Diagnostic for issue 8387: Found 2 one-hop circuits more than 1800 seconds old! Logging 2... Jun 02 00:59:43.614 [notice] #0 created at 2014-06-01 22:09:58. open, General-purpose client. Not marked for close. usable for new conns. Jun 02 00:59:43.614 [notice] #1 created at 2014-06-01 20:47:37. open, General-purpose client. Not marked for close. usable for new conns.what have we here?
-
Both circuits were created like this:
Jun 01 22:09:58.616 [info] update_consensus_networkstatus_downloads(): Launching microdesc networkstatus consensus download. Jun 01 22:09:58.617 [debug] directory_initiate_command_rend(): anonymized 0, use_begindir 1. Jun 01 22:09:58.617 [debug] directory_initiate_command_rend(): Initiating consensus network-status fetch Jun 01 22:09:58.617 [info] connection_ap_make_link(): Making internal direct tunnel to 109.201.131.11:443 ... Jun 01 22:09:58.617 [debug] connection_add_impl(): new conn type Socks, socket -1, address (Tor_internal), n_conns 7. Jun 01 22:09:58.617 [debug] extend_info_from_node(): using 109.201.131.11:443 for TORoC4SSoORG Jun 01 22:09:58.617 [debug] onion_pick_cpath_exit(): Launching a one-hop circuit for dir tunnel.and then they proceed to finish being built, and have the directory stream attached to them, and get a connected cell, and receive directory stuff, and then successfully got the whole thing:
Jun 01 22:10:00.383 [info] connection_dir_client_reached_eof(): Successfully loaded consensus. -
And this second one did eventually close:
Jun 02 06:36:28.628 [debug] circuit_expire_old_circuits_clientside(): Closing n_circ_id 4290848735 (dirty 30390 sec ago, purpose 5) Jun 02 06:36:28.628 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x7ff16890ef20 for circ_id 4290848735, channel ID 44 (0x7ff1689f6a90) Jun 02 06:36:28.628 [debug] circuit_get_by_circid_channel_impl(): circuit_get_by_circid_channel_impl() returning circuit 0x7ff16890ef20 for circ_id 4290848735, channel ID 44 (0x7ff1689f6a90) Jun 02 06:36:28.628 [debug] circuitmux_append_destroy_cell(): Cmux at 0x7ff168f0e4b0 queued a destroy for circ 4290848735, cmux counter is now 2, global counter is now 2 Jun 02 06:36:28.628 [debug] channel_send_destroy(): Sending destroy (circID 4290848735) on channel 0x7ff1689f6a90 (global ID 44) -
The part that should have triggered (and which eventually did trigger) in circuit_expire_old_circuits_clientside() is:
if (circ->timestamp_dirty && circ->timestamp_dirty + get_options()->MaxCircuitDirtiness < now.tv_sec && !TO_ORIGIN_CIRCUIT(circ)->p_streams /* nothing attached */ ) {I'd suspect that p_streams was not in fact empty on these circuits somehow. I think I'll extend the log message to investigate that.
-
Turns out I got the messages earlier too:
May 31 06:59:43.615 [notice] Diagnostic for issue 8387: Found 3 one-hop circuits more than 1800 seconds old! Logging 3... May 31 06:59:43.615 [notice] #0 created at 2014-05-31 06:16:44. open, General-purpose client. Not marked for close. usable for new conns. May 31 06:59:43.615 [notice] #1 created at 2014-05-31 04:25:55. open, General-purpose client. Not marked for close. usable for new conns. May 31 06:59:43.615 [notice] #2 created at 2014-05-31 01:08:41. open, General-purpose client. Not marked for close. usable for new conns.so I guess that's good news for reproducing once you have more log details in place.
-
Replying to nickm:
arma, can you say any more about your configuration here?a
Tor v0.2.5.4-alpha-dev (git-e318ab14b10f353d), built from source, running as a client. I believe there's nothing interesting in the torrc. This Tor client is used by my pidgin and often is unused.
-
Well, that's strange! I had kind of thought that there would still be streams on these. But it isn't logging anything about streams.
Oh, here is a possible dumb bug: What if it isn't calling circuit_expire_old_circuits_clientside() at all? The circuit_expire_old_circuits_clientside() function is supposed to be getting called from circuit_build_needed_circs()... and circuit_build_needed_circs is called only when have_dir_info && !net_is_disabled().
I wonder which one of those might be false? Does have_dir_info become false after running as a relay for a while, or do we think we're hibernating for some reason?
The sensible fix is probably to call circuit_expire_old_circuits_clientside even when we aren't calling circuit_build_needed_circuits().
-
Good idea. I've merged "bug8387_024" to 0.2.5, and added a diagnostic of the type you suggest as 32495ee3099c3fb512a986a8e.
This is now needs_information for 0.2.5 again. If the fix does make the bug go away, then it should become needs_review for 0.2.4.
Trac:
Status: needs_review to needs_information Tor version 0.2.5.10 (git-43a5f3d91e726291).
Feb 06 04:08:02.000 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... Feb 06 04:08:02.000 [notice] #0 created at 2015-02-05 04:44:35. open, General-purpose client. Not marked for close. Not usable for new conns. Dirty since 2015-02-05 04:34:39 (84803 seconds vs 600-second cutoff). Feb 06 04:08:02.000 [notice] Stream#1 created at 2015-02-05 04:44:35. Socks conn in state open. Not marked for close (--:0). Hold-open is not set. Has not sent RELAY_END. Not blocked on circuit. Feb 06 04:08:02.000 [notice] It has been 0 seconds since I last called circuit_expire_old_circuits_clientside(). Feb 06 04:08:12.000 [notice] Interrupt: exiting cleanly.
I recently picked this up in the log of the meek-google bridge. I'm running 0.2.7.6:
Dec 25 09:52:43.000 [notice] Diagnostic for issue 8387: Found 2 one-hop circuits more than 1800 seconds old! Logging 2... Dec 25 09:52:43.000 [notice] #0 created at 2015-12-25 08:57:57. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Dirty since 2015-12-25 09:49:48 (175 seconds vs 600-second cutoff). Dec 25 09:52:43.000 [notice] #1 created at 2015-12-25 09:12:11. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Dec 25 09:52:43.000 [notice] It has been 22 seconds since I last called circuit_expire_old_circuits_clientside().
Edit: It appears that I have set the Severity to Normal. This was unintentional, but I'm not sure what it was before.
Trac:
Sponsor: N/A to N/A
Severity: N/A to Normal
Saw the same message in the log of the meek-amazon bridge running with 0.2.6.7
Jan 09 16:44:20.000 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... Jan 09 16:44:20.000 [notice] #0 created at 2016-01-09 15:56:47. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Jan 09 16:44:20.000 [notice] It has been 5 seconds since I last called circuit_expire_old_circuits_clientside().
Trac:
Username: torlandSeems to be another one spam log, but nevertheless (TBB 6.5a2, Tor 0.2.8.5-rc):
Sep 01 14:01:59.000 [notice] Your system clock just jumped 21583 seconds forward; assuming established circuits no longer work. Sep 01 19:09:53.000 [notice] Heartbeat: Tor's uptime is 10:17 hours, with 1 circuits open. I've sent 9.70 MB and received 55.77 MB. Sep 01 19:09:53.000 [notice] Average packaged cell fullness: 63.218%. TLS write overhead: 3% Sep 01 19:09:53.000 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... Sep 01 19:09:54.000 [notice] #0 created at 2016-09-01 08:01:50. open, General-purpose client. Not marked for close. Package window: 1000. Not usable for new conns. Dirty since 2016-09-01 07:51:59 (40674 seconds vs 600-second cutoff). Sep 01 19:09:54.000 [notice] Stream#1 created at 2016-09-01 08:01:50. Socks conn in state open. It is linked and reading from a linked connection 00000000. Package window 499. Not marked for close (--:0). Hold-open is not set. Has not sent RELAY_END. Not blocked on circuit. Sep 01 19:09:54.000 [notice] It has been 18473 seconds since I last called circuit_expire_old_circuits_clientside(). Sep 01 19:09:57.000 [notice] Your system clock just jumped 18482 seconds forward; assuming established circuits no longer work. Sep 01 19:10:07.000 [notice] Our IP address has changed. Rotating keys...(OT: When tried to switch from direct to bridge in Torbutton during session, Tor was restarted and began to write UTC instead of local time to its log. Thoughts?)
I'm getting output related to this ticket every heartbeat it looks like. Running 0294-alpha as a single onion service.
The real-time up-to-date log is http://bh2lpa5qyawryvk2.onion/log
Tor 0.2.9.4-alpha (git-8b0755c9bb296ae2) running on Linux with Libevent 2.0.10-stable, OpenSSL 1.0.1t and Zlib 1.2.8.
Snippit:
Nov 07 07:50:00.000 [notice] Heartbeat: Tor's uptime is 9 days 11:59 hours, with 10 circuits open. I've sent 38.40 MB and received 122.33 MB. Nov 07 07:50:00.000 [notice] Diagnostic for issue 8387: Found 3 one-hop circuits more than 1800 seconds old! Logging 3... Nov 07 07:50:00.000 [notice] #0 created at 2016-11-06 23:49:39. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 07:50:00.000 [notice] #1 created at 2016-11-06 18:23:40. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 07:50:00.000 [notice] #2 created at 2016-11-07 05:29:55. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 07:50:00.000 [notice] It has been 11 seconds since I last called circuit_expire_old_circuits_clientside(). Nov 07 10:07:03.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service bh2lpa5qyawryvk2. Nov 07 10:07:14.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service bh2lpa5qyawryvk2. Nov 07 10:07:44.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service bh2lpa5qyawryvk2. Nov 07 10:08:23.000 [warn] Giving up launching first hop of circuit to rendezvous point [scrubbed] for service bh2lpa5qyawryvk2. Nov 07 13:50:00.000 [notice] Heartbeat: Tor's uptime is 9 days 17:59 hours, with 6 circuits open. I've sent 39.17 MB and received 124.90 MB. Nov 07 13:50:00.000 [notice] Diagnostic for issue 8387: Found 3 one-hop circuits more than 1800 seconds old! Logging 3... Nov 07 13:50:00.000 [notice] #0 created at 2016-11-06 23:49:39. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 13:50:00.000 [notice] #1 created at 2016-11-06 18:23:40. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 13:50:00.000 [notice] #2 created at 2016-11-07 05:29:55. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 13:50:00.000 [notice] It has been 4 seconds since I last called circuit_expire_old_circuits_clientside(). Nov 07 19:01:32.000 [warn] connection_edge_process_relay_cell (at origin) failed. Nov 07 19:50:00.000 [notice] Heartbeat: Tor's uptime is 9 days 23:59 hours, with 6 circuits open. I've sent 40.01 MB and received 128.15 MB. Nov 07 19:50:00.000 [notice] Diagnostic for issue 8387: Found 3 one-hop circuits more than 1800 seconds old! Logging 3... Nov 07 19:50:00.000 [notice] #0 created at 2016-11-06 23:49:39. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 19:50:00.000 [notice] #1 created at 2016-11-07 16:01:03. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 19:50:00.000 [notice] #2 created at 2016-11-07 05:29:55. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 19:50:00.000 [notice] It has been 28 seconds since I last called circuit_expire_old_circuits_clientside(). Nov 08 01:50:00.000 [notice] Heartbeat: Tor's uptime is 10 days 5:59 hours, with 7 circuits open. I've sent 40.93 MB and received 131.47 MB. Nov 08 01:50:00.000 [notice] Diagnostic for issue 8387: Found 3 one-hop circuits more than 1800 seconds old! Logging 3... Nov 08 01:50:00.000 [notice] #0 created at 2016-11-07 16:01:03. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 08 01:50:00.000 [notice] #1 created at 2016-11-07 20:38:25. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 08 01:50:00.000 [notice] #2 created at 2016-11-07 05:29:55. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 08 01:50:00.000 [notice] It has been 21 seconds since I last called circuit_expire_old_circuits_clientside(). Nov 08 07:50:00.000 [notice] Heartbeat: Tor's uptime is 10 days 11:59 hours, with 12 circuits open. I've sent 41.66 MB and received 133.95 MB. Nov 08 07:50:00.000 [notice] Diagnostic for issue 8387: Found 3 one-hop circuits more than 1800 seconds old! Logging 3... Nov 08 07:50:00.000 [notice] #0 created at 2016-11-08 04:46:37. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 08 07:50:00.000 [notice] #1 created at 2016-11-07 16:01:03. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 08 07:50:00.000 [notice] #2 created at 2016-11-07 20:38:25. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 08 07:50:00.000 [notice] It has been 14 seconds since I last called circuit_expire_old_circuits_clientside(). Nov 08 13:50:00.000 [notice] Heartbeat: Tor's uptime is 10 days 17:59 hours, with 6 circuits open. I've sent 42.45 MB and received 137.12 MB. Nov 08 13:50:00.000 [notice] Diagnostic for issue 8387: Found 3 one-hop circuits more than 1800 seconds old! Logging 3... Nov 08 13:50:00.000 [notice] #0 created at 2016-11-08 04:46:37. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 08 13:50:00.000 [notice] #1 created at 2016-11-08 09:17:21. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 08 13:50:00.000 [notice] #2 created at 2016-11-07 20:38:25. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 08 13:50:00.000 [notice] It has been 7 seconds since I last called circuit_expire_old_circuits_clientside().Replying to pastly:
I'm getting output related to this ticket every heartbeat it looks like. Running 0294-alpha as a single onion service.
The real-time up-to-date log is http://bh2lpa5qyawryvk2.onion/log
Tor 0.2.9.4-alpha (git-8b0755c9bb296ae2) running on Linux with Libevent 2.0.10-stable, OpenSSL 1.0.1t and Zlib 1.2.8.
Snippit:
{{{ ... Nov 07 07:50:00.000 [notice] Diagnostic for issue 8387: Found 3 one-hop circuits more than 1800 seconds old! Logging 3... Nov 07 07:50:00.000 [notice] #0 created at 2016-11-06 23:49:39. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 07:50:00.000 [notice] #1 created at 2016-11-06 18:23:40. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Nov 07 07:50:00.000 [notice] #2 (closed) created at 2016-11-07 05:29:55. open, Hidden service: Introduction point. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. ... }}}
There was a time when only directory connections were one-hop, and they were expected to finish up quickly.
With single onion services, the
Hidden service: Introduction pointcircuits are intentionally long-term, one-hop circuits.I've split off this specific issue into #20613 (moved).
Hmm this looks old but here's what I got today:
Mar 29 15:12:11.000 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... Mar 29 15:12:11.000 [notice] #0 created at 2017-03-29 14:26:57. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Mar 29 15:12:11.000 [notice] It has been 3 seconds since I last called circuit_expire_old_circuits_clientside().On Tor
0.3.0.2-alpha-dev (git-0f79fb51e5653cbc+f6d2aaa).
I got some of these too on some eotk hidden service testing I've been doing.
Apr 19 03:02:40.000 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... Apr 19 03:02:40.000 [notice] #0 created at 2017-04-19 02:29:44. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Apr 19 03:02:40.000 [notice] It has been 27 seconds since I last called circuit_expire_old_circuits_clientside().This is on Tor version 0.2.9.10 (git-1f6c8eda0073f464).
I found this in my logs :
May 04 16:08:02.000 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... May 04 16:08:02.000 [notice] #0 created at 2017-05-04 15:26:07. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Dirty since 2017-05-04 15:58:06 (596 seconds vs 600-second cutoff). May 04 16:08:02.000 [notice] It has been 23 seconds since I last called circuit_expire_old_circuits_clientside().on Tor 0.3.1.0-alpha-dev (git-b8f7488e94f2cb83) ; tor client only on debian unstable 32bit.
I use tor just as client (not a relay, not a HS service). Recently during my work with some HS I got it (linux, 64 bit, 0.3.1.9):
Dec 06 02:03:03.000 [notice] Heartbeat: Tor's uptime is XX:XX hours, with XX circuits open. I've sent XX.XX MB and received XX.XX GB. Dec 06 02:03:03.000 [notice] Average packaged cell fullness: 65.XXX%. TLS write overhead: 4% Dec 06 02:03:03.000 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... Dec 06 02:03:03.000 [notice] #0 created at 2017-12-06 01:10:06. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Dirty since 2017-12-06 01:56:04 (4XX seconds vs 600-second cutoff). Dec 06 02:03:03.000 [notice] It has been 2 seconds since I last called circuit_expire_old_circuits_clientside().
Got it on my hsv3 HS:
Feb 22 09:53:43.000 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... Feb 22 09:53:43.000 [notice] #0 created at 2018-02-22 09:20:08. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Not marked dirty. Feb 22 09:53:43.000 [notice] It has been 23 seconds since I last called circuit_expire_old_circuits_clientside().-
This bug could be caused by the fact that we don't close underlying edge connections when the dirconn times out/closes. Then the circuit will always have a stream on it, and never close.
This same issue applies to any HSDIR activity as well (since those are also linked dirconns).
See also https://trac.torproject.org/projects/tor/ticket/27241#comment:8
-
If we fix this by closing edge connections when dirconns close, we shouldn't mark the edge conn, and instead use connection_edge_end(), because technically the other side will keep it open and we should be ready for half-opened cells (as per #25573 (moved) -- connection_edge_end() adds the stream id to the half-closed list)
-
Jan 27 00:07:39.416 [notice] Tor 0.4.0.1-alpha (git-77712a5fa29f135e) running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1a, Zlib 1.2.11, Liblzma N/A, and Libzstd N/A. [...] Jan 27 18:07:40.446 [notice] Heartbeat: Tor's uptime is 18:00 hours, with 0 circuits open. I've sent 315 kB and received 2.75 MB. Jan 27 23:02:41.006 [notice] No user activity in a long time: becoming dormant. Jan 28 00:07:40.544 [notice] Heartbeat: Tor's uptime is 22:55 hours, with 1 circuits open. I've sent 361 kB and received 4.01 MB. Jan 28 00:07:40.544 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... Jan 28 00:07:40.544 [notice] #0 created at 2019-01-27 22:55:41. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Dirty since 2019-01-27 22:55:42 (4318 seconds vs 600-second cutoff). Jan 28 00:07:40.544 [notice] It has been 3906 seconds since I last called circuit_expire_old_circuits_clientside(). Jan 28 06:07:40.640 [notice] Heartbeat: Tor's uptime is 22:55 hours, with 1 circuits open. I've sent 361 kB and received 4.05 MB. Jan 28 06:07:40.640 [notice] Diagnostic for issue 8387: Found 1 one-hop circuits more than 1800 seconds old! Logging 1... Jan 28 06:07:40.640 [notice] #0 created at 2019-01-27 22:55:41. open, General-purpose client. Not marked for close. Package window: 1000. usable for new conns. Dirty since 2019-01-27 22:55:42 (25918 seconds vs 600-second cutoff). Jan 28 06:07:40.640 [notice] It has been 25506 seconds since I last called circuit_expire_old_circuits_clientside().Running as just a standard client.
For extra fun, I seem to still have an OR connection open, and be sending / receiving keepalive cells on it. Even though Tor said it was going dormant, is surprised that it still has a circuit open, etc.
mentioned in issue #20613 (moved)
mentioned in issue #25116 (moved)
mentioned in issue #27241 (moved)
moved to tpo/core/tor#8387 (closed)
mentioned in issue tpo/core/tor#20613 (closed)
mentioned in issue tpo/core/tor#25116 (closed)