Opened 7 months ago

Closed 7 months ago

#31527 closed defect (fixed)

In Tor Browser nightly, Tor fails to boostrap, hangs at 50%

Reported by: pospeselr Owned by: nickm
Priority: Medium Milestone:
Component: Core Tor/Tor Version:
Severity: Normal Keywords: tbb-needs
Cc: brade, mcs Actual Points:
Parent ID: #29211 Points:
Reviewer: Sponsor: Sponsor31-must

Description

Tor Log:

8/26/19, 20:54:01.877 [NOTICE] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections. 
8/26/19, 20:54:01.877 [NOTICE] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections. 
8/26/19, 20:54:01.878 [NOTICE] DisableNetwork is set. Tor will not make or accept non-control network connections. Shutting down all existing connections. 
8/26/19, 20:54:01.878 [NOTICE] Opening Socks listener on 127.0.0.1:9150 
8/26/19, 20:54:01.878 [NOTICE] Opened Socks listener on 127.0.0.1:9150 
8/26/19, 20:54:01.878 [NOTICE] Renaming old configuration file to "C:\Users\user\Desktop\Tor Browser GeKo Test2\Browser\TorBrowser\Data\Tor\torrc.orig.1" 
8/26/19, 20:54:02.292 [NOTICE] Bootstrapped 5% (conn): Connecting to a relay 
8/26/19, 20:54:02.622 [NOTICE] Bootstrapped 10% (conn_done): Connected to a relay 
8/26/19, 20:54:03.285 [NOTICE] Bootstrapped 14% (handshake): Handshaking with a relay 
8/26/19, 20:54:03.579 [NOTICE] Bootstrapped 15% (handshake_done): Handshake with a relay done 
8/26/19, 20:54:03.580 [NOTICE] Bootstrapped 20% (onehop_create): Establishing an encrypted directory connection 
8/26/19, 20:54:03.863 [NOTICE] Bootstrapped 25% (requesting_status): Asking for networkstatus consensus 
8/26/19, 20:54:04.155 [NOTICE] Bootstrapped 30% (loading_status): Loading networkstatus consensus 
8/26/19, 20:54:06.827 [NOTICE] I learned some more directory information, but not enough to build a circuit: We have no usable consensus. 
8/26/19, 20:54:07.168 [NOTICE] Bootstrapped 40% (loading_keys): Loading authority key certs 
8/26/19, 20:54:08.289 [WARN] Your configuration excludes 100% of all possible guards. That's likely to make you stand out from the rest of the world. 
8/26/19, 20:54:08.289 [NOTICE] Switching to guard context "restricted" (was using "default") 
8/26/19, 20:54:08.289 [NOTICE] The current consensus has no exit nodes. Tor can only build internal paths, such as paths to onion services. 
8/26/19, 20:54:08.289 [NOTICE] Bootstrapped 45% (requesting_descriptors): Asking for relay descriptors 
8/26/19, 20:54:08.290 [NOTICE] I learned some more directory information, but not enough to build a circuit: We need more microdescriptors: we have 0/0, 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.) 
8/26/19, 20:54:08.807 [NOTICE] Bootstrapped 50% (loading_descriptors): Loading relay descriptors 
8/26/19, 20:54:09.210 [NOTICE] The current consensus contains exit nodes. Tor can build exit and internal paths. 

Child Tickets

Attachments (1)

debug.log.gz (237.6 KB) - added by sysrqb 7 months ago.

Download all attachments as: .zip

Change History (12)

comment:1 Changed 7 months ago by pospeselr

Keywords: tbb-needs added

comment:2 Changed 7 months ago by gk

Component: Applications/Tor BrowserCore Tor/Tor
Priority: Very HighMedium

comment:3 Changed 7 months ago by nickm

Does this happen every time you start tor, or only some times? Is it with 0.4.1.x or 0.4.2.x, or both? Is it windows-only, or does it happen on other platforms?

Changed 7 months ago by sysrqb

Attachment: debug.log.gz added

comment:4 in reply to:  3 Changed 7 months ago by sysrqb

Replying to nickm:

Does this happen every time you start tor, or only some times? Is it with 0.4.1.x or 0.4.2.x, or both? Is it windows-only, or does it happen on other platforms?

It seems this is happening every time tor browser is started - probably on all platforms (at least Windows 64-bit and Linux 64-bit). I haven't experimented with running tor directly, yet.

