TB 8.0.4 - Tor is not shutting down properly
Error message: Tor exited during startup. This might be due to an error in your torrc file, a bug in Tor or another program on your system, or faulty hardware. Until you fix the underlying problem and restart Tor, Tor Browser will not start.
Session log - see attached tor-error.log
Trac:
Username: jb.1234abcd
Activity
Trac:
Username: jb.1234abcd-
This time a good run, with some WARNING, but no tor process leftover:
[jb@r61i ~]$ ./Downloads/tor-browser_en-US/Browser/firefox Jan 05 10:09:43.274 [notice] Tor 0.3.4.9 (git-4ac3ccf2863b86e7) running on Linux with Libevent 2.1.8-stable, OpenSSL 1.0.2q, Zlib 1.2.11, Liblzma N/A, and Libzstd N/A. Jan 05 10:09:43.274 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning Jan 05 10:09:43.274 [notice] Read configuration file "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc-defaults". Jan 05 10:09:43.274 [notice] Read configuration file "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc". Jan 05 10:09:43.281 [notice] Scheduler type KIST has been enabled. Jan 05 10:09:43.281 [notice] Opening Socks listener on 127.0.0.1:9150 Jan 05 10:09:43.281 [notice] Opening Control listener on 127.0.0.1:9151 Jan 05 10:09:43.000 [notice] Parsing GEOIP IPv4 file /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip. Jan 05 10:09:43.000 [notice] Parsing GEOIP IPv6 file /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip6. Jan 05 10:09:44.000 [notice] Bootstrapped 0%: Starting Jan 05 10:09:45.000 [notice] Starting with guard context "default" Jan 05 10:09:45.000 [notice] Bootstrapped 80%: Connecting to the Tor network Jan 05 10:09:45.000 [notice] New control connection opened from 127.0.0.1. Jan 05 10:09:45.000 [notice] New control connection opened from 127.0.0.1. Jan 05 10:09:45.000 [notice] Bootstrapped 85%: Finishing handshake with first hop Jan 05 10:09:45.000 [notice] Bootstrapped 90%: Establishing a Tor circuit Jan 05 10:09:46.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working. Jan 05 10:09:46.000 [notice] Bootstrapped 100%: Done 1546682986230 addons.webextension.https-everywhere-eff@eff.org WARN Please specify whether you want browser_style or not in your browser_action options. 1546682986233 addons.webextension.{73a6fe31-595d-460b-a920-fcc0f8843232} WARN Please specify whether you want browser_style or not in your browser_action options. Jan 05 10:09:48.000 [notice] New control connection opened from 127.0.0.1. Jan 05 10:09:48.000 [notice] New control connection opened from 127.0.0.1. Jan 05 10:10:34.000 [notice] Owning controller connection has closed -- exiting now. Jan 05 10:10:34.000 [notice] Catching signal TERM, exiting cleanly. [Parent 2026, Gecko_IOThread] WARNING: pipe error (50): Connection reset by peer: file /var/tmp/build/firefox-efdff96e8955/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353 JavaScript error: chrome://torbutton/content/tor-circuit-display.js, line 436: TypeError: myController is null [jb@r61i ~]$ ps -ef |grep -i tor [jb@r61i ~]$
Trac:
Username: jb.1234abcd Hi, thanks for reporting this! Did you close Tor Browser or did it crash? Did you do anything special in the end of the first session? Did it maybe download an update?
Trac:
Owner: N/A to tbb-team
Priority: Immediate to Medium
Component: Applications to Applications/Tor Browser
Severity: Critical to Normal
Replying to jb.1234abcd:
[jb@r61i ~]$ ./Downloads/tor-browser_en-US/Browser/firefox
Btw this isn't how you're supposed to run tor browser. There's a ./start-tor-browser.desktop script.
-
Another hopefully useful hint: "Jan 05 09:41:52.927 [warn] Could not bind to 127.0.0.1:9150: Address already in use. Is Tor already running?" is what you might see when you run Tor Browser but for some reason there is already a Tor process running, e.g. from some previous broken attempt at running Tor Browser.
-
Replying to arma:
Replying to jb.1234abcd:
[jb@r61i ~]$ ./Downloads/tor-browser_en-US/Browser/firefox
Btw this isn't how you're supposed to run tor browser. There's a ./start-tor-browser.desktop script. Yes, but I get the same errors when utilizing that. Btw, I started TB from terminal to see/capture the error log.
Trac:
Username: jb.1234abcd -
Replying to arma:
Another hopefully useful hint: "Jan 05 09:41:52.927 [warn] Could not bind to 127.0.0.1:9150: Address already in use. Is Tor already running?" is what you might see when you run Tor Browser but for some reason there is already a Tor process running, e.g. from some previous broken attempt at running Tor Browser. Yes, but that's catch-22 - there is that first time failure (why ?), and the rest is just failed followup runs. Btw, it all started in new year 2019.
Trac:
Username: jb.1234abcd -
It looks like some TB runs are good, others not.
Any way, this run is good and the log shows some font config, addons, and JavaScript error messages that you might want to fix: [jb@r61i ~]$ cd Downloads/tor-browser_en-US/ [jb@r61i tor-browser_en-US]$ ./start-tor-browser.desktop --verbose Fontconfig warning: "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/fontconfig/fonts.conf", line 37: Use of ambiguous
element. please add prefix="cwd" if current behavior is desired. Fontconfig warning: "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/fontconfig/fonts.conf", line 85: unknown element "blank" Jan 05 13:47:28.595 [notice] Tor 0.3.4.9 (git-4ac3ccf2863b86e7) running on Linux with Libevent 2.1.8-stable, OpenSSL 1.0.2q, Zlib 1.2.11, Liblzma N/A, and Libzstd N/A. Jan 05 13:47:28.595 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning Jan 05 13:47:28.595 [notice] Read configuration file "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc-defaults". Jan 05 13:47:28.595 [notice] Read configuration file "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc". Jan 05 13:47:28.603 [notice] Scheduler type KIST has been enabled. Jan 05 13:47:28.603 [notice] Opening Socks listener on 127.0.0.1:9150 Jan 05 13:47:28.603 [notice] Opening Control listener on 127.0.0.1:9151 Jan 05 13:47:28.000 [notice] Parsing GEOIP IPv4 file /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip. Jan 05 13:47:28.000 [notice] Parsing GEOIP IPv6 file /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip6. Jan 05 13:47:29.000 [notice] Bootstrapped 0%: Starting Jan 05 13:47:30.000 [notice] Starting with guard context "default" Jan 05 13:47:30.000 [notice] Bootstrapped 80%: Connecting to the Tor network Jan 05 13:47:30.000 [notice] New control connection opened from 127.0.0.1. Jan 05 13:47:30.000 [notice] New control connection opened from 127.0.0.1. Jan 05 13:47:30.000 [notice] Bootstrapped 85%: Finishing handshake with first hop Jan 05 13:47:30.000 [notice] Bootstrapped 90%: Establishing a Tor circuit 1546696050532 addons.webextension.https-everywhere-eff@eff.org WARN Please specify whether you want browser_style or not in your browser_action options. 1546696050534 addons.webextension.{73a6fe31-595d-460b-a920-fcc0f8843232} WARN Please specify whether you want browser_style or not in your browser_action options. Jan 05 13:47:30.000 [notice] Tor has successfully opened a circuit. Looks like client functionality is working. Jan 05 13:47:30.000 [notice] Bootstrapped 100%: Done Jan 05 13:47:32.000 [notice] New control connection opened from 127.0.0.1. Fontconfig warning: "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/fontconfig/fonts.conf", line 37: Use of ambiguous element. please add prefix="cwd" if current behavior is desired. Fontconfig warning: "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/fontconfig/fonts.conf", line 85: unknown element "blank" Jan 05 13:47:32.000 [notice] New control connection opened from 127.0.0.1. Fontconfig warning: "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/fontconfig/fonts.conf", line 37: Use of ambiguous element. please add prefix="cwd" if current behavior is desired. Fontconfig warning: "/home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/fontconfig/fonts.conf", line 85: unknown element "blank" Jan 05 13:47:57.000 [notice] Owning controller connection has closed -- exiting now. Jan 05 13:47:57.000 [notice] Catching signal TERM, exiting cleanly. JavaScript error: chrome://torbutton/content/tor-circuit-display.js, line 436: TypeError: myController is nullOK. That's it.
Trac:
Username: jb.1234abcd The tricky question here is how Tor Browser left behind a tor process. Usually tor exits when the controller vanishes as your tor-error.log shows:
24 Jan 05 09:27:49.000 [notice] Owning controller connection has closed -- exiting now. ... 29 This is left runnning after a good run: 30 ======================================= 31 [jb@r61i ~]$ ps -ef |grep -i tor 32 jb 1485 1 1 10:29 tty1 00:00:04 /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Tor/tor ...Did you possibly set environment variables? Does it also happen if you start Tor Browser in the supported way described above?
Trac:
Status: new to needs_information-
No env variables set.
Well, I thought I fixed it because it worked for a few hours, but then it is back to error message and tor process leftover after closing TB (started from desktop with a TB launcher (standard way to start).
netstat -tulpn | grep LISTEN
tcp 0 0 127.0.0.1:9150 0.0.0.0:* LISTEN 9557/tor
tcp 0 0 127.0.0.1:9151 0.0.0.0:* LISTEN 9557/torps -ef |grep -i tor
jb 9557 1 0 11:34 tty1 00:00:05 /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Tor/tor --defaults-torrc /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc-defaults -f /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/torrc DataDirectory /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor GeoIPFile /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip GeoIPv6File /home/jb/Downloads/tor-browser_en-US/Browser/TorBrowser/Data/Tor/geoip6 HashedControlPassword 16:3d14d99d23786de960b25579094fabb3a5323d26af8b5fd81a9fc8c1a0 +__ControlPort 9151 +__SocksPort 127.0.0.1:9150 IPv6Traffic PreferIPv6 KeepAliveIsolateSOCKSAuth __OwningControllerProcess 9526
I decided to save the old dir with TB that gave me trouble (in case I may want to look at it or run TB from later).
I downloaded fresh TB copy and ran few times. [jb@r61i tor-browser_en-US]$ ./start-tor-browser.desktop --log I attached log files: tor-browser-1.log fresh TB copy - good run - initial startup and config. tor-browser-2.log good run. tor-browser-3.log bad run - let TB stay open for half an hour, then closed (tried that with old copy too - it is a sure way to get a bad run); process left behind.
I do not know how this can be debugged to help TB developers.
Trac:
Username: jb.1234abcd -
Trac:
Username: jb.1234abcd -
Trac:
Username: jb.1234abcd -
Trac:
Username: jb.1234abcd 
Replying to cypherpunks3:
GDB only!
What do you mean? I was assuming jb.1234abcd was just starting Tor Browser "as usual" outside of a debugger or am I wrong?
-
Replying to gk:
Replying to cypherpunks3:
GDB only!
What do you mean? I was assuming jb.1234abcd was just starting Tor Browser "as usual" outside of a debugger or am I wrong? If I may (as I understand it): I asked how this can be debugged to help TB developers, and cypherpunks3 answered that in GDB only as he suggests there is a "deadlock after calling tor_cleanup". I tested TB with standard invocation via .desktop launch (outside GDB, and its potential influence).
Btw, is this problem with a process left behind experienced by me only, or by others too ? I tested it on other machine (but same Linux distro) with the same effect.
Trac:
Username: jb.1234abcd -
Replying to jb.1234abcd:
Replying to gk:
Replying to cypherpunks3:
GDB only!
What do you mean? I was assuming jb.1234abcd was just starting Tor Browser "as usual" outside of a debugger or am I wrong? If I may (as I understand it): I asked how this can be debugged to help TB developers, and cypherpunks3 answered that in GDB only as he suggests there is a "deadlock after calling tor_cleanup".
Aha, okay.
I tested TB with standard invocation via .desktop launch (outside GDB, and its potential influence).
Btw, is this problem with a process left behind experienced by me only, or by others too ? I tested it on other machine (but same Linux distro) with the same effect.
I am not sure whether it's only you but on Linux at least I don't think we hear this problem very often. What you could do to get more logging information is to make the log on the Tor side more detailed by adding a
Log notice file your_file_nameline into yourtorrcfile (in Browser/TorBrowser/Data/Tor)What are the requirements for you to reproduce that error reliably? Just starting a default Tor Browser and then leaving it open for half an hour and then closing it again?
Trac:
Summary: TB 8.0.4 startup problem with tor to TB 8.0.4 - Tor is not shutting down properly I recall ticket with similar problem (linux, tor, deadlock). But found something different #26887 (moved) (windows, kernel, deadlock)
-
Trac:
Username: jb.1234abcd -
Replying to gk:
What are the requirements for you to reproduce that error reliably? Just starting a default Tor Browser and then leaving it open for half an hour and then closing it again? Last time I opened TB for 5 min and let it stay so, then just closed main window with "X".
Trac:
Username: jb.1234abcd -
Trac:
Username: jb.1234abcd -
Replying to cypherpunks3:
tor-debug-1.zip
Incomplete. "Catching signal TERM, exiting cleanly" missed.
Attached tor-debug-2.zip It includes yesterday's bad run (TERM is present; could it be that the log file is not flushed on TB close ?). It includes today's run too (opened for 5 min, closed TB with menu: File-Quit).
Trac:
Username: jb.1234abcd -
Trac:
Username: jb.1234abcd -
Replying to cypherpunks3:
Try to remove option from torrc-defaults file {{{ Log notice stdout }}} still bad run? Done. Bad run - see tor-debug-3.zip attached.
Trac:
Username: jb.1234abcd Oh I was confused. My bad. "Catching signal TERM" is about your "kill -s 15" not something else.
Tor detect browser vanish by OwningControllerProcess monitor and closed control connection (taken by TAKEOWNERSHIP command).
Then generate notice "Owning controller connection has closed -- exiting now." or "Owning controller process has vanished -- exiting now."
Your Tor missed both. The question is "why".
Good news about OwningControllerProcess monitor. It doesn't work for me, either. "Monitored process is still alive" info every 15 (!) seconds missed for me too. Is it broken?
@jb.1234abcd, Can you check netfilter rules for lo? Might be some another rules affect it?
-
Replying to cypherpunks3:
@jb.1234abcd, Can you check netfilter rules for lo? Might be some another rules affect it?
iptables -n -L -v
Chain INPUT (policy DROP 0 packets, 0 bytes) pkts bytes target prot opt in out source destination
434 22520 DROP all -- * * 0.0.0.0/0 0.0.0.0/0 ctstate INVALID 8746K 5805M ACCEPT all -- * * 0.0.0.0/0 0.0.0.0/0 ctstate RELATED,ESTABLISHED 2963 181K ACCEPT all -- lo * 0.0.0.0/0 0.0.0.0/0
0 0 ACCEPT icmp -- * * 0.0.0.0/0 0.0.0.0/0
132 13874 REJECT udp -- * * 0.0.0.0/0 0.0.0.0/0 reject-with icmp-port-unreachable 1 60 REJECT tcp -- * * 0.0.0.0/0 0.0.0.0/0 reject-with tcp-reset 4008 128K REJECT all -- * * 0.0.0.0/0 0.0.0.0/0 reject-with icmp-proto-unreachableChain FORWARD (policy DROP 0 packets, 0 bytes) pkts bytes target prot opt in out source destination
0 0 REJECT all -- * * 0.0.0.0/0 0.0.0.0/0 reject-with icmp-admin-prohibitedChain OUTPUT (policy ACCEPT 7110K packets, 998M bytes) pkts bytes target prot opt in out source destination
Trac:
Username: jb.1234abcd -
Replying to cypherpunks3:
Maybe this {{{ 434 22520 DROP all -- * * 0.0.0.0/0 0.0.0.0/0 ctstate INVALID }}} Can you test with ACCEPT all -- lo * before dropping INVALID? Congratulations ! I tested TB run twice for 5 min and all is clean (no process left behind). This is strange, as I have run these firewall rules for ages, and also have been using TB weekly for a couple of years. Only very recently (prior to New Year) this problem popped up. This would indicate that my original iptables rules order (which is programatically more correct as it protects all interfaces from invalid protocol messages) started blocking something INVALID very recently - problem in TB and/or tor protocol comm, or in iptables (most recent upgrade was 2018-11-28 1:1.8.0-1 -> 1:1.8.2-1; I made a fallback to 2018-09-24 iptables-1.8.0-1 and retested and it did not change the error behavior, so we can exclude iptables).
iptables-invalid-1.log attached. These are messages loggged as INVALID when TB closed (after being open for 5 min idle time).
Trac:
Username: jb.1234abcd -
Trac:
Username: jb.1234abcd -
Replying to cypherpunks3:
or in iptables
or kernel update (more likely). some race condition, browser closed socket and vanished, conntrack purged state before connection terminated. then anything (non RST) for this connection is invalid. That would suggest that TB on close/exit is responsible for orderly connection closeout, even forceful with e.g. abortive close (tcp RST) to avoid CLOSE_WAIT or TIME_WAIT states (see: socket close(3), SO_LINGER option with zero timeout).
Trac:
Username: jb.1234abcd JavaScript error: chrome://torbutton/content/tor-circuit-display.js, line 436: TypeError: myController is null [Parent 11496, Gecko_IOThread] WARNING: pipe error (55): Connection reset by peer: file /var/tmp/build/firefox-efdff96e8955/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 353Maybe browser just vanished.
Good news about OwningControllerProcess monitor. It doesn't work for me, either. "Monitored process is still alive" info every 15 (!) seconds missed for me too. Is it broken?
Nope.
reply = this._sendCommand(conn, "TAKEOWNERSHIP", null); if (!this.TorCommandSucceeded(reply)) TorLauncherLogger.log(4, "take ownership failed"); else { reply = this._sendCommand(conn, "RESETCONF", "__OwningControllerProcess"); if (!this.TorCommandSucceeded(reply)) TorLauncherLogger.log(4, "clear owning controller process failed"); }