Skip to content
Snippets Groups Projects
New look: Off

Client builds and timeouts tons of circs to connect to HS

    • Closed (moved) Issue created by George Kadianakis @asn

    I was testing #23101 (moved) by connecting to a few hidden services, and I noticed that my client would create about 7 intro circs and 7 rend circs before finally connecting to a single HS. Apparently it was creating circs and timing them and then making more.

    I'm not sure if this is caused by the current damaged state of the network, but it definitely is not making it better if a single client is causing so many circuits.

    I'll be attaching logs in the next comment.

    To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information

    Child items ...

    • Activity

    • George Kadianakis changed milestone to %Tor: unspecified

      changed milestone to %Tor: unspecified

    • George Kadianakis added 034-removed-20180328 034-triage-20180328 component::core tor/tor milestone::Tor: unspecified performance points::2 priority::medium severity::normal status::new tor-hs type::defect labels

      added 034-removed-20180328 034-triage-20180328 component::core tor/tor milestone::Tor: unspecified performance points::2 priority::medium severity::normal status::new tor-hs type::defect labels

    • George Kadianakis
      George Kadianakis @asn ·
      Author

      Trac:
      info.log.gz

    • George Kadianakis
      George Kadianakis @asn ·
      Author

      Please see attached info.log.gz for logs here.

      You can see one connection to a v3 HS at:

      Dec 22 14:18:54.000 [info] connection_handle_listener_read(): New SOCKS connection opened from 127.0.0.1.
Dec 22 14:18:54.000 [info] connection_ap_handle_onion(): No descriptor found in our cache for [scrubbed]. Fetching.

      and then a series of circuit constructions and cannibalizations:

      Dec 22 14:18:55.000 [warn] Cannibalizing circ 3209247593 (id: 15) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:18:55.000 [warn] Cannibalizing circ 3363556098 (id: 11) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:18:59.000 [warn] Cannibalizing circ 2737292824 (id: 16) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:18:59.000 [warn] Cannibalizing circ 4162479077 (id: 18) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:02.000 [warn] Cannibalizing circ 2698199725 (id: 20) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:02.000 [warn] Cannibalizing circ 3242037898 (id: 19) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:05.000 [warn] Cannibalizing circ 2267218611 (id: 23) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:05.000 [warn] Cannibalizing circ 2441688608 (id: 22) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:08.000 [warn] Cannibalizing circ 4103029933 (id: 25) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:08.000 [warn] Cannibalizing circ 3233300841 (id: 21) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:13.000 [warn] Cannibalizing circ 3874617006 (id: 26) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:13.000 [warn] Cannibalizing circ 2322608187 (id: 27) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:16.000 [warn] Cannibalizing circ 2805126006 (id: 30) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:16.000 [warn] Cannibalizing circ 2956657524 (id: 29) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:19.000 [warn] Cannibalizing circ 3521109109 (id: 28) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:19.000 [warn] Cannibalizing circ 2592602427 (id: 31) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:24.000 [warn] Cannibalizing circ 2703721722 (id: 34) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:24.000 [warn] Cannibalizing circ 3251400289 (id: 33) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:30.000 [warn] Cannibalizing circ 2382439824 (id: 36) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:30.000 [warn] Cannibalizing circ 3020576912 (id: 35) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:35.000 [warn] Cannibalizing circ 3700419328 (id: 37) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:35.000 [warn] Cannibalizing circ 3823492187 (id: 38) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:38.000 [warn] Cannibalizing circ 4269648492 (id: 40) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:38.000 [warn] Cannibalizing circ 2708250606 (id: 39) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:43.000 [warn] Cannibalizing circ 3340988672 (id: 42) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:43.000 [warn] Cannibalizing circ 3282187317 (id: 43) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:46.000 [warn] Cannibalizing circ 3168062844 (id: 32) for purpose 6 (Hidden service client: Connecting to intro point)
Dec 22 14:19:51.000 [warn] Cannibalizing circ 4001996127 (id: 49) for purpose 9 (Hidden service client: Establishing rendezvous point)
Dec 22 14:19:51.000 [warn] Cannibalizing circ 2704454500 (id: 48) for purpose 6 (Hidden service client: Connecting to intro point)

      see how aggressive it is. Then after all these cannibalizations happen we start receiving tons of RENDEZVOUS2 in most of them (some of them got timed out):

      Dec 22 14:19:53.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 2737292824.