Aug 26 21:22:25.000 [notice] Tor 0.4.2.0-alpha-dev (git-6ba05eea8efcfc1f) opening log file.

comment:5 Changed 7 months ago by sysrqb

Running this directly doesn't result in any bootstrapping problems:

/home/user/tor-browser_en-US/Browser/TorBrowser/Tor/tor --defaults-torrc /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc-defaults -f /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc DataDirectory /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor GeoIPFile /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip GeoIPv6File /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip6 HashedControlPassword 16:e7332c020b4455796082d608cebf3e8a15193f0dc14ded66f1ba6a5713 +__ControlPort 9151 +__SocksPort "127.0.0.1:9150 IPv6Traffic PreferIPv6"

torrc-defaults:

# torrc-defaults for Tor Browser
#
# DO NOT EDIT THIS FILE
#
# This file is distributed with Tor Browser and SHOULD NOT be modified (it
# may be overwritten during the next Tor Browser update). To customize your
# Tor configuration, shut down Tor Browser and edit the torrc file.
#
# If non-zero, try to write to disk less frequently than we would otherwise.
AvoidDiskWrites 1
# Where to send logging messages.  Format is minSeverity[-maxSeverity]
# (stderr|stdout|syslog|file FILENAME).
Log notice stdout
Log debug file debug.log
CookieAuthentication 1
DormantCanceledByStartup 1
## obfs4proxy configuration
ClientTransportPlugin obfs2,obfs3,obfs4,scramblesuit exec ./TorBrowser/Tor/PluggableTransports/obfs4proxy

## meek configuration
ClientTransportPlugin meek exec ./TorBrowser/Tor/PluggableTransports/meek-client-torbrowser -- ./TorBrowser/Tor/PluggableTransports/meek-client

## snowflake configuration
ClientTransportPlugin snowflake exec ./TorBrowser/Tor/PluggableTransports/snowflake-client -url https://snowflake-broker.azureedge.net/ -front ajax.aspnetcdn.com -ice stun:stun.l.google.com:19302

torrc:

# This file was generated by Tor; if you edit it, comments will not be preserved
# The old torrc file was renamed to torrc.orig.1 or similar, and Tor will ignore it

DataDirectory /home/multipass/tor-browser_en-US/Browser/TorBrowser/Data/Tor
GeoIPFile /home/multipass/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip
GeoIPv6File /home/multipass/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip6

comment:6 Changed 7 months ago by teor

Parent ID: #29211
Sponsor: Sponsor31-must

Probably caused by #29211.

comment:7 Changed 7 months ago by teor

Owner: changed from tbb-team to nickm
Status: newassigned

comment:8 Changed 7 months ago by sysrqb

It seems like this is the conversation between tor browser and tor:

