Opened 19 months ago

Last modified 16 months ago

#24712 new defect

Client builds and timeouts tons of circs to connect to HS

Reported by: asn Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tor-hs, performance, 034-triage-20180328, 034-removed-20180328
Cc: Actual Points:
Parent ID: Points: 2
Reviewer: Sponsor:

Description

I was testing #23101 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.

Child Tickets

Attachments (1)

info.log.gz (31.5 KB) - added by asn 19 months ago.

Download all attachments as: .zip

Change History (7)

Changed 19 months ago by asn

Attachment: info.log.gz added

comment:1 Changed 19 months ago by asn

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

comment:2 in reply to:  1 Changed 19 months ago by 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.

comment:3 Changed 18 months ago by dgoulet

Milestone: Tor: 0.3.3.x-finalTor: 0.3.4.x-final

Moving a bunch of tickets from 033 to 034.

comment:4 Changed 16 months ago by nickm

Keywords: 034-triage-20180328 added

comment:5 Changed 16 months ago by nickm

Keywords: 034-removed-20180328 added

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

comment:6 Changed 16 months ago by nickm

Milestone: Tor: 0.3.4.x-finalTor: unspecified

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

Note: See TracTickets for help on using tickets.