[tor-talk] tor-browser with system tor, "authentication cookie with wrong length"

Sat Aug 3 20:42:00 UTC 2019

Hi!

I tried to use Debian system tor, instead of the bundled TBB tor.

(NOTE: I know it's not supported, won't take it hard if I do not get
much support. However, it's in the script below...)

First source for my experiments was the canonical start-tor-browser
script in tor-browser_en-US.
Followed it, and created this file:

-rw-r--r-- 1 nym nym 658 2018-03-29 10:07
tor-browser_en-US/Browser/TorBrowser/Data/Browser/profile.default/user.js
// as per start-tor-browser
user_pref("network.security.ports.banned", "9050,9051");
user_pref("network.proxy.socks", "127.0.0.1");
user_pref("network.proxy.socks_port", 9050);
user_pref("extensions.torbutton.inserted_button", true);
user_pref("extensions.torbutton.launch_warning", false);
user_pref("extensions.torbutton.loglevel", 2);
user_pref("extensions.torbutton.logmethod", 0);
user_pref("extensions.torlauncher.control_port", 9051);
user_pref("extensions.torlauncher.loglevel", 2);
user_pref("extensions.torlauncher.logmethod", 0);
user_pref("extensions.torlauncher.prompt_at_startup", false);
user_pref("extensions.torlauncher.start_tor", false);

Second (major) source was:
https://trac.torproject.org/projects/tor/wiki/TorBrowserBundleSAQ

The user nym is memeber of group debian-tor:

$ groups nym
nym : nym mail cdrom floppy sudo audio [...] debian-tor [...]
(and I did not just log out and log in, I even rebooted, in vain hope...
so far... )

And also (but it's probably extra since the user.js does the same, I did
set the export lines from the "Seldom Asked Questions" above:

nym at ymous:~/tor-browser_en-US/Browser$ echo $TOR_CONTROL_COOKIE_AUTH_FILE
/run/tor/control.authcookie
nym at ymous:~/tor-browser_en-US/Browser$ echo $TOR_SOCKS_PORT
9050
nym at ymous:~/tor-browser_en-US/Browser$ echo $TOR_CONTROL_PORT
9051
nym at ymous:~/tor-browser_en-US/Browser$ echo $TOR_SKIP_LAUNCH
1
nym at ymous:~/tor-browser_en-US/Browser$

And, temporarily (the SafeLogging and the debug line), this is the:

$ cat /etc/tor/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

SocksPort 9050 IPv6Traffic PreferIPv6 KeepAliveIsolateSOCKSAuth
ControlPort 9051
ExcludeExitNodes {??}
Log debug file /var/log/tor/log
SafeLogging 0
LogTimeGranularity 50

Launching Tor browser with

nym at ymous:~/tor-browser_en-US/Browser$ ./start-tor-browser

got me an all-in-red Tor browser window telling:

Something went wrong. (in huge print)
Tor is not working in this browser.

The lines that I got in the /var/log/tor/log and which correspond to the
failure are:

Aug 01 11:24:52.500 [notice] New control connection opened from 127.0.0.1.
Aug 01 11:24:52.500 [debug] connection_add_impl(): new conn type
Control, socket 12, address 127.0.0.1, n_conns 5.
Aug 01 11:24:52.850 [debug] conn_read_callback(): socket 12 wants to read.
Aug 01 11:24:52.850 [debug] read_to_chunk(): Read 43 bytes. 43 on inbuf.
Aug 01 11:24:52.850 [warn] Got authentication cookie with wrong length (8)
Aug 01 11:24:52.850 [debug] conn_close_if_marked(): Cleaning up
connection (fd 12).
Aug 01 11:24:52.850 [info] conn_close_if_marked(): Conn (addr
"127.0.0.1", fd 12, type Control, state 2) marked, but wants to flush 67
bytes. (Marked at ../src/feature/control/control.c:1622)

And a little later:

Aug 01 11:24:54.000 [debug] connection_handle_listener_read():
Connection accepted on socket 13 (child of fd 8).
Aug 01 11:24:54.000 [notice] New control connection opened from 127.0.0.1.
Aug 01 11:24:54.000 [debug] connection_add_impl(): new conn type
Control, socket 13, address 127.0.0.1, n_conns 6.
Aug 01 11:24:54.000 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.000 [debug] read_to_chunk(): Read 1 bytes. 1 on inbuf.
Aug 01 11:24:54.000 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.000 [debug] read_to_chunk(): Read 1 bytes. 2 on inbuf.
Aug 01 11:24:54.000 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.000 [debug] read_to_chunk(): Read 1 bytes. 3 on inbuf.
Aug 01 11:24:54.000 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.000 [debug] read_to_chunk(): Read 1 bytes. 4 on inbuf.
Aug 01 11:24:54.000 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.000 [debug] read_to_chunk(): Read 1 bytes. 5 on inbuf.
Aug 01 11:24:54.000 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.000 [debug] read_to_chunk(): Read 1 bytes. 6 on inbuf.
Aug 01 11:24:54.000 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.000 [debug] read_to_chunk(): Read 1 bytes. 7 on inbuf.
Aug 01 11:24:54.000 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.000 [debug] read_to_chunk(): Read 1 bytes. 8 on inbuf.
Aug 01 11:24:54.000 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 9 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 10 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 11 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 12 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 13 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 14 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 15 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 16 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 17 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 18 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 2 bytes. 20 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 21 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 22 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 23 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 24 on inbuf.
Aug 01 11:24:54.050 [debug] conn_read_callback(): socket 13 wants to read.
Aug 01 11:24:54.050 [debug] read_to_chunk(): Read 1 bytes. 25 on inbuf.
Aug 01 11:24:54.050 [warn] Got authentication cookie with wrong length (8)
Aug 01 11:24:54.050 [debug] conn_close_if_marked(): Cleaning up
connection (fd 13).
Aug 01 11:24:54.050 [info] conn_close_if_marked(): Conn (addr
"127.0.0.1", fd 13, type Control, state 2) marked, but wants to flush 67
bytes. (Marked at ../src/feature/control/control.c:1622)
Aug 01 11:24:54.050 [debug] connection_remove(): removing socket 13
(type Control), n_conns now 6
Aug 01 11:24:54.050 [debug] connection_free_minimal(): closing fd 13.

(NOTE: dates, times and names redacted/anonymized in this entire mail,
however, I tried to keep it consistent, such as the time difference of
the lines with "Got authentication cookie with wrong length (8)", and
all lines btwn them are correctly consecutive.)

That was also with the current Debian Tor package (from unstable repo),
previously. Back then I thought if I get the Debian source from unstable
repo and compile my own Tor packages (of the 0.4 version as the
TorBrowser bundles), this might be solved, but no. The above is with the
0.4.0.5 that I compiled.

Is this a bug in Tor? Because I do not see I did anything the wrong way
nor that I missed to do something...

Thanks and regards!

Mathe