$ ./tor-browser_en-US/Browser/start-tor-browser -v
Gtk-Message: 18:28:44.476: Failed to load module "canberra-gtk-module"
Gtk-Message: 18:28:44.477: Failed to load module "canberra-gtk-module"
[08-26 22:28:44] Torbutton INFO: Torbutton debug output ready
[08-26 22:28:44] Torbutton INFO: Component Load 5: New CookieJarSelector @torproject.org/cookie-jar-selector;1
[08-26 22:28:44] Torbutton INFO: Cookie jar selector got profile-after-change
[08-26 22:28:44] Torbutton INFO: domain isolator: set up isolating circuits by domain
[08-26 22:28:44] Torbutton INFO: Component Load 0: New DragDropFilter.
[08-26 22:28:44] Torbutton INFO: Startup Observer created
[08-26 22:28:44] Torbutton INFO: This is a Tor Browser's XPCOM
[08-26 22:28:44] TorLauncher INFO: debug output ready
[08-26 22:28:44] TorLauncher INFO: SOCKS port type: TCP
[08-26 22:28:44] TorLauncher INFO: SOCKS host: 127.0.0.1
[08-26 22:28:44] TorLauncher INFO: SOCKS port: 9150
[08-26 22:28:44] Torbutton INFO: Reset socks host to 127.0.0.1
[08-26 22:28:44] Torbutton INFO: Reset socks port to 9150
[08-26 22:28:44] Torbutton INFO: Synced network settings to environment.
[08-26 22:28:44] Torbutton INFO: Listening for message from NoScript.
[08-26 22:28:44] Torbutton INFO: Reset socks host to 127.0.0.1
[08-26 22:28:44] Torbutton INFO: Reset socks port to 9150
[08-26 22:28:44] Torbutton INFO: Synced network settings to environment.
Fontconfig warning: "/home/user/tor-browser_en-US/Browser/TorBrowser/Data/fontconfig/fonts.conf", line 145: blank doesn't take any effect anymore. please remove it from your fonts.conf
[08-26 22:28:44] TorLauncher DBUG: Starting /home/user/tor-browser_en-US/Browser/TorBrowser/Tor/tor
[08-26 22:28:44] TorLauncher DBUG:   --defaults-torrc
[08-26 22:28:44] TorLauncher DBUG:   /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc-defaults
[08-26 22:28:44] TorLauncher DBUG:   -f
[08-26 22:28:44] TorLauncher DBUG:   /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc
[08-26 22:28:44] TorLauncher DBUG:   DataDirectory
[08-26 22:28:44] TorLauncher DBUG:   /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor
[08-26 22:28:44] TorLauncher DBUG:   GeoIPFile
[08-26 22:28:44] TorLauncher DBUG:   /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip
[08-26 22:28:44] TorLauncher DBUG:   GeoIPv6File
[08-26 22:28:44] TorLauncher DBUG:   /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip6
[08-26 22:28:44] TorLauncher DBUG:   HashedControlPassword
[08-26 22:28:44] TorLauncher DBUG:   16:4b446c03a1b054976099156ab91beca2c4eab46a864f634587b61b89b4
[08-26 22:28:44] TorLauncher DBUG:   +__ControlPort
[08-26 22:28:44] TorLauncher DBUG:   9151
[08-26 22:28:44] TorLauncher DBUG:   +__SocksPort
[08-26 22:28:44] TorLauncher DBUG:   127.0.0.1:9150 IPv6Traffic PreferIPv6 KeepAliveIsolateSOCKSAuth
[08-26 22:28:44] TorLauncher DBUG:   __OwningControllerProcess
[08-26 22:28:44] TorLauncher DBUG:   12907
Aug 26 22:28:44.657 [notice] Tor 0.4.2.0-alpha-dev (git-6ba05eea8efcfc1f) running on Linux with Libevent 2.1.8-stable, OpenSSL 1.1.1c, Zlib 1.2.11, Liblzma N/A, and Libzstd N/A.
Aug 26 22:28:44.657 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Aug 26 22:28:44.657 [notice] This version is not a stable Tor release. Expect more bugs than usual.
Aug 26 22:28:44.657 [notice] Tor is running with Rust integration. Please report any bugs you encounter.
Aug 26 22:28:44.657 [notice] Read configuration file "/home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc-defaults".
Aug 26 22:28:44.658 [notice] Read configuration file "/home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc".
Aug 26 22:28:44.658 [notice] Opening Socks listener on 127.0.0.1:9150
Aug 26 22:28:44.658 [notice] Opened Socks listener on 127.0.0.1:9150
Aug 26 22:28:44.659 [notice] Opening Control listener on 127.0.0.1:9151
Aug 26 22:28:44.659 [notice] Opened Control listener on 127.0.0.1:9151
Aug 26 22:28:44.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.
Aug 26 22:28:44.000 [notice] Parsing GEOIP IPv4 file /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip.
[08-26 22:28:44] TorLauncher DBUG: Opening control connection to 127.0.0.1:9151
[08-26 22:28:44] TorLauncher DBUG: Sending Tor command: AUTHENTICATE 416f714a60283371427c3c287b3c7a49
Aug 26 22:28:44.000 [notice] Parsing GEOIP IPv6 file /home/user/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip6.
Aug 26 22:28:44.000 [notice] Bootstrapped 0% (starting): Starting
Aug 26 22:28:44.000 [notice] Starting with guard context "default"
Aug 26 22:28:44.000 [notice] New control connection opened from 127.0.0.1.
[08-26 22:28:44] TorLauncher DBUG: Command response: 250 OK
[08-26 22:28:44] TorLauncher DBUG: Sending Tor command: TAKEOWNERSHIP
[08-26 22:28:44] TorLauncher DBUG: Command response: 250 OK
[08-26 22:28:44] TorLauncher DBUG: Sending Tor command: RESETCONF __OwningControllerProcess
Aug 26 22:28:44.000 [notice] All routers are down or won't exit or are Excluded -- choosing a doomed exit at random.
Aug 26 22:28:44.000 [warn] No exits in ExitNodes, except possibly those excluded by your configuration,  seem to be running: can't choose an exit.
Aug 26 22:28:44.000 [warn] Failed to choose an exit server
Aug 26 22:28:44.000 [notice] Our circuit 0 (id: 1) died due to an invalid selected path, purpose General-purpose client. This may be a torrc configuration issue, or a bug.
[08-26 22:28:44] TorLauncher DBUG: Command response: 250 OK
[08-26 22:28:44] TorLauncher DBUG: Opening control connection to 127.0.0.1:9151
[08-26 22:28:44] TorLauncher DBUG: Sending Tor command: AUTHENTICATE 416f714a60283371427c3c287b3c7a49
Aug 26 22:28:45.000 [notice] New control connection opened from 127.0.0.1.
[08-26 22:28:45] TorLauncher DBUG: Command response: 250 OK
[08-26 22:28:45] TorLauncher DBUG: Sending Tor command: SETEVENTS STATUS_CLIENT NOTICE WARN ERR
[08-26 22:28:45] TorLauncher DBUG: Command response: 250 OK
[08-26 22:28:45] TorLauncher DBUG: Sending Tor command: GETINFO status/bootstrap-phase
[08-26 22:28:45] TorLauncher DBUG: Command response: 250-status/bootstrap-phase=NOTICE BOOTSTRAP PROGRESS=0 TAG=starting SUMMARY="Starting"
[08-26 22:28:45] TorLauncher DBUG: Command response: 250 OK
[08-26 22:28:45] TorLauncher DBUG: readTorSettings ----------------------------------------------
[08-26 22:28:45] TorLauncher DBUG: Sending Tor command: GETCONF UseBridges
[08-26 22:28:45] TorLauncher DBUG: Command response: 250 UseBridges=0
[08-26 22:28:45] TorLauncher DBUG: Sending Tor command: GETCONF Bridge
[08-26 22:28:45] TorLauncher DBUG: Command response: 250 Bridge
[08-26 22:28:45] TorLauncher DBUG: Sending Tor command: GETCONF Socks4Proxy
[08-26 22:28:45] TorLauncher DBUG: Command response: 250 Socks4Proxy
[08-26 22:28:45] TorLauncher DBUG: Sending Tor command: GETCONF Socks5Proxy
[08-26 22:28:45] TorLauncher DBUG: Command response: 250 Socks5Proxy
[08-26 22:28:45] TorLauncher DBUG: Sending Tor command: GETCONF HTTPSProxy
[08-26 22:28:45] TorLauncher DBUG: Command response: 250 HTTPSProxy
[08-26 22:28:45] TorLauncher DBUG: readTorSettings done; didSucceed: true
[08-26 22:28:45] TorLauncher DBUG: Sending Tor command: GETINFO status/bootstrap-phase
[08-26 22:28:45] TorLauncher DBUG: Command response: 250-status/bootstrap-phase=NOTICE BOOTSTRAP PROGRESS=0 TAG=starting SUMMARY="Starting"
[08-26 22:28:45] TorLauncher DBUG: Command response: 250 OK
[08-26 22:28:45] TorLauncher DBUG: initDialog done
Aug 26 22:28:45.000 [warn] Could not find a node that matches the configured _HSLayer2Nodes set
Aug 26 22:28:46.000 [warn] Failed to find node for hop #2 of our path. Discarding this circuit.
[08-26 22:28:46] TorLauncher DBUG: Event response: 650 WARN Could not find a node that matches the configured _HSLayer2Nodes set 
[08-26 22:28:46] TorLauncher DBUG: Event response: 650 WARN Failed to find node for hop #2 of our path. Discarding this circuit. 
Aug 26 22:28:47.000 [warn] Failed to find node for hop #2 of our path. Discarding this circuit.
[08-26 22:28:47] TorLauncher DBUG: Event response: 650 WARN Failed to find node for hop #2 of our path. Discarding this circuit.

comment:9 Changed 7 months ago by mcs

Cc: brade mcs added

comment:10 Changed 7 months ago by teor

Status: assignedneeds_information

Does the #31495 fix also fix this issue?

comment:11 in reply to:  10 Changed 7 months ago by gk

Resolution: fixed
Status: needs_informationclosed

Replying to teor:

Does the #31495 fix also fix this issue?

Yes, that's fixed with a tor compiled from 7fa624537cded385 as well.

Note: See TracTickets for help on using tickets.