Counting circuit timeouts when we can't establish any TLS connection
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 (closed): 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 (closed): 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.