[tor-bugs] #30746 [Core Tor/Tor]: Tor bootstrap hangs

Tue Jun 4 01:28:30 UTC 2019

#30746: Tor bootstrap hangs
------------------------------+--------------------
     Reporter:  atagar        |      Owner:  (none)
         Type:  defect        |     Status:  new
     Priority:  Medium        |  Milestone:
    Component:  Core Tor/Tor  |    Version:
     Severity:  Normal        |   Keywords:
Actual Points:                |  Parent ID:
       Points:                |   Reviewer:
      Sponsor:                |
------------------------------+--------------------
 Hi network team. Stem's integ tests impose a 90 second timeout when
 bootstrapping. The vast majority of time it succeeds without issue, but
 sometimes bootstrapping hangs, exceeding this.

 I have debug level logs available but it's pretty big so attaching info
 level logs instead. If debug logging would be useful just let me know.

 {{{
 % du -h ~/Desktop/tor_hang_debug_log.txt
 13M     /home/atagar/Desktop/tor_hang_debug_log.txt
 }}}

 Notice runlevel logs are as follows...

 {{{
 Jun 03 18:10:04.000 [notice] Tor 0.4.1.1-alpha-dev (git-180048e013c06ee6)
 opening new log file.
 Jun 03 18:10:04.131 [notice] Tor 0.4.1.1-alpha-dev (git-180048e013c06ee6)
 running on Linux with Libevent 2.0.21-stable, OpenSSL 1.0.2g, Zlib 1.2.8,
 Liblzma N/A, and Libzstd N/A.
 Jun 03 18:10:04.132 [notice] Tor can't help you if you use it wrong! Learn
 how to be safe at https://www.torproject.org/download/download#warning
 Jun 03 18:10:04.132 [notice] This version is not a stable Tor release.
 Expect more bugs than usual.
 Jun 03 18:10:04.132 [notice] Read configuration file
 "/home/atagar/Desktop/stem/test/data/torrc".
 Jun 03 18:10:04.136 [notice] Your ContactInfo config option is not set.
 Please consider setting it, so we can contact you if your server is
 misconfigured or something else goes wrong.
 Jun 03 18:10:04.137 [notice] Based on detected system memory,
 MaxMemInQueues is set to 5917 MB. You can override this by setting
 MaxMemInQueues by hand.
 Jun 03 18:10:04.137 [warn] ControlPort is open, but no authentication
 method has been configured.  This means that any program on your computer
 can reconfigure your Tor.  That's bad!  You should upgrade your Tor
 controller as soon as possible.
 Jun 03 18:10:04.138 [notice] Opening Socks listener on 127.0.0.1:1112
 Jun 03 18:10:04.138 [notice] Opened Socks listener on 127.0.0.1:1112
 Jun 03 18:10:04.138 [notice] Opening Control listener on 127.0.0.1:1111
 Jun 03 18:10:04.139 [notice] Opened Control listener on 127.0.0.1:1111
 Jun 03 18:10:04.139 [notice] Opening OR listener on 0.0.0.0:1113
 Jun 03 18:10:04.139 [notice] Opened OR listener on 0.0.0.0:1113
 Jun 03 18:10:04.139 [warn] Fixing permissions on directory
 /home/atagar/Desktop/stem/test/data
 Jun 03 18:10:04.000 [warn] Your log may contain sensitive information -
 you're logging more than "notice". Don't log unless it serves an important
 reason. Overwrite the log afterwards.
 Jun 03 18:10:04.000 [notice] Configured to measure directory request
 statistics, but no GeoIP database found. Please specify a GeoIP database
 using the GeoIPFile option.
 Jun 03 18:10:04.000 [notice] You are running a new relay. Thanks for
 helping the Tor network! If you wish to know what will happen in the
 upcoming weeks regarding its usage, have a look at
 https://blog.torproject.org/blog/lifecycle-of-a-new-relay
 Jun 03 18:10:04.000 [notice] It looks like I need to generate and sign a
 new medium-term signing key, because I don't have one. To do that, I need
 to load (or create) the permanent master identity key. If the master
 identity key was not moved or encrypted with a passphrase, this will be
 done automatically and no further action is required. Otherwise, provide
 the necessary data using 'tor --keygen' to do it manually.
 Jun 03 18:10:04.000 [notice] Your Tor server's identity key fingerprint is
 'Unnamed D65E957D19700A27C67D89C314DE822B0CA6CD7D'
 Jun 03 18:10:04.000 [notice] Bootstrapped 0% (starting): Starting
 Jun 03 18:10:04.000 [notice] Starting with guard context "default"
 Jun 03 18:10:04.000 [notice] Guessed our IP address as 71.231.87.208
 (source: 86.59.21.38).
 Jun 03 18:10:06.000 [notice] I learned some more directory information,
 but not enough to build a circuit: We have no usable consensus.
 Jun 03 18:10:07.000 [notice] The current consensus has no exit nodes. Tor
 can only build internal paths, such as paths to onion services.
 Jun 03 18:10:07.000 [notice] I learned some more directory information,
 but not enough to build a circuit: We need more microdescriptors: we have
 0/6563, and can only build 0% of likely paths. (We have 0% of guards bw,
 0% of midpoint bw, and 0% of end bw (no exits in consensus, using mid) =
 0% of path bw.)
 Jun 03 18:10:07.000 [notice] Bootstrapped 5% (conn): Connecting to a relay
 Jun 03 18:10:07.000 [notice] Bootstrapped 10% (conn_done): Connected to a
 relay
 Jun 03 18:10:07.000 [notice] The current consensus contains exit nodes.
 Tor can build exit and internal paths.
 Jun 03 18:10:08.000 [notice] Bootstrapped 14% (handshake): Handshaking
 with a relay
 Jun 03 18:10:08.000 [notice] Bootstrapped 15% (handshake_done): Handshake
 with a relay done
 Jun 03 18:10:08.000 [notice] Bootstrapped 50% (loading_descriptors):
 Loading relay descriptors
 Jun 03 18:10:09.000 [notice] Bootstrapped 55% (loading_descriptors):
 Loading relay descriptors
 Jun 03 18:10:09.000 [notice] Bootstrapped 60% (loading_descriptors):
 Loading relay descriptors
 Jun 03 18:10:09.000 [notice] Bootstrapped 65% (loading_descriptors):
 Loading relay descriptors
 Jun 03 18:10:09.000 [notice] Bootstrapped 70% (loading_descriptors):
 Loading relay descriptors
 Jun 03 18:10:10.000 [warn] Please upgrade! This version of Tor (0.4.1.1
 -alpha-dev) is not recommended, according to the directory authorities.
 Recommended versions are:
 0.2.9.15,0.2.9.16,0.2.9.17,0.3.4.10,0.3.4.11,0.3.5.7,0.3.5.8,0.4.0.1-alpha,0.4.0.2-alpha,0.4.0.3-alpha,0.4.0.4-rc,0.4.0.5,0.4.0.6,0.4.1.1-alpha,0.4.1.2-alpha
 Jun 03 18:10:10.000 [notice] I learned some more directory information,
 but not enough to build a circuit: We're missing descriptors for 1/2 of
 our primary entry guards (total microdescriptors: 5662/6563).

 [ hangs for 76 more seconds, then stem times out bootstrapping ]
 }}}

 Debug log ends with...

 {{{
 % tail ~/Desktop/tor_hang_debug_log.txt
 Jun 03 18:11:32.000 [debug] conn_read_callback(): socket 116 wants to
 read.
 Jun 03 18:11:32.000 [debug] connection_buf_read_from_socket(): 116:
 starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
 Jun 03 18:11:32.000 [debug] connection_buf_read_from_socket(): After TLS
 read of 514: 543 read, 0 written
 Jun 03 18:11:32.000 [debug] connection_or_process_cells_from_inbuf(): 116:
 starting, inbuf_datalen 514 (0 pending in tls object).
 Jun 03 18:11:32.000 [debug] connection_or_process_cells_from_inbuf(): 116:
 starting, inbuf_datalen 0 (0 pending in tls object).
 Jun 03 18:11:33.000 [debug] conn_read_callback(): socket 129 wants to
 read.
 Jun 03 18:11:33.000 [debug] connection_buf_read_from_socket(): 129:
 starting, inbuf_datalen 0 (0 pending in tls object). at_most 16448.
 Jun 03 18:11:33.000 [debug] connection_buf_read_from_socket(): After TLS
 read of 514: 543 read, 0 written
 Jun 03 18:11:33.000 [debug] connection_or_process_cells_from_inbuf(): 129:
 starting, inbuf_datalen 514 (0 pending in tls object).
 Jun 03 18:11:33.000 [debug] connection_or_process_cells_from_inbuf(): 129:
 starting, inbuf_datalen 0 (0 pending in tls object).
 }}}

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/30746>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online