Opened 5 years ago

Last modified 5 months ago

#8387 new defect

Unbuilt one-hop circuits sometimes hang around forever

Reported by: mikeperry Owned by: nickm
Priority: High Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-client, 2016-bug-retrospective, needs-insight needs-analysis maybe-logs-would-help
Cc: atagar, karsten, teor Actual Points:
Parent ID: Points:
Reviewer: Sponsor:

Description

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, or Roger's "let circuits last forever if you have none open" hack from #3443, or directory guards, or $RANDOM_GUESS.

I'll poke at it with gdb next time I notice it.

Child Tickets

Attachments (1)

tor-58f4200789d0cc47ebd88f3091207cf4dd493573-profile-run.notices.log (186.3 KB) - added by andrea 3 years ago.

Download all attachments as: .zip

Change History (63)

comment:1 Changed 5 years ago by nickm

Owner: set to mikeperry
Status: newassigned

Mike, if your "I'll poke at it with gdb next time I notice it" doesn't mean I should assign this to you, please let me know

comment:2 Changed 5 years ago by mikeperry

Cc: atagar karsten added

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 :/.

comment:3 Changed 5 years ago by atagar

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.

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

comment:4 Changed 5 years ago by mikeperry

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...

comment:5 Changed 5 years ago by nickm

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.

comment:6 Changed 5 years ago by mikeperry

So the specific change from #3443 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.

comment:7 Changed 5 years ago by nickm

Keywords: 024-backport added
Milestone: Tor: 0.2.4.x-finalTor: 0.2.5.x-final

Hm. Yeah, let's try it in 0.2.5, and if we find a bug, backport the fix to 0.2.4 as needed.

comment:8 Changed 4 years ago by nickm

Keywords: 025-triaged added

Specifically, let's add a log message to the heartbeat that counts one-hop circuits that are over X hours old.

comment:9 Changed 3 years ago by nickm

Owner: changed from mikeperry to nickm

Oh, I'm probably the one who's going to have to be writing that logging code, huh? reassigning to me.

comment:10 Changed 3 years ago by nickm

Status: assignedneeds_review

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.

comment:11 Changed 3 years ago by mikeperry

Keywords: MikePerry201405R added

comment:12 Changed 3 years ago by nickm

Roger suggests that ""Diagnostic for issue #8387:" 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.

comment:13 Changed 3 years ago by nickm

Keywords: 024-backport 025-triaged removed
Milestone: Tor: 0.2.5.x-finalTor: 0.2.???
Status: needs_reviewnew

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.

comment:14 Changed 3 years ago by arma

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?

comment:15 Changed 3 years ago by arma

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.

comment:16 Changed 3 years ago by arma

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)

comment:17 Changed 3 years ago by nickm

So, why do we think that circuit_expire_old_circuits_clientside() didn't catch those before?

comment:18 Changed 3 years ago by nickm

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

Tentatively replacing this into 0.2.5.

comment:19 Changed 3 years ago by nickm

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.

comment:20 Changed 3 years ago by nickm

arma, can you say any more about your configuration here?a

comment:21 Changed 3 years ago by arma

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.

comment:22 in reply to:  20 Changed 3 years ago by arma

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.

comment:23 Changed 3 years ago by nickm

Keywords: 025-triaged added

comment:24 Changed 3 years ago by nickm

Priority: normalmajor

comment:25 Changed 3 years ago by mikeperry

Keywords: MikePerry201406R added; MikePerry201405R removed

comment:26 Changed 3 years ago by nickm

Status: newneeds_review

I have some simple logging improvements in more_bug8387_diagnosis. They log how long the circuit has been dirty, and information about any streams on it (and any connections they might be linked to).

comment:27 Changed 3 years ago by andrea

I think the patch in more_bug8387_diagnosis should be okay to merge.

comment:28 Changed 3 years ago by nickm

Status: needs_reviewneeds_information

Okay. Merged that diagnosis branch; moving this into needs_information.

comment:29 Changed 3 years ago by andrea

