Handle output from PT processes with the event loop

changed milestone to %Tor: 0.4.0.x-final in legacy/trac

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 legacy/trac#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 legacy/trac#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.

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

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

tor -f torrc SOCKSPort 10000
In another terminal, tail -F mirror.log. You will see a mixture of hello tor world and received XXX bytes lines.
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/.

New PR is at https://github.com/torproject/tor/pull/552

PR in previous comment. Branch is in ahf:bugs/28179_pr.

@nickm, this is rather large branch. It had a lots of back and forth and testing with me and ahf so it is in merge_ready for your consideration and upstream merge.

The spec changes of this branch are in legacy/trac#28180 (moved).

Trac:
Status: needs_review to merge_ready

Hi! I've got some requests in the branch. I don't know if the windows code works or not, but if it's well-tested both manually and with automated tests, I'll believe it.

I had thought that we'd be doing multiple threads here to make the windows code work. I think that might be our only way around a timer. Having timers that bypass the periodic timer system risks undoing a bunch of our work for wakeup reduction, unless we are super careful.

For the spec: I think we need to request more structure from these log messages, or we won't be able to actually do anything automatic based on them. Maybe we could define severity, keyword, suggested-action stuff?

Trac:
Status: merge_ready to needs_revision

Fixed all pending comments on the code. Moving to needs_review.

I've postponed integrating any code that needs to make use of the K/V parser (that is the PT stdout handler) for the LOG and STATUS messages. If we think these should go in first, I'll need some help figuring out what the best way to do this with a merge/rebase without making it difficult for the reviewers to review this again.

Trac:
Status: needs_revision to needs_review

Trac:
Sponsor: Sponsor8 to Sponsor8-must

Marked as merge_ready, but made a squashed-and-merged PR as https://github.com/torproject/tor/pull/603 so that CI can take one last peek at this branch before I merge it.

Trac:
Status: needs_review to merge_ready