Opened 3 months ago

Last modified 2 months ago

#30746 new defect

Tor relay bootstrap hangs: missing descriptors for 1/2 of our primary entry guards

Reported by: atagar Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: needs-proposal
Cc: Actual Points:
Parent ID: #21969 Points:
Reviewer: Sponsor:

Description

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).

Child Tickets

Attachments (1)

tor_hang_info_log.txt (312.4 KB) - added by atagar 3 months ago.

Download all attachments as: .zip

Change History (5)

Changed 3 months ago by atagar

Attachment: tor_hang_info_log.txt added

comment:1 Changed 3 months ago by teor

Parent ID: #21969
Summary: Tor bootstrap hangsTor bootstrap hangs: missing descriptors for 1/2 of our primary entry guards

Looks like an instance of tor bug #21969

comment:2 Changed 3 months ago by teor

Summary: Tor bootstrap hangs: missing descriptors for 1/2 of our primary entry guardsTor relay bootstrap hangs: missing descriptors for 1/2 of our primary entry guards

comment:3 Changed 3 months ago by teor

Keywords: needs-proposal added

#16844 and #21969 have conflicting goals, so we need to write a proposal that balances these goals. See #30817.

comment:4 Changed 2 months ago by nickm

Milestone: Tor: unspecified
Note: See TracTickets for help on using tickets.