[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]
Re: [tor-bugs] #1772 [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: mikeperry
Type: defect | Status: assigned
Priority: major | Milestone: Tor: 0.2.2.x-final
Component: Tor Client | Version:
Keywords: | Parent:
------------------------+---------------------------------------------------
Comment(by arma):
Ah ha. Mystery partially solved. Here's what I was seeing:
{{{
Sep 29 08:40:20.807 [debug] onion_pick_cpath_exit(): Launching a one-hop
circuit
for dir tunnel.
Sep 29 08:40:20.808 [info] onion_pick_cpath_exit(): Using requested exit
node 'P
andora32'
Sep 29 08:40:20.808 [debug] onion_extend_cpath(): Path is 0 long; we want
1
Sep 29 08:40:20.808 [debug] onion_extend_cpath(): Chose router Pandora32
for hop 1 (exit is Pandora32)
Sep 29 08:40:20.808 [debug] onion_extend_cpath(): Path is complete: 1
steps long
Sep 29 08:40:20.808 [debug] circuit_handle_first_hop(): Looking for
firsthop '91.208.34.32:443'
Sep 29 08:40:20.808 [info] circuit_handle_first_hop(): Next router is
Pandora32: Connection in progress; waiting.
Sep 29 08:40:20.808 [debug] circuit_handle_first_hop(): connecting in
progress (or finished). Good.
Sep 29 08:40:21.803 [debug] circuit_expire_building(): 1285764021 60000 30
30 1285763991
Sep 29 08:40:21.803 [debug] circuit_expire_building(): 1285763990
1285763991
Sep 29 08:40:21.803 [debug] circuit_build_times_add_time(): Adding circuit
build time 2147483646
Sep 29 08:40:21.803 [info] circuit_expire_building(): Abandoning circ 0
(state 2:connecting to server, purpose 13)
Sep 29 08:40:21.803 [info] exit circ (length 1, exit Pandora32):
Pandora32(closed)
Sep 29 08:40:21.803 [info] circuit_build_failed(): Our circuit died before
the first hop with no connection
Sep 29 08:40:21.803 [info] connection_ap_fail_onehop(): Closing one-hop
stream to '$DFE540DC6BE5C822223D6A2347DC9C04E75E4509/91.208.34.32' because
the OR conn just failed.
}}}
And the question is "why the heck is it abandoning the circuit one second
after launching it".
The first answer is that it's not, it's abandoning a circuit 30 seconds
after launching it:
{{{
Sep 29 08:39:50.688 [info] update_consensus_networkstatus_downloads():
Launching ns networkstatus consensus download.
Sep 29 08:39:50.690 [debug] smartlist_choose_by_bandwidth_weights():
Choosing node for rule weight as directory based on weights Wg=0.000000
Wm=1.000000 We=0.029000 Wd=0.003900 with total bw 567996336.300000
Sep 29 08:39:50.690 [debug] directory_initiate_command_rend(): anonymized
0, use_begindir 1.
Sep 29 08:39:50.690 [debug] directory_initiate_command_rend(): Initiating
consensus network-status fetch
Sep 29 08:39:50.690 [info] connection_ap_make_link(): Making internal
direct tunnel to 91.208.34.32:443 ...
Sep 29 08:39:50.690 [debug] connection_add_impl(): new conn type Socks,
socket -1, address (Tor_internal), n_conns 6.
Sep 29 08:39:50.690 [debug] onion_pick_cpath_exit(): Launching a one-hop
circuit for dir tunnel.
Sep 29 08:39:50.690 [info] onion_pick_cpath_exit(): Using requested exit
node 'Pandora32'
Sep 29 08:39:50.690 [debug] onion_extend_cpath(): Path is 0 long; we want
1
Sep 29 08:39:50.690 [debug] onion_extend_cpath(): Chose router Pandora32
for hop 1 (exit is Pandora32)
Sep 29 08:39:50.691 [debug] onion_extend_cpath(): Path is complete: 1
steps long
Sep 29 08:39:50.691 [debug] circuit_handle_first_hop(): Looking for
firsthop '91.208.34.32:443'
Sep 29 08:39:50.691 [info] circuit_handle_first_hop(): Next router is
Pandora32: Not connected. Connecting.
Sep 29 08:39:50.691 [debug] connection_connect(): Connecting to
"91.208.34.32":443.
Sep 29 08:39:50.691 [debug] connection_connect(): Connection to
"91.208.34.32":443 in progress (sock 13).
Sep 29 08:39:50.691 [debug] connection_add_impl(): new conn type OR,
socket 13, address 91.208.34.32, n_conns 7.
Sep 29 08:39:50.691 [debug] circuit_handle_first_hop(): connecting in
progress (or finished). Good.
}}}
So why is the new circuit launched at 08:40:20.807? On the first go-round
through circuit_expire_building() we notice that its purpose is C_GENERAL,
and switch it:
{{{
if (victim->purpose != CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT) {
victim->purpose = CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT;
circuit_build_times_count_timeout(&circ_times,
first_hop_succeeded);
continue;
}
}}}
Then we notice that there's an outstanding directory fetch request, with
no circuit to handle it, so we launch one. Then one second later, we're
back in circuit_expire_building() and it's time to kill the circuit
because it's purpose CIRCUIT_PURPOSE_C_MEASURE_TIMEOUT.
(This behavior only happens when I've got 100 or fewer circuit build
times, since it's only then that circ_times.timeout_ms equals
circ_times.close_ms.)
Sure enough, 30 seconds later,
{{{
Sep 29 08:40:51.859 [debug] circuit_build_times_add_time(): Adding circuit
build time 2147483646
Sep 29 08:40:51.859 [info] circuit_expire_building(): Abandoning circ 0
(state 2:connecting to server, purpose 13)
Sep 29 08:40:51.859 [info] exit circ (length 1, exit Pandora32):
Pandora32(closed)
Sep 29 08:40:51.859 [info] circuit_build_failed(): Our circuit died before
the first hop with no connection
}}}
--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/1772#comment:8>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
_______________________________________________
tor-bugs mailing list
tor-bugs@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs