[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]
[tor-bugs] Re: #847 [Tor - Tor client]: Extreme values in downloading directory information

To: undisclosed-recipients:;
Subject: [tor-bugs] Re: #847 [Tor - Tor client]: Extreme values in downloading directory information
From: "Tor Bug Tracker & Wiki" <torproject-admin@xxxxxxxxxxxxxx>
Date: Tue, 06 Jul 2010 21:06:16 -0000
Auto-submitted: auto-generated
Delivered-to: archiver@xxxxxxxx
Delivered-to: tor-bugs-outgoing@xxxxxxxx
Delivered-to: tor-bugs@xxxxxxxxxxxxxx
Delivery-date: Tue, 06 Jul 2010 17:06:24 -0400
In-reply-to: <047.0c7af15767a16675781b9ac7342fc498@xxxxxxxxxxxxxx>
References: <047.0c7af15767a16675781b9ac7342fc498@xxxxxxxxxxxxxx>
Reply-to: tor-assistants@xxxxxxxxxxxxxx
Sender: owner-tor-bugs@xxxxxxxxxxxxxx
#847: Extreme values in downloading directory information
-------------------------------+--------------------------------------------
  Reporter:  karsten           |       Owner:  nickm             
      Type:  defect            |      Status:  assigned          
  Priority:  minor             |   Milestone:  Tor: 0.2.1.x-final
 Component:  Tor - Tor client  |     Version:  0.2.1.5-alpha     
Resolution:  None              |    Keywords:                    
    Parent:                    |  
-------------------------------+--------------------------------------------
Changes (by nickm):

  * milestone:  0.2.1.x-final => Tor: 0.2.1.x-final


Old description:

> Sometimes it takes a really long time until Tor has downloaded enough
> directory information to build circuits. In an experiment with 1,220
> attempts to start new Tor instances, the following times were measured
> for
> downloading directory information (in seconds):
>
>  Min. 1st Qu.  Median    Mean 3rd Qu.    Max.
> 1.732   5.016   7.602  35.680  17.210 681.300
>
> The highest 50 values are:
>
> 141.560 151.013 151.880 164.672 169.010 184.269 184.280 187.733 207.903
> 222.899 238.430 248.529 250.513 252.959 265.249 269.104 281.840 295.144
> 307.421 307.719 307.863 307.940 308.403 308.438 308.672 308.730 308.741
> 309.053 309.293 309.357 309.839 310.033 310.259 310.275 311.930 313.203
> 313.385 313.597 315.260 317.916 318.327 325.420 362.017 367.175 452.797
> 487.972 489.534 537.029 615.759 681.341
>
> A look at the log files reveals that Tor attempts to fetch network
> statuses or authority certificates from a single directory that is
> unavailable at the moment. The request times out after 120 seconds, and
> another attempt is made---possibly to the same directory. During the
> measurements, dannenberg appeared to be offline, so that attempts to that
> authority timed out:
>
> egrep
> "Bootstrap|86.59.21.38|216.224.124.114|213.73.91.31|141.13.4.202|128.31.0.34|194.109.206.212"
> log
> Nov 01 08:42:02.390 [info] Bootstrapped 0%: Starting.
> Nov 01 08:42:02.390 [info] connection_ap_make_link(): Making internal
> direct tunnel to 194.109.206.212:443 ...
> Nov 01 08:42:02.391 [notice] Bootstrapped 5%: Connecting to directory
> server.
> Nov 01 08:42:02.393 [info] connection_ap_make_link(): Making internal
> direct tunnel to 213.73.91.31:443 ...
> Nov 01 08:42:02.393 [info] directory_send_command(): Downloading
> consensus from 213.73.91.31:443 using /tor/status-
> vote/current/consensus.z
> Nov 01 08:42:02.413 [notice] Bootstrapped 10%: Finishing handshake with
> directory server.
> Nov 01 08:42:02.603 [info] command_process_versions_cell(): Negotiated
> version 2 with 194.109.206.212; sending NETINFO.
> Nov 01 08:42:02.604 [notice] Bootstrapped 15%: Establishing an encrypted
> directory connection.
> Nov 01 08:42:02.605 [info] command_process_netinfo_cell(): Got good
> NETINFO cell from 194.109.206.212; OR connection is now open, using
> protocol version 2
> Nov 01 08:42:02.693 [notice] Bootstrapped 20%: Asking for networkstatus
> consensus.
> Nov 01 08:42:02.790 [info] connection_dir_client_reached_eof(): Received
> authority certificates (size 9804) from server '194.109.206.212:443'
> Nov 01 08:42:35.033 [info] command_process_versions_cell(): Negotiated
> version 2 with 213.73.91.31; sending NETINFO.
> Nov 01 08:44:02.857 [info] connection_ap_expire_beginning(): Tried for
> 120 seconds to get a connection to 213.73.91.31:443. Giving up. (waiting
> for circuit)
> Nov 01 08:44:02.857 [info] connection_ap_make_link(): Making internal
> direct tunnel to 213.73.91.31:443 ...
> Nov 01 08:44:02.858 [info] directory_send_command(): Downloading
> consensus from 213.73.91.31:443 using /tor/status-
> vote/current/consensus.z
> Nov 01 08:46:02.317 [info] connection_ap_expire_beginning(): Tried for
> 120 seconds to get a connection to 213.73.91.31:443. Giving up. (waiting
> for circuit)
> Nov 01 08:47:07.565 [info] connection_ap_make_link(): Making internal
> direct tunnel to 213.73.91.31:443 ...
> Nov 01 08:47:07.565 [info] directory_send_command(): Downloading
> consensus from 213.73.91.31:443 using /tor/status-
> vote/current/consensus.z
> Nov 01 08:47:35.669 [info] run_connection_housekeeping(): Expiring non-
> open OR connection to fd 16 (213.73.91.31:443).
> Nov 01 08:47:35.669 [info] connection_ap_fail_onehop(): Closing onehop
> stream to '$7BE683E65D48141321C5ED92F075C55364AC7123/213.73.91.31'
> because the OR conn just failed.
> Nov 01 08:53:13.929 [info] connection_ap_make_link(): Making internal
> direct tunnel to 216.224.124.114:9090 ...
> Nov 01 08:53:13.930 [info] directory_send_command(): Downloading
> consensus from 216.224.124.114:9090 using /tor/status-
> vote/current/consensus.z
> Nov 01 08:53:15.788 [info] command_process_versions_cell(): Negotiated
> version 2 with 216.224.124.114; sending NETINFO.
> Nov 01 08:53:15.788 [info] command_process_netinfo_cell(): Got good
> NETINFO cell from 216.224.124.114; OR connection is now open, using
> protocol version 2
> Nov 01 08:53:16.677 [notice] Bootstrapped 25%: Loading networkstatus
> consensus.
> Nov 01 08:53:21.322 [info] connection_dir_client_reached_eof(): Received
> consensus directory (size 256583) from server '216.224.124.114:9090'
> Nov 01 08:53:21.345 [notice] Bootstrapped 45%: Asking for relay
> descriptors.
> Nov 01 08:53:21.742 [notice] Bootstrapped 50%: Loading relay descriptors.
> Nov 01 08:53:22.105 [notice] Bootstrapped 59%: Loading relay descriptors.
> Nov 01 08:53:22.652 [notice] Bootstrapped 69%: Loading relay descriptors.
> Nov 01 08:53:23.092 [notice] Bootstrapped 80%: Connecting to the Tor
> network.
> Nov 01 08:53:24.408 [notice] Bootstrapped 90%: Establishing a Tor
> circuit.
> Nov 01 08:53:25.394 [notice] Bootstrapped 100%: Done.
> Nov 01 08:53:59.577 [info] connection_ap_make_link(): Making internal
> anonymized tunnel to 141.13.4.202:443 ...
> Nov 01 09:08:24.117 [info] run_connection_housekeeping(): Expiring non-
> used OR connection to fd 15 (194.109.206.212:443) [Not in clique mode].
>
> Possible fixes could be shorter timeouts or parallel requests. However,
> these fixes have side-effects on network load. Maybe there is also a way
> to
> detect and exclude unavailable directory more quickly (requests are
> tunneled directory requests using one-hop circuits).
>

> [Automatically added by flyspray2trac: Operating System: All]

New description:

 Sometimes it takes a really long time until Tor has downloaded enough
 directory information to build circuits. In an experiment with 1,220
 attempts to start new Tor instances, the following times were measured for
 downloading directory information (in seconds):

  Min. 1st Qu.  Median    Mean 3rd Qu.    Max.
 1.732   5.016   7.602  35.680  17.210 681.300

 The highest 50 values are:

 141.560 151.013 151.880 164.672 169.010 184.269 184.280 187.733 207.903
 222.899 238.430 248.529 250.513 252.959 265.249 269.104 281.840 295.144
 307.421 307.719 307.863 307.940 308.403 308.438 308.672 308.730 308.741
 309.053 309.293 309.357 309.839 310.033 310.259 310.275 311.930 313.203
 313.385 313.597 315.260 317.916 318.327 325.420 362.017 367.175 452.797
 487.972 489.534 537.029 615.759 681.341

 A look at the log files reveals that Tor attempts to fetch network
 statuses or authority certificates from a single directory that is
 unavailable at the moment. The request times out after 120 seconds, and
 another attempt is made---possibly to the same directory. During the
 measurements, dannenberg appeared to be offline, so that attempts to that
 authority timed out:

 egrep
 "Bootstrap|86.59.21.38|216.224.124.114|213.73.91.31|141.13.4.202|128.31.0.34|194.109.206.212"
 log
 Nov 01 08:42:02.390 [info] Bootstrapped 0%: Starting.
 Nov 01 08:42:02.390 [info] connection_ap_make_link(): Making internal
 direct tunnel to 194.109.206.212:443 ...
 Nov 01 08:42:02.391 [notice] Bootstrapped 5%: Connecting to directory
 server.
 Nov 01 08:42:02.393 [info] connection_ap_make_link(): Making internal
 direct tunnel to 213.73.91.31:443 ...
 Nov 01 08:42:02.393 [info] directory_send_command(): Downloading consensus
 from 213.73.91.31:443 using /tor/status-vote/current/consensus.z
 Nov 01 08:42:02.413 [notice] Bootstrapped 10%: Finishing handshake with
 directory server.
 Nov 01 08:42:02.603 [info] command_process_versions_cell(): Negotiated
 version 2 with 194.109.206.212; sending NETINFO.
 Nov 01 08:42:02.604 [notice] Bootstrapped 15%: Establishing an encrypted
 directory connection.
 Nov 01 08:42:02.605 [info] command_process_netinfo_cell(): Got good
 NETINFO cell from 194.109.206.212; OR connection is now open, using
 protocol version 2
 Nov 01 08:42:02.693 [notice] Bootstrapped 20%: Asking for networkstatus
 consensus.
 Nov 01 08:42:02.790 [info] connection_dir_client_reached_eof(): Received
 authority certificates (size 9804) from server '194.109.206.212:443'
 Nov 01 08:42:35.033 [info] command_process_versions_cell(): Negotiated
 version 2 with 213.73.91.31; sending NETINFO.
 Nov 01 08:44:02.857 [info] connection_ap_expire_beginning(): Tried for 120
 seconds to get a connection to 213.73.91.31:443. Giving up. (waiting for
 circuit)
 Nov 01 08:44:02.857 [info] connection_ap_make_link(): Making internal
 direct tunnel to 213.73.91.31:443 ...
 Nov 01 08:44:02.858 [info] directory_send_command(): Downloading consensus
 from 213.73.91.31:443 using /tor/status-vote/current/consensus.z
 Nov 01 08:46:02.317 [info] connection_ap_expire_beginning(): Tried for 120
 seconds to get a connection to 213.73.91.31:443. Giving up. (waiting for
 circuit)
 Nov 01 08:47:07.565 [info] connection_ap_make_link(): Making internal
 direct tunnel to 213.73.91.31:443 ...
 Nov 01 08:47:07.565 [info] directory_send_command(): Downloading consensus
 from 213.73.91.31:443 using /tor/status-vote/current/consensus.z
 Nov 01 08:47:35.669 [info] run_connection_housekeeping(): Expiring non-
 open OR connection to fd 16 (213.73.91.31:443).
 Nov 01 08:47:35.669 [info] connection_ap_fail_onehop(): Closing onehop
 stream to '$7BE683E65D48141321C5ED92F075C55364AC7123/213.73.91.31' because
 the OR conn just failed.
 Nov 01 08:53:13.929 [info] connection_ap_make_link(): Making internal
 direct tunnel to 216.224.124.114:9090 ...
 Nov 01 08:53:13.930 [info] directory_send_command(): Downloading consensus
 from 216.224.124.114:9090 using /tor/status-vote/current/consensus.z
 Nov 01 08:53:15.788 [info] command_process_versions_cell(): Negotiated
 version 2 with 216.224.124.114; sending NETINFO.
 Nov 01 08:53:15.788 [info] command_process_netinfo_cell(): Got good
 NETINFO cell from 216.224.124.114; OR connection is now open, using
 protocol version 2
 Nov 01 08:53:16.677 [notice] Bootstrapped 25%: Loading networkstatus
 consensus.
 Nov 01 08:53:21.322 [info] connection_dir_client_reached_eof(): Received
 consensus directory (size 256583) from server '216.224.124.114:9090'
 Nov 01 08:53:21.345 [notice] Bootstrapped 45%: Asking for relay
 descriptors.
 Nov 01 08:53:21.742 [notice] Bootstrapped 50%: Loading relay descriptors.
 Nov 01 08:53:22.105 [notice] Bootstrapped 59%: Loading relay descriptors.
 Nov 01 08:53:22.652 [notice] Bootstrapped 69%: Loading relay descriptors.
 Nov 01 08:53:23.092 [notice] Bootstrapped 80%: Connecting to the Tor
 network.
 Nov 01 08:53:24.408 [notice] Bootstrapped 90%: Establishing a Tor circuit.
 Nov 01 08:53:25.394 [notice] Bootstrapped 100%: Done.
 Nov 01 08:53:59.577 [info] connection_ap_make_link(): Making internal
 anonymized tunnel to 141.13.4.202:443 ...
 Nov 01 09:08:24.117 [info] run_connection_housekeeping(): Expiring non-
 used OR connection to fd 15 (194.109.206.212:443) [Not in clique mode].

 Possible fixes could be shorter timeouts or parallel requests. However,
 these fixes have side-effects on network load. Maybe there is also a way
 to
 detect and exclude unavailable directory more quickly (requests are
 tunneled directory requests using one-hop circuits).


 [Automatically added by flyspray2trac: Operating System: All]

--

-- 
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/847#comment:10>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online
Prev by Author: [tor-bugs] Re: #1319 [Tor - Tor client]: FAIL test.c:517: assert(fabs(circuit_build_times_cdf(...
Next by Author: [tor-bugs] #1666 [Tor - Tor client]: SOCKS handling should accept (and ignore) password auth.
Previous by thread: [tor-bugs] Re: #1319 [Tor - Tor client]: FAIL test.c:517: assert(fabs(circuit_build_times_cdf(...
Next by thread: [tor-bugs] #1666 [Tor - Tor client]: SOCKS handling should accept (and ignore) password auth.
Index(es):
- Author
- Thread