Handle output from PT processes with the event loop

Currently the output from stdout/stderr of a PT process is only read during the startup of the process. The reading process uses read() on a non-blocking socket, which currently seems to work, but have proved to be flaky.

We should ensure that PT processes' output can be read all the time.

On Windows we cannot attach the pipes to the main loop because of limitations of the select() API, so we have to do something slightly worse such as reading from the stdout/stderr handle via a timer as long as the processes are alive.

changed milestone to %Tor: 0.4.0.x-final

added 040-roadmap-subtask component::core tor/tor milestone::Tor: 0.4.0.x-final owner::ahf parent::25502 points::31 priority::medium resolution::implemented reviewer::nickm severity::normal sponsor::19-must status::closed tor-pt type::enhancement version::tor unspecified labels

Trac:
Status: new to assigned
Owner: N/A to ahf

Trac:
Keywords: N/A deleted, 036-roadmap-subtask, tor-pt added

Related to this is #26360 (moved). tor should read from transport plugins' stderr, if only to prevent processes from deadlocking when they write to it too much.

Tor 0.3.6.x has been renamed to 0.4.0.x.

Trac:
Milestone: Tor: 0.3.6.x-final to Tor: 0.4.0.x-final

0.3.6 is now 0.4.0: changing keywords

Trac:
Keywords: 036-roadmap-subtask deleted, 040-roadmap-subtask added

Starting to track this in https://github.com/ahf/tor/tree/bugs/28179

This is already pretty big, it's not entirely done yet, but let's start having some review of the design and code:

Known issues with the current code:

• The Python file is missing its actual test implementations in test_unix/test_win32. Need to talk with Nick about that.
• Missing doc strings for a lot of functions.
• Missing process termination detection.
• Some FIXME's still around.

Trac:
Status: assigned to needs_review

PR at: https://github.com/torproject/tor/pull/525

Trac:
Reviewer: N/A to dgoulet

Did a pass on it. No show stopper for now but what I would need also is some documentation on how that API is used since right now it is very "abstract" to the process.c and not used outside of it. One thing that could be done there is to do some documentation on how to use the API at the start of process.c?

Trac:
Status: needs_review to needs_revision

Fixes should be in: https://github.com/torproject/tor/pull/537

Trac:
Status: needs_revision to needs_review

Trac:
Status: needs_review to needs_revision

Added fixup commits.

Trac:
Status: needs_revision to needs_review

https://github.com/torproject/tor/pull/537/files#diff-08bd8435ecfd8690789652091567ff47R1151

  /* The format is 'LOG <transport> <message>'. We accept empty messages. */

It looks like this comment is out of date; I thought the <transport> part was removed. Also "We accept empty messages" seems to contradict the "Managed proxy sent us a LOG line with missing arguments" check above: I suppose that LOG (with a space) is acceptable but LOG is not, not sure if that's what's intended.

https://github.com/torproject/tor/pull/537/files#diff-6fdba7a022e591369dcf7054e5f2700aR7396

/** A pluggable transport called <b>transport_name</b> has emitted a log
 * message found in <b>message</b>. */
void
control_event_transport_log(const char *transport_name, const char *message)
{
  send_control_event(EVENT_TRANSPORT_LOG,
                     "650 TRANSPORT_LOG %s %s\r\n",
                     transport_name,
                     message);
}

Where does <transport_name> come from? Is it the path the executable? In general, tor won't know a specific transport name corresponding to any LOG message. I don't see where control_event_transport_log is called other than in tests.

Cross-referencing #9957 (moved), an older ticket about reading and logging PTs' stderr.

Trac:
bug28179-client.go

Client PT program that demonstrates a deadlock when writing too much to stdout/stderr.

This program may be useful for testing: bug28179-client.go

It's a modified version of dummy-client from goptlib. The differences are that after PT initialization, it starts writing to stdout and stderr at 4 KB/s. Also, in its core proxying loop, it tries to write a line to stdout/stderr every time it downloads a chunk of data. Eventually the stdout and stderr buffers fill up, and the proxy loop halts because it cannot write its line. The program copies everything it writes to stdout/stderr to a file called mirror.log, so you can see how much was written before it deadlocks.

1. Download and put in a directory called bug28179-client.
2. go get and go build.
3. Put in torrc:\

DataDirectory datadir
UseBridges 1
ClientTransportPlugin dummy exec bug28179-client
Bridge dummy 128.31.0.61:443

4. tor -f torrc SOCKSPort 10000
5. In another terminal, tail -F mirror.log. You will see a mixture of hello tor world and received XXX bytes lines.
6. For me, the system deadlocks after 8 seconds; apparently the stdout/stderr buffers are 64 KB.\ {{{ $ ls -l mirror.log -rw-r--r-- 1 david david 65425 Nov 27 14:09 mirror.log }}} If tor was in the middle of bootstrapping, it will stop here. If tor finished bootstrapping, you can verify that it stopped working with curl -x socks5h://127.0.0.1:10000/ https://example.com/.