[tor-bugs] #24712 [Core Tor/Tor]: Client builds and timeouts tons of circs to connect to HS
Tor Bug Tracker & Wiki
blackhole at torproject.org
Fri Dec 22 12:50:17 UTC 2017
#24712: Client builds and timeouts tons of circs to connect to HS
---------------------------------+------------------------------------
Reporter: asn | Owner: (none)
Type: defect | Status: new
Priority: Medium | Milestone: Tor: 0.3.3.x-final
Component: Core Tor/Tor | Version:
Severity: Normal | Resolution:
Keywords: tor-hs, performance | Actual Points:
Parent ID: | Points: 2
Reviewer: | Sponsor:
---------------------------------+------------------------------------
Comment (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).
}}}
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/24712#comment:1>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
More information about the tor-bugs
mailing list