tor freeze when receiving to many http proxy requests on socks port

After receiving 724 curl 127.0.0.1:9150 (number was very consistent for me, but maybe somehow platform dependent?), tor stop doing anything. I can't reproduce that issue with a tor not started by TB. Arma intuition is it could be TB isn't reading tor logs "fast enough" so tor end up blocked on trying to write to its stdout.

Note: these requests are invalid by tor standards: tor does not accept http requests on its socks port, and answer them with a basic "this is not how to use tor" webpage (and logs a complain).

Edit: setting Log warn stdout causes the error to appear after 740 curls, and Log err stdout make it never is an issue, so it is indeed an issue of not reading tor stdout fast enough (or at all possibly?), and getting blocked when the pipe is full.

changed the description

Thanks trinity!

And cc'ing @s7r as the original person who experienced the bug.

This bug isn't just theoretical -- it turns out that Electrum does this "http request to the socks port many times" behavior, as part of its process to detect if there is a Tor running that it can use: https://github.com/spesmilo/electrum/issues/7317

This bug is confusing to me. It sure looks like Tor is writing to its stdout, and Tor Browser isn't reading it, and eventually Tor blocks on writing to its stdout and things stop working. But, if that's the case, how come we haven't discovered this bug already? Does Tor Browser read Tor's stdout but only every so often, so the bug would only show up if enough log messages are generated in a given time frame?

How does Tor Browser use the stdout from Tor? I remember there was some complexity in terms of the browser launching an external app and being able to read its stdout, e.g. to be able to read and tell the user about Tor's warnings/errors on startup.

this isn't an issue with the 11.0/11.5 series, only 12.0+. Also I notice tor has a lot of file descriptors open that makes no sens for it. A few /memfd:mozilla-ipc, more pipes than it should (and I think more socket too, but that's harder to make sure of), a few omni.ja an .xpi...

It looks like something changed on how tor is executed, and the new thing doesn't do any cleanup between forking and execve.

Ticket to look closer at: #40853 (closed) (merged in 12.0a4 it seems)

Related original motivation ticket: tpo/core/tor#10059 (closed) (marked as closed, but apparently it was never built, just closed 'because arti')

afaict the Subprocess.jsm doesn't provide a way to control the oddities I saw, however adding a

(async () => {
  while ((string = await this._subprocess.stdout.readString()))
})();

immediately after Subprocess.call is enough to make stdout not clog up (as stderr is set to "pipe", that's probably required for it too, though tor isn't talking much on there it seems).

Thanks for the CC @arma

ghost43 responded to my request, people at Electrum like and take Tor very seriously (we have a very good contact and interaction with people in Electrum wallet community because it's the a lightweight wallet that has strong privacy policies that meet our standards and is a tool that comes shipped by default in Tails).

Fix was applied in:

https://github.com/spesmilo/electrum/commit/253150cb36e820f0a8262ef559d3295f7c8fe8d1

This is an immediate fix, so now instead of probing once every 10 seconds, until the application closes, it will just do this once. In the longer term after the architecture redesign it will switch to tor-resolve 0:0:0:0:0:0:0:0

We still have to fix this in Tor Browser, because there are plenty of other use cases where Tor daemon launched by Tor Browser freezes because of the log file and becomes not usable. Example:

• you use that Tor process SocksPort in a p2p daemon that connects to other .onion peers aggressively, because many are not up and just residual you will get spam in Tor's log that filed to get HS Descriptor. After enough of these messages Tor process will freeze;
• you don't close Tor and don't turn off the laptop but close lid and continuously switch from wireless networks to 4G networks and so on, you will get spam in Tor's log that Network speed has changed, resetting build times. After enough of these messages Tor process will freeze;

Of course these cases don't include a message every 10 seconds so it doesn't freeze in 30 - 40 mins (I think this is platform / resources / environment dependent because @trinity-1686a experienced smaller amounts of time) but instead freeze in 6 hours or so - still a bug that needs fix especially that in previous Tor Browser series it did not occur.

@trinity-1686a @arma So there are a pair of things here that are different in 12.0 when it comes to the tor daemon management on Windows that I can think of:

• The switch to Subprocess.jsm; all platforms
• Changed build flags which prevented tor daemon from ever printing to stdout in terminal (fixed in 12.0.1 and 12.5a1); windows specific

I think we don't read stdout at all in Tor Browser but at this point I have so many tor controller implementations floating around in my head I'd need to investigate to make sure.

when it comes to the tor daemon management on Windows

this bug isn't Windows specific (in fact I haven't tried to reproduce on Windows, only Linux, though I have no reasons to believe it can't be reproduced there)

I think we don't read stdout at all in Tor Browser

from what I can tell this is right (and probably "the issue")

added Bug Q2 labels

added Backlog label

mentioned in issue #41548 (closed)

added Desktop label

https://github.com/bit/subprocess

    stdout: function(data) {
      dump("got data on stdout:" + data + "\n");
    },
    stderr: function(data) {
      dump("got data on stderr:" + data + "\n");
    },

 stdout:      An optional function that can receive output data from the
              process. The stdout-function is called asynchronously; it can be
              called mutliple times during the execution of a process.
              At a minimum at each occurance of \n or \r.
              Please note that null-characters might need to be escaped
              with something like 'data.replace(/\0/g, "\\0");'.

 stderr:      An optional function that can receive stderr data from the
              process. The stderr-function is called asynchronously; it can be
              called mutliple times during the execution of a process. Please
              note that null-characters might need to be escaped with
              something like 'data.replace(/\0/g, "\\0");'.
              (on windows it only gets called once right now)

       this._subprocess = await Subprocess.call(options);
+      this._subprocess.stdout.close();
       this._watchProcess();

I confirm this works for me, too!

Thank you very much!

hi @cypherpunks. The Subprocess in https://github.com/bit/subprocess isn't the same as what's currently in TorBrowser (documentation here). There is no stdout in the object passed to Subprocess.call, and stderr is expected to be a string.

However this._subprocess.stdout.close(); in the second message does seems to work fine, at least on linux.

Related to

#41548 (closed)

https://forum.torproject.net/t/socks-problem-since-ver-12-x-x-windows/6067

Good find -- I added a pointer to the forum thread back to this ticket. Thanks.

That linked issue is tagged with Windows, but just-in-case I can confirm the time-out/stall also seems to happen on a Linux desktop.

Maybe related: #41532 (closed).

I can reproduce without closing stdout, but can't when it's closed, it indeed seems to be the same underlying issue

Yep. about:tor still needs to be cleaned up, but at least this might heal the "remains blank" part.

marked this issue as related to #41548 (closed)

assigned to @pierov