Dec 22 14:19:54.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 2698199725.
Dec 22 14:19:57.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 2267218611.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3874617006.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 2805126006.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3521109109.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3700419328.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 4103029933.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 2703721722.
Dec 22 14:20:50.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3209247593.
Dec 22 14:20:52.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 4001996127.
Dec 22 14:20:55.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3340915042.
Dec 22 14:20:56.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 2382439824.
Dec 22 14:20:57.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3340988672.
Dec 22 14:20:57.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 4269648492.

      In general, it seems like we are way too aggressive in timing out HS circuits and popping up new ones. For example see 3209247593 which is the first rend circ we ever cannibalized at 14:18:55 getting timed out after 4 seconds:

      Dec 22 14:18:59.000 [info] circuit_expire_building(): Marking circ 3209247593 (state 4:open, purpose 11) as timed-out HS circ

      In the end we actually received a RENDEZVOUS2 on that circuit but it was 2 minutes late:

      Dec 22 14:20:50.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3209247593.

      Some more things to note:

      It's weird how we receive all the RENDEZVOUS2 cells together:

      Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3874617006.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 2805126006.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3521109109.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3700419328.
Dec 22 14:20:49.000 [info] connection_edge_reached_eof(): conn (fd 58) reached eof. Closing.
Dec 22 14:20:49.000 [info] connection_edge_reached_eof(): conn (fd 46) reached eof. Closing.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 4103029933.
Dec 22 14:20:49.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 2703721722.
Dec 22 14:20:50.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3209247593.
Dec 22 14:20:52.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 4001996127.
Dec 22 14:20:53.000 [info] connection_edge_reached_eof(): conn (fd 49) reached eof. Closing.
Dec 22 14:20:53.000 [info] connection_edge_reached_eof(): conn (fd 50) reached eof. Closing.
Dec 22 14:20:53.000 [info] connection_edge_reached_eof(): conn (fd 36) reached eof. Closing.
Dec 22 14:20:54.000 [info] connection_edge_reached_eof(): conn (fd 51) reached eof. Closing.
Dec 22 14:20:54.000 [info] connection_edge_reached_eof(): conn (fd 43) reached eof. Closing.
Dec 22 14:20:54.000 [info] connection_edge_reached_eof(): conn (fd 52) reached eof. Closing.
Dec 22 14:20:54.000 [info] connection_edge_reached_eof(): conn (fd 44) reached eof. Closing.
Dec 22 14:20:55.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3340915042.
Dec 22 14:20:55.000 [info] connection_edge_reached_eof(): conn (fd 53) reached eof. Closing.
Dec 22 14:20:55.000 [info] connection_edge_reached_eof(): conn (fd 56) reached eof. Closing.
Dec 22 14:20:56.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 2382439824.
Dec 22 14:20:57.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 3340988672.
Dec 22 14:20:57.000 [info] hs_client_receive_rendezvous2(): Got RENDEZVOUS2 cell from hidden service on circuit 4269648492.

      How come this happened? Did the guard spit everything together? Is it the scheduler that got them piped? Or what?

      Also there are tons of data cell dropped, unknown stream` messages that I have no idea what they mean:

      Dec 22 14:20:41.000 [info] connection_edge_process_relay_cell(): data cell dropped, unknown stream (streamid 4032).
    • Roger Dingledine
      Roger Dingledine @arma ·

      Replying to asn:

      In general, it seems like we are way too aggressive in timing out HS circuits and popping up new ones. For example see 3209247593 which is the first rend circ we ever cannibalized at 14:18:55 getting timed out after 4 seconds:

      Sounds like your circuitbuildtimeout was 4 seconds.

      I wonder if your Tor should be recognizing that its cbt is wrong after this many failures. Do failures of this kind of circuit contribute towards Tor deciding that its cbt is too low? We should look for edge cases where the cbt can be too low yet some kinds of circuit failures don't contribute toward resetting it.

    • David Goulet
      David Goulet @dgoulet ·

      Moving a bunch of tickets from 033 to 034.

      Trac:
      Milestone: Tor: 0.3.3.x-final to Tor: 0.3.4.x-final

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Trac:
      Keywords: N/A deleted, 034-triage-20180328 added

    • Nick Mathewson
      Nick Mathewson @nickm ·

      Per our triage process, these tickets are pending removal from 0.3.4.

      Trac:
      Keywords: N/A deleted, 034-removed-20180328 added

    • Nick Mathewson
      Nick Mathewson @nickm ·

      These tickets, tagged with 034-removed-*, are no longer in-scope for 0.3.4. We can reconsider any of them, if time permits.

      Trac:
      Milestone: Tor: 0.3.4.x-final to Tor: unspecified

    • Trac changed time estimate to 16h

      changed time estimate to 16h

    • Trac moved to tpo/core/tor#24712 (closed)

      moved to tpo/core/tor#24712 (closed)

    Please register or sign in to reply