[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]
[tor-bugs] #1772 [Tor - Tor client]: Counting circuit timeouts when we can't establish any TLS connection
#1772: Counting circuit timeouts when we can't establish any TLS connection
------------------------------+---------------------------------------------
Reporter: arma | Owner:
Type: defect | Status: new
Priority: normal | Milestone:
Component: Tor - Tor client | Version:
Keywords: | Parent:
------------------------------+---------------------------------------------
Running 856a36c43439da as a client
When my laptop loses its internet connection, I get this in my log:
Jul 28 22:43:09.572 [info] connection_ap_make_link(): Making internal
direct tunnel to 85.17.59.169:19090 ...
Jul 28 22:43:09.572 [debug] onion_pick_cpath_exit(): Launching a one-hop
circuit for dir tunnel.
Jul 28 22:43:09.572 [info] onion_pick_cpath_exit(): Using requested exit
node 'privacyvpndotnet01'
Jul 28 22:43:09.572 [debug] onion_extend_cpath(): Path is 0 long; we want
1
Jul 28 22:43:09.572 [debug] onion_extend_cpath(): Chose router
privacyvpndotnet01 for hop 1 (exit is privacyvpndotnet01)
Jul 28 22:43:09.572 [debug] onion_extend_cpath(): Path is complete: 1
steps long
Jul 28 22:43:09.572 [debug] circuit_handle_first_hop(): Looking for
firsthop '85.17.59.169:19090'
Jul 28 22:43:09.572 [info] circuit_handle_first_hop(): Next router is
privacyvpndotnet01: Not connected. Connecting.
Jul 28 22:43:09.572 [debug] connection_connect(): Connecting to
"85.17.59.169":19090.
Jul 28 22:43:09.572 [debug] connection_connect(): Connection to
"85.17.59.169":19090 in progress (sock 13).
Jul 28 22:43:09.572 [debug] connection_add(): new conn type OR, socket 13,
address 85.17.59.169, n_conns 16.
Jul 28 22:43:20.316 [debug] connection_or_finished_connecting(): OR
connect() to router at 85.17.59.169:19090 finished.
Jul 28 22:43:20.316 [debug] connection_tls_start_handshake(): starting TLS
handshake on fd 13
Jul 28 22:43:41.629 [debug] onion_pick_cpath_exit(): Launching a one-hop
circuit for dir tunnel.
Jul 28 22:43:41.629 [info] onion_pick_cpath_exit(): Using requested exit
node 'privacyvpndotnet01'
Jul 28 22:43:41.630 [debug] onion_extend_cpath(): Path is 0 long; we want
1
Jul 28 22:43:41.630 [debug] onion_extend_cpath(): Chose router
privacyvpndotnet01 for hop 1 (exit is privacyvpndotnet01)
Jul 28 22:43:41.630 [debug] onion_extend_cpath(): Path is complete: 1
steps long
Jul 28 22:43:41.630 [debug] circuit_handle_first_hop(): Looking for
firsthop '85.17.59.169:19090'
Jul 28 22:43:41.630 [info] circuit_handle_first_hop(): Next router is
privacyvpndotnet01: Connection in progress; waiting.
Jul 28 22:43:41.630 [debug] circuit_handle_first_hop(): connecting in
progress (or finished). Good.
Jul 28 22:43:41.630 [debug] conn_write_callback(): socket 17 wants to
write.
Jul 28 22:43:42.633 [debug] circuit_build_times_add_time(): Adding circuit
build time 2147483646
Jul 28 22:43:42.635 [info] circuit_build_times_get_xm(): Xm mode #0: 925
23
Jul 28 22:43:42.635 [info] circuit_build_times_get_xm(): Xm mode #1: 1425
15
Jul 28 22:43:42.635 [info] circuit_build_times_get_xm(): Xm mode #2: 1025
13
Jul 28 22:43:42.635 [notice] Based on 1000 circuit times, it looks like we
need to wait longer for circuits to finish. We will now assume a circuit
is too slow to use after waiting 64 seconds.
Jul 28 22:43:42.635 [info] circuit_build_times_set_timeout(): Circuit
timeout data: 64381.435070ms, 2148375.414446ms, Xm: 1097, a: 0.395221, r:
0.164000
Jul 28 22:43:42.636 [info] circuit_expire_building(): Abandoning circ 0
(state 2:connecting to server, purpose 13)
Jul 28 22:43:42.636 [info] exit circ (length 1, exit privacyvpndotnet01):
$58F9C92572EA8BF85F38C87467CA1542AD8D6F65(closed)
Jul 28 22:43:42.636 [info] circuit_build_failed(): Our circuit died before
the first hop with no connection
Jul 28 22:43:42.636 [info] connection_ap_fail_onehop(): Closing one-hop
stream to '$58F9C92572EA8BF85F38C87467CA1542AD8D6F65/85.17.59.169' because
the OR conn just failed.
Jul 28 22:43:42.641 [info] connection_dir_client_reached_eof(): 'fetch'
response not all here, but we're at eof. Closing.
Jul 28 22:43:42.642 [debug] conn_close_if_marked(): Cleaning up connection
(fd -1).
Jul 28 22:43:42.642 [info] connection_dir_request_failed(): Giving up on
directory server at '85.17.59.169'; retrying
Jul 28 22:43:56.474 [debug] connection_tls_finish_handshake(): tls
handshake with 85.17.59.169 done. verifying.
Jul 28 22:43:56.475 [debug] connection_or_check_valid_tls_handshake(): The
certificate seems to be valid on outgoing connection with
85.17.59.169:19090
Jul 28 22:44:14.749 [debug] circuit_build_times_add_time(): Adding circuit
build time 2147483646
Jul 28 22:44:14.751 [info] circuit_build_times_get_xm(): Xm mode #0: 925
23
Jul 28 22:44:14.751 [info] circuit_build_times_get_xm(): Xm mode #1: 1425
15
Jul 28 22:44:14.751 [info] circuit_build_times_get_xm(): Xm mode #2: 1025
13
Jul 28 22:44:14.751 [notice] Based on 1000 circuit times, it looks like we
need to wait longer for circuits to finish. We will now assume a circuit
is too slow to use after waiting 66 seconds.
Jul 28 22:44:14.751 [info] circuit_build_times_set_timeout(): Circuit
timeout data: 65576.560832ms, 2223200.500411ms, Xm: 1097, a: 0.393444, r:
0.165000
Jul 28 22:44:14.751 [info] circuit_expire_building(): Abandoning circ
85.17.59.169:19090:46080 (state 0:doing handshakes, purpose 13)
Jul 28 22:44:14.752 [info] exit circ (length 1, exit privacyvpndotnet01):
$58F9C92572EA8BF85F38C87467CA1542AD8D6F65(waiting for keys)
Jul 28 22:44:14.752 [info] circuit_build_failed(): Our circuit failed to
get a response from the first hop (85.17.59.169:19090). I'm going to try
to rotate to a better connection.
Jul 28 22:44:14.752 [debug] connection_or_send_destroy(): Sending destroy
(circID 46080).
A) Why are we counting cbt timeouts for one-hop circs? I guess in
circuit_expire_building() we do in fact compute begindir_cutoff as a
function of circ_times.timeout_ms. Ok.
B) If the first hop fails to establish, we shouldn't necessarily be
blaming our circuit build timeout. It could be that we don't have a
network. But it could also be that our cbt is too small. Hm.
C) What's up with this "expire it twice" business? Are we marking the
circuit to state MEASURE the first time, then when the TLS finally
finishes, we're killing it again and calling
circuit_build_times_count_close()?
I get lots of these TLS conn failures in quick succession when my network
goes away, and CBT is punishing me for it.
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/1772>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online