Many observed occurrences of this; attaching log.

comment:30 Changed 3 years ago by nickm

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().

comment:31 Changed 3 years ago by nickm

Status: needs_informationneeds_review

Please review my patch in branch "bug8387_024".

comment:32 Changed 3 years ago by andrea

The patch looks good, but I wonder if there might be some benefit to extra logging in circuit_expire_old_circs_as_needed(), so if the bug persists we can tell "this is not getting called" from "this is getting called but not expiring the circuit for some reason"

comment:33 Changed 3 years ago by nickm

Status: needs_reviewneeds_information

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.

comment:34 Changed 3 years ago by mikeperry

Keywords: MikePerry201406R removed

comment:35 Changed 3 years ago by nickm

Has this gotten better in 0.2.5.6-alpha? If so, we should close this ticket.

comment:36 Changed 3 years ago by ioerror

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.

comment:37 Changed 3 years ago by arma

skruffy points us at

      connection_start_reading(conn->linked_conn);

in connection_unlink().

He thinks we need to connection_start_reading() whether conn->linked_conn->reading_from_linked_conn is true or false.

comment:38 Changed 3 years ago by arma

(If the goal is to cause the other side to wake up and notice the eof, but we only cause it to do this when it was willing to read already... then we have an edge case where if it wasn't reading, we won't tell it to wake up, and then we never will.)

comment:39 Changed 3 years ago by nickm

Milestone: Tor: 0.2.5.x-finalTor: 0.2.6.x-final
Status: needs_informationaccepted

comment:40 Changed 3 years ago by cypherpunks

ask someone else

Last edited 3 years ago by cypherpunks (previous) (diff)

comment:41 Changed 3 years ago by nickm

Status: acceptedneeds_information

Applied the diagnostic patch with an extra piece of information.

comment:42 Changed 3 years ago by nickm

Milestone: Tor: 0.2.6.x-finalTor: 0.2.7.x-final

comment:43 Changed 3 years ago by nickm

Keywords: 027-triaged-1-out added

Marking triaged-out items from first round of 0.2.7 triage.

comment:44 Changed 3 years ago by nickm

Milestone: Tor: 0.2.7.x-finalTor: 0.2.???

Make all non-needs_review, non-needs_revision, 027-triaged-1-out items belong to 0.2.???

comment:45 Changed 22 months ago by kernelcorn

Severity: Normal

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.

Last edited 22 months ago by kernelcorn (previous) (diff)

comment:46 Changed 22 months ago by torland

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().

comment:47 Changed 22 months ago by teor

Cc: teor added

comment:48 Changed 18 months ago by nickm

Keywords: 2016-bug-retrospective added

comment:49 Changed 14 months ago by bugzilla

Seems 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?)

comment:50 Changed 11 months ago by 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] 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().

comment:51 in reply to:  50 Changed 11 months ago by teor

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 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 point circuits are intentionally long-term, one-hop circuits.

I've split off this specific issue into #20613.

comment:52 Changed 11 months ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:53 Changed 10 months ago by nickm

Keywords: tor-03-unspecified-201612 added
Milestone: Tor: 0.3.???Tor: unspecified

Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.

comment:54 Changed 7 months ago by s7r

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).

comment:55 Changed 6 months ago by tom

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).

comment:56 Changed 6 months ago by cypherpunks

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.

comment:57 Changed 5 months ago by nickm

Keywords: tor-03-unspecified-201612 removed

Remove an old triaging keyword.

comment:58 Changed 5 months ago by nickm

Keywords: 025-triaged removed

remove an old triage keyword.

comment:59 Changed 5 months ago by nickm

Keywords: 027-triaged-in added

comment:60 Changed 5 months ago by nickm

Keywords: 027-triaged-in removed

comment:61 Changed 5 months ago by nickm

Keywords: 027-triaged-1-out removed

comment:62 Changed 5 months ago by nickm

Keywords: needs-insight needs-analysis maybe-logs-would-help added
Status: needs_informationnew
Note: See TracTickets for help on using tickets.