[tor-bugs] #1772 [Tor Client]: Counting circuit timeouts when we can't establish any TLS connection

[Tor Bug Tracker & Wiki]

#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