commit a1bf13ae243428224fa49afc85add3e1b4d31e29 Author: David Fifield <david@bamsoftware.com> Date: Sun Feb 12 10:54:49 2012 -0800 Use "LearnCircuitBuildTimeout 0" in exercise-flashproxy. flashproxy-exercise, despite getting a proxy in over 99% of cases, only bootstraps in about 75% of them. I suspect this is because of too-short timeouts. 75% is close to the designed-for 80% described here (2.4.1): https://gitweb.torproject.org/torspec.git?a=blob_plain;hb=HEAD;f=path-spec.t... Here are sample logs with extra circuit_expire_building debugging added by me. A successful run (note "it's still young"): Feb 12 00:13:21.000 [info] circuit_build_times_set_timeout(): Based on 1000 circuit times, it looks like we don't need to wait so long for circuits to finish. We will now assume a circuit is too slow to use after waiting 5 seconds. Feb 12 00:13:21.000 [info] circuit_build_times_set_timeout(): Circuit timeout data: 5051.643548ms, 60000.000000ms, Xm: 3092, a: 3.278575, r: 0.223000 ... Feb 12 00:13:23.000 [notice] Bootstrapped 10%: Finishing handshake with directory server. Feb 12 00:13:23.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer. Feb 12 00:13:23.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer. Feb 12 00:13:23.000 [info] connection_read_proxy_handshake(): Proxy Client: connection to 127.0.0.1:9001 successful Feb 12 00:13:23.000 [info] connection_tls_continue_handshake(): Client got a v3 cert! Moving on to v3 handshake. Feb 12 00:13:24.000 [info] circuit_expire_building(): created is 1329030803.139067; cutoff is 1329030801.611628 (2.526000). Feb 12 00:13:24.000 [info] circuit_expire_building(): it's still young (1.527439 seconds remain). Feb 12 00:13:24.000 [info] command_process_versions_cell(): Negotiated version 3 with [scrubbed]:9001; Sending cells: NETINFO Feb 12 00:13:24.000 [info] connection_or_client_learned_peer_id(): Connected to router $7C03D29CA58BE8EED5F483F31A2DEDF6FD7CC444 at 127.0.0.1:9001 without knowing its key. Hoping for the best. Feb 12 00:13:24.000 [notice] Learned fingerprint 7C03D29CA58BE8EED5F483F31A2DEDF6FD7CC444 for bridge 127.0.0.1:9001 Feb 12 00:13:24.000 [info] command_process_certs_cell(): Got some good certificates from [scrubbed]:9001: Authenticated it. Feb 12 00:13:24.000 [notice] Bootstrapped 15%: Establishing an encrypted directory connection. Feb 12 00:13:24.000 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE_FAST cell to '<unnamed>' Feb 12 00:13:24.000 [info] command_process_netinfo_cell(): Got good NETINFO cell from [scrubbed]:9001; OR connection is now open, using protocol version 3. Its ID digest is 7C03D29CA58BE8EED5F483F31A2DEDF6FD7CC444 Feb 12 00:13:25.000 [info] circuit_finish_handshake(): Finished building fast circuit hop: Feb 12 00:13:25.000 [info] exit circ (length 1, last hop 0000000000000000000000000000000000000000): $0000000000000000000000000000000000000000(open) Feb 12 00:13:25.000 [info] circuit_send_next_onion_skin(): circuit built! Feb 12 00:13:25.000 [notice] Bootstrapped 20%: Asking for networkstatus consensus. And an unsuccessful run (note "too old"→"Abandoning circ"→"no running bridges known"): Feb 12 03:13:21.000 [info] circuit_build_times_set_timeout(): Based on 1000 circuit times, it looks like we don't need to wait so long for circuits to finish. We will now assume a circuit is too slow to use after waiting 5 seconds. Feb 12 03:13:21.000 [info] circuit_build_times_set_timeout(): Circuit timeout data: 5056.857311ms, 60000.000000ms, Xm: 3193, a: 3.500420, r: 0.219000 ... Feb 12 03:13:23.000 [notice] Bootstrapped 10%: Finishing handshake with directory server. Feb 12 03:13:23.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer. Feb 12 03:13:23.000 [info] connection_edge_process_inbuf(): data from edge while in 'waiting for circuit' state. Leaving it on buffer. Feb 12 03:13:23.000 [info] connection_read_proxy_handshake(): Proxy Client: connection to 127.0.0.1:9001 successful Feb 12 03:13:24.000 [info] circuit_expire_building(): created is 1329041603.765838; cutoff is 1329041602.236589 (2.528000). Feb 12 03:13:24.000 [info] circuit_expire_building(): it's still young (1.529249 seconds remain). Feb 12 03:13:25.000 [info] connection_tls_continue_handshake(): Client got a v3 cert! Moving on to v3 handshake. Feb 12 03:13:25.000 [info] circuit_expire_building(): created is 1329041603.765838; cutoff is 1329041603.237411 (2.528000). Feb 12 03:13:25.000 [info] circuit_expire_building(): it's still young (0.528427 seconds remain). Feb 12 03:13:26.000 [info] command_process_versions_cell(): Negotiated version 3 with [scrubbed]:9001; Sending cells: NETINFO Feb 12 03:13:26.000 [info] connection_or_client_learned_peer_id(): Connected to router $7C03D29CA58BE8EED5F483F31A2DEDF6FD7CC444 at 127.0.0.1:9001 without knowing its key. Hoping for the best. Feb 12 03:13:26.000 [notice] Learned fingerprint 7C03D29CA58BE8EED5F483F31A2DEDF6FD7CC444 for bridge 127.0.0.1:9001 Feb 12 03:13:26.000 [info] command_process_certs_cell(): Got some good certificates from [scrubbed]:9001: Authenticated it. Feb 12 03:13:26.000 [notice] Bootstrapped 15%: Establishing an encrypted directory connection. Feb 12 03:13:26.000 [info] circuit_send_next_onion_skin(): First hop: finished sending CREATE_FAST cell to '<unnamed>' Feb 12 03:13:26.000 [info] command_process_netinfo_cell(): Got good NETINFO cell from [scrubbed]:9001; OR connection is now open, using protocol version 3. Its ID digest is 7C03D29CA58BE8EED5F483F31A2DEDF6FD7CC444 Feb 12 03:13:26.000 [info] circuit_expire_building(): created is 1329041603.765838; cutoff is 1329041604.238231 (2.528000). Feb 12 03:13:26.000 [info] circuit_expire_building(): too old (0.472393 seconds). Feb 12 03:13:26.000 [info] circuit_expire_building(): Abandoning circ 127.0.0.1:9001:14929 (state 0:doing handshakes, purpose 5) Feb 12 03:13:26.000 [info] exit circ (length 1, last hop 0000000000000000000000000000000000000000): $0000000000000000000000000000000000000000(waiting for keys) Feb 12 03:13:26.000 [info] circuit_build_failed(): Our circuit failed to get a response from the first hop (127.0.0.1:9001). I'm going to try to rotate to a better connection. Feb 12 03:13:26.000 [info] connection_ap_fail_onehop(): Closing one-hop stream to '$0000000000000000000000000000000000000000/127.0.0.1' because the OR conn just failed. Feb 12 03:13:26.000 [info] smartlist_choose_node_by_bandwidth_weights(): Empty routerlist passed in to consensus weight node selection for rule weight as guard Feb 12 03:13:26.000 [info] smartlist_choose_node_by_bandwidth(): Empty routerlist passed in to old node selection for rule weight as guard Feb 12 03:13:26.000 [info] should_delay_dir_fetches(): delaying dir fetches (no running bridges known) Feb 12 03:13:26.000 [notice] no known bridge descriptors running yet; stalling Feb 12 03:13:26.000 [info] _connection_free(): Freeing linked Socks connection [waiting for circuit] with 62 bytes on inbuf, 0 on outbuf. --- experiments/exercise/exercise.sh | 2 +- 1 files changed, 1 insertions(+), 1 deletions(-) diff --git a/experiments/exercise/exercise.sh b/experiments/exercise/exercise.sh index 834bd48..0557062 100755 --- a/experiments/exercise/exercise.sh +++ b/experiments/exercise/exercise.sh @@ -25,7 +25,7 @@ PIDS_TO_KILL+=($!) sleep 20 -"$TOR" UseBridges 1 Bridge 127.0.0.1:9001 Socks4Proxy 127.0.0.1:$LOCAL_PORT & +"$TOR" UseBridges 1 Bridge 127.0.0.1:9001 Socks4Proxy 127.0.0.1:$LOCAL_PORT LearnCircuitBuildTimeout 0 & PIDS_TO_KILL+=($!) sleep 60