Tor Connection sometimes gives up connecting to PTs too early
As seen on https://jenkins.tails.boum.org/job/test_Tails_ISO_devel/2404/, when switching from direct connection to PTs, sometimes Tor will initially say "Delaying directory fetches: No running bridges" and about 32s later it'll say "Bootstrapped 10% (conn_done): Connected to a relay", then complete its bootstrap in a few seconds (remember it's Chutney though :)
But at that point Tor Connection has already given up. Once we have the fix for #18470 (closed) in, this will make the connection fail, while without this fix, tor would have bootstrapped eventually.
I've already seen something similar happen on https://jenkins.tails.boum.org/job/test_Tails_ISO_devel/2401/ However, there, 34s after "Delaying directory fetches: No running bridges", tor still had not made progress, and we aborted the scenario so we can't tell how much longer tor would have needed to bootstrap.
I'm wondering if "Delaying directory fetches" always takes 30s. If it does, then I suggest we bump TOR_SIGNOFLIFE_TIMEOUT
to something larger than 30s, such as 35 or 40 seconds. That goes in the opposite direction of what we would like on #18501 (closed) but until we have time to work on that one, I think it's the right thing to do.
Also note that we set TestingTorNetwork 1
in the test suite, which changes lots of timeouts compared to a regular tor client, so it's not 100% clear whether this exact scenario can happen in the real world.
Journal:
Aug 16 21:33:33 amnesia tca[12078]: INFO:tca.ui.main_window:Retrying with default bridges
Aug 16 21:33:33 amnesia tca[12078]: DEBUG:stem:SETCONF UseBridges="1" Bridge="obfs4 10.2.1.1:9941 51372B076603EB8E89E9871CCEE60C7E1DCEC0C3 cert=3pHeO7PekMN5dgdKXIBrj8jXJKa9fvM7FM+Kl2F2QAVnZ3rkViPfz6BvNMgLG/cDGCocUw iat-mode=0" Socks4Proxy Socks5Proxy HTTPSProxy Socks5ProxyUsername Socks5ProxyPassword HTTPSProxyAuthenticator (runtime: 0.0131)
Aug 16 21:33:34 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0022)
Aug 16 21:33:35 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0015)
Aug 16 21:33:36 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0016)
Aug 16 21:33:37 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0025)
Aug 16 21:33:38 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0015)
Aug 16 21:33:39 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0014)
Aug 16 21:33:40 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0016)
Aug 16 21:33:41 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0039)
Aug 16 21:33:42 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0016)
Aug 16 21:33:43 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0026)
Aug 16 21:33:44 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0016)
Aug 16 21:33:45 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0020)
Aug 16 21:33:46 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0018)
Aug 16 21:33:47 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0017)
Aug 16 21:33:48 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0016)
Aug 16 21:33:49 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0017)
Aug 16 21:33:50 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0017)
Aug 16 21:33:51 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0018)
Aug 16 21:33:52 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0021)
Aug 16 21:33:53 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0018)
Aug 16 21:33:54 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0017)
Aug 16 21:33:55 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0017)
Aug 16 21:33:56 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0019)
Aug 16 21:33:57 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0074)
Aug 16 21:33:58 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0018)
Aug 16 21:33:59 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0015)
Aug 16 21:34:00 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0014)
Aug 16 21:34:01 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0016)
Aug 16 21:34:02 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0014)
Aug 16 21:34:03 amnesia tca[12078]: DEBUG:stem:GETINFO status/bootstrap-phase (runtime: 0.0018)
Aug 16 21:34:04 amnesia tca[12078]: INFO:tca.ui.main_window:Failed with bridges
Tor log:
Aug 16 21:33:33.000 [notice] Switching to guard context "bridges" (was using "default")
Aug 16 21:33:33.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:34.000 [notice] Delaying directory fetches: No running bridges
Aug 16 21:33:34.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:35.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:36.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:37.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:38.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:39.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:40.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:41.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:42.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:43.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:44.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:45.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:47.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:48.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:49.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:50.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:51.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:52.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:53.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:54.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:55.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:56.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:57.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:58.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:33:59.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:34:00.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:34:01.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:34:02.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:34:03.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:34:04.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:34:05.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:34:06.000 [notice] Bootstrapped 10% (conn_done): Connected to a relay
Aug 16 21:34:06.000 [notice] Bootstrapped 14% (handshake): Handshaking with a relay
Aug 16 21:34:06.000 [notice] Bootstrapped 15% (handshake_done): Handshake with a relay done
Aug 16 21:34:06.000 [notice] Bootstrapped 20% (onehop_create): Establishing an encrypted directory connection
Aug 16 21:34:06.000 [notice] Bootstrapped 25% (requesting_status): Asking for networkstatus consensus
Aug 16 21:34:06.000 [notice] new bridge descriptor 'test041defbr' (fresh): $51372B076603EB8E89E9871CCEE60C7E1DCEC0C3~test041defbr [qPS2W7Ac3E/WizYagFLtzZD99glUDrdHbp8HpTqV8Hw] at 10.2.1.1
Aug 16 21:34:06.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:34:07.000 [notice] Bootstrapped 30% (loading_status): Loading networkstatus consensus
Aug 16 21:34:07.000 [notice] I learned some more directory information, but not enough to build a circuit: We have no usable consensus.
Aug 16 21:34:07.000 [notice] Bootstrapped 40% (loading_keys): Loading authority key certs
Aug 16 21:34:07.000 [notice] The current consensus has no exit nodes. Tor can only build internal paths, such as paths to onion services.
Aug 16 21:34:07.000 [notice] Bootstrapped 45% (requesting_descriptors): Asking for relay descriptors
Aug 16 21:34:07.000 [notice] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 0/35, and can only build 0% of likely paths. (We have 100% of guards bw, 0% of midpoint bw, and 0% of end bw (no exits in consensus, using mid) = 0% of path bw.)
Aug 16 21:34:07.000 [notice] Bootstrapped 50% (loading_descriptors): Loading relay descriptors
Aug 16 21:34:07.000 [notice] The current consensus contains exit nodes. Tor can build exit and internal paths.
Aug 16 21:34:07.000 [notice] Bootstrapped 75% (enough_dirinfo): Loaded enough directory info to build circuits
Aug 16 21:34:07.000 [notice] New control connection opened from 127.0.0.1.
Aug 16 21:34:08.000 [notice] Bootstrapped 76% (ap_conn_pt): Connecting to pluggable transport to build circuits
Aug 16 21:34:08.000 [notice] Bootstrapped 77% (ap_conn_done_pt): Connected to pluggable transport to build circuits
Aug 16 21:34:08.000 [notice] Bootstrapped 85% (ap_conn_done): Connected to a relay to build circuits
Aug 16 21:34:08.000 [notice] Bootstrapped 89% (ap_handshake): Finishing handshake with a relay to build circuits
Aug 16 21:34:08.000 [notice] Bootstrapped 90% (ap_handshake_done): Handshake finished with a relay to build circuits
Aug 16 21:34:08.000 [notice] Bootstrapped 95% (circuit_create): Establishing a Tor circuit
Aug 16 21:34:08.000 [notice] Bootstrapped 100% (done): Done