Opened 4 years ago

Last modified 6 months ago

#9957 assigned enhancement

Tor should consider stderr output of transport proxies

Reported by: wfn Owned by: yawning
Priority: Very Low Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: unspecified
Severity: Normal Keywords: tor-pt, SponsorS-deferred, tor-bridge
Cc: asn, yawning, mcs Actual Points:
Parent ID: Points: small
Reviewer: Sponsor:

Description

Currently, Tor cares about what transport proxies (e.g. obfsproxy) say over stdout (it echoes stdout in its log, etc.) Not so with stderr, the reason being, as far as I can tell, the presumed/standard signaling channel for transport proxies to communicate with Tor is their standard output stream, as per design.

It so happens that as of now, obfsproxy may complain about some things (e.g. it not being able to write to its own log file) over stderr. If one runs obfsproxy as intended (using the ServerTransportPlugin directive in torrc), obfsproxy may exit (Tor will report this, of course) without any verbal explanation.

Using the "run a transport proxy manually (without Tor) to figure out what's wrong" method (which some bridge operators have (had) to resort to (that is, at least me and someone else who talked with asn)) in order to debug things seems suboptimal.

Three ways out, as I see it:

  1. Make sure all transport proxies adhere to the "use stdout to complain about things" protocol.
  1. Have Tor treat both stdout and stderr streams of transport proxies as meaningful, and include their contents in log. This requires changing the design in regards to transport proxy <-> Tor signaling channels.
  1. Care about stderr instead of stdout (most easy in terms of code changes, I think; not sure if makes much sense / is elegant, though.)

Are there any specific design-level nuances that block option 2?

For option 2, the tor_get_lines_from_handle() function seems to be overall more or less handle-type-agnostic; it uses variable names like "stdout_buf", but it all really depends on what's passed via "handle", which could be any kind of stream.

configure_proxy() in or/transports.c is what would need changing. Depending on design changes, the streams would have to be combined, or (simply) stderr would have to be used instead of stdout (so to remain clean, there'd need to be a tor_process_get_stderr_pipe(), which would simply return process_handle->stderr_pipe).

Child Tickets

Attachments (4)

9957.patch (3.8 KB) - added by wfn 4 years ago.
Patch for #9957 (output from git diff master)
9957-2.patch (3.8 KB) - added by wfn 4 years ago.
Updated patch for #9957, with escaped()
9957-torrc (157 bytes) - added by wfn 4 years ago.
Sample torrc which makes obfsproxy fail before it can report anything to its log (hence stderr useful)
9957-3.patch (4.7 KB) - added by wfn 4 years ago.
Another patch for #9957 - log proxy stderr in separate function

Download all attachments as: .zip

Change History (55)

comment:1 Changed 4 years ago by nickm

Milestone: Tor: 0.2.???

I'm fine with option 2 personally if somebody implements it.

comment:2 Changed 4 years ago by yawning

Cc: yawning added

comment:3 Changed 4 years ago by wfn

Status: newneeds_review

Here's a patch re: option 2. I assume that actual PT configuration won't happen over stderr (i.e. we don't need to handle_proxy_line() each stderr line the way we do for stdout.)

So we

  • log NOTICE that the transport proxy gave us some stderr (it really should not give any stderr unless something is wrong - we just tell the user they may be interested to see what is up)
  • log INFO every stderr line.

To achieve this nicely, we also needed a tor_process_get_stderr_pipe(), but the lower-level primitives for handling stderr are already there, so no big deal.

It's just that the other parts (e.g. get_string_from_pipe() in util.c which we may want to use in lieu of tor_process_get_stderr_pipe) have variable names like stdout_buf, even though they are handle-type-agnostic. This is just cosmetics, though, but maybe in the future we'll want to have more neutral variable names where we are doing handle-neutral things.

Can transport proxies leak any sensitive information over stderr? (The kinds of python tracebacks that I was once encountering for obfsproxy surely didn't and (I think) couldn't, but we should assume things conservatively when generalizing to "transport proxies.") The trouble here is that normally, a transport proxy would do its own address etc. scrubbing; but stderr may be a nasty traceback of some uncaught exception (which shouldn't really happen, that's not nice) or somesuch.

Patch attached, also, here's a branch for this ticket:

https://github.com/wfn/tor/commits/bug_9957

Two commits there:

This is a simplistic approach to reporting transport proxy stderr output. Do we want something more than this?

Changed 4 years ago by wfn

Attachment: 9957.patch added

Patch for #9957 (output from git diff master)

comment:4 Changed 4 years ago by nickm

Milestone: Tor: 0.2.???Tor: 0.2.6.x-final

comment:5 Changed 4 years ago by wfn

Updated patch to use escaped() for every stderr output line that we log.

(https://github.com/wfn/tor/commit/cfd4f7e22f0db68f14e343d971f2b4109da4423a)

Changed 4 years ago by wfn

Attachment: 9957-2.patch added

Updated patch for #9957, with escaped()

Changed 4 years ago by wfn

Attachment: 9957-torrc added

Sample torrc which makes obfsproxy fail before it can report anything to its log (hence stderr useful)

comment:6 Changed 4 years ago by wfn

Also see #11542. If #11542 is to be done soon, #9957 can be updated to use the new logging domain before it is closed. The patches would need to be distinct, not a single "new logging domain and here's all the #9957 stuff" patch.

comment:7 Changed 4 years ago by asn

Patch looks plausible.

Three comments:
a) configure_proxy() is getting pretty big. Maybe move stderr reading to a function, and call it from configure_proxy()?

b) With regards to the log_notice() message, maybe we should call it standard error stream or just stderr? I'm not sure if it's a pipe. Maybe we should just suggest people to look into INFO-level logs, since obfsproxy doesn't log to a file by default, and some times it doesn't have time to write a logfile when this error appears (in ImportErrors, etc.).

c) I wonder what PTs currently output to stderr. Maybe if we are serious about this, we should add another convention to pt-spec.txt asking PTs to not print stuff in stderr except if they have error messages that the user should see.

comment:8 Changed 4 years ago by asn

As another thought, this "Send a notice to log_notice, but send the actually useful information to log_info" is a new workflow for Tor users. If we decide we like this, maybe we could make it easier for users to detect the proper info logs by using a log prefix and suggesting it in the log_notice message? So that users can just grep for that prefix? Maybe overengineering.

comment:9 in reply to:  7 ; Changed 4 years ago by wfn

Replying to asn:

Patch looks plausible.

Three comments:
a) configure_proxy() is getting pretty big. Maybe move stderr reading to a function, and call it from configure_proxy()?

Hmm, it's not *that* big (~100 lines), but I see what you mean - it's doing multiple things, so to say. There's some global state involved (e.g. we need to free proxy_err_output at a particular point dependent on the status of the stdout stream), so it might not be as clean as you'd like - but see attached patch. Something like that?

b) With regards to the log_notice() message, maybe we should call it standard error stream or just stderr? I'm not sure if it's a pipe.

Ah yes, indeed (tor seems to prefer to call it 'pipe' as a higher-level abstraction (i.e. it may be a handle, etc. depending on platform; but it's a pipe in general), but this shouldn't mean we should call it that when talking to a user.)

Maybe we should just suggest people to look into INFO-level logs, since obfsproxy doesn't log to a file by default, and some times it doesn't have time to write a logfile when this error appears (in ImportErrors, etc.).

I agree (that was indeed the original problem anyway.) Log message tells them that, maybe it should be more clear about it? But this notice is there.

c) I wonder what PTs currently output to stderr. Maybe if we are serious about this, we should add another convention to pt-spec.txt asking PTs to not print stuff in stderr except if they have error messages that the user should see.

Yeah, I was wondering if this could not cause any trouble in some other/future PTs. Adding an explicit clause makes sense. Also, it'd be nice to make sure all current PTs already stick to this practice (obfsproxy does, I guess.)

Changed 4 years ago by wfn

Attachment: 9957-3.patch added

Another patch for #9957 - log proxy stderr in separate function

comment:10 in reply to:  9 ; Changed 4 years ago by wfn

Replying to wfn:

Replying to asn:

Patch looks plausible.

Three comments:
a) configure_proxy() is getting pretty big. Maybe move stderr reading to a function, and call it from configure_proxy()?

Hmm, it's not *that* big (~100 lines), but I see what you mean - it's doing multiple things, so to say. There's some global state involved (e.g. we need to free proxy_err_output at a particular point dependent on the status of the stdout stream), so it might not be as clean as you'd like - but see attached patch.

On second thought, I was wrong, what 'global state'. Flow is simple. Will probably attach another patch once I get the chance to compile tor again (afk/computer now.) Sorry for verbosity!

comment:11 in reply to:  9 ; Changed 4 years ago by asn

Replying to wfn:

Replying to asn:

Patch looks plausible.

Three comments:

Maybe we should just suggest people to look into INFO-level logs, since obfsproxy doesn't log to a file by default, and some times it doesn't have time to write a logfile when this error appears (in ImportErrors, etc.).

I agree (that was indeed the original problem anyway.) Log message tells them that, maybe it should be more clear about it? But this notice is there.

I wanted to say that maybe we shouldn't even suggest people to look at obfsproxy's log, because that might confuse them (they probably don't know if obfsproxy is logging or where. and obfsproxy does not log by default). We should only suggest people to look at Tor's info log.

BTW, here is the current log message:

    log_notice(LD_GENERAL, "Managed proxy '%s' is giving some output over "
               "the standard error pipe. This usually means that it has "
               "encountered some error that I won't be able to understand. "
               "You should check its log, or enable INFO-level tor log to "
               "see what it is saying.", mp->argv[0]);

What do you think?

c) I wonder what PTs currently output to stderr. Maybe if we are serious about this, we should add another convention to pt-spec.txt asking PTs to not print stuff in stderr except if they have error messages that the user should see.

Yeah, I was wondering if this could not cause any trouble in some other/future PTs. Adding an explicit clause makes sense. Also, it'd be nice to make sure all current PTs already stick to this practice (obfsproxy does, I guess.)

Yeah, we should make sure of this.

Last edited 4 years ago by asn (previous) (diff)

comment:12 in reply to:  10 Changed 4 years ago by wfn

Replying to wfn:

Replying to wfn:

Replying to asn:

Patch looks plausible.

Three comments:
a) configure_proxy() is getting pretty big. Maybe move stderr reading to a function, and call it from configure_proxy()?

Hmm, it's not *that* big (~100 lines), but I see what you mean - it's doing multiple things, so to say. There's some global state involved (e.g. we need to free proxy_err_output at a particular point dependent on the status of the stdout stream), so it might not be as clean as you'd like - but see attached patch.

On second thought, I was wrong, what 'global state'. Flow is simple. Will probably attach another patch once I get the chance to compile tor again (afk/computer now.) Sorry for verbosity!

Moved everything to do with stderr logging to a separate function, tested out with failing and non-failing obfsproxy config, and squashed several minor commits onto a separate branch - https://github.com/wfn/tor/commits/bug_9957_2:

comment:13 in reply to:  11 Changed 4 years ago by wfn

Replying to asn:

Replying to wfn:

Replying to asn:

Patch looks plausible.

Three comments:

Maybe we should just suggest people to look into INFO-level logs, since obfsproxy doesn't log to a file by default, and some times it doesn't have time to write a logfile when this error appears (in ImportErrors, etc.).

I agree (that was indeed the original problem anyway.) Log message tells them that, maybe it should be more clear about it? But this notice is there.

I wanted to say that maybe we shouldn't even suggest people to look at obfsproxy's log, because that might confuse them (they probably don't know if obfsproxy is logging or where. and obfsproxy does not log by default). We should only suggest people to look at Tor's info log.

BTW, here is the current log message:

    log_notice(LD_GENERAL, "Managed proxy '%s' is giving some output over "
               "the standard error pipe. This usually means that it has "
               "encountered some error that I won't be able to understand. "
               "You should check its log, or enable INFO-level tor log to "
               "see what it is saying.", mp->argv[0]);

What do you think?

Ahh - of course, that makes sense, yeah. See rebased commit above (https://github.com/wfn/tor/commit/580516d37f4332da280a1cd5077f71285e6d75cc) - I considered including a very short notice about which keyword to use in torrc to enable INFO etc., but it would all come out too verbose, I think. So simply removed the 'look at PT proxy logs' part.

c) I wonder what PTs currently output to stderr. Maybe if we are serious about this, we should add another convention to pt-spec.txt asking PTs to not print stuff in stderr except if they have error messages that the user should see.

Yeah, I was wondering if this could not cause any trouble in some other/future PTs. Adding an explicit clause makes sense. Also, it'd be nice to make sure all current PTs already stick to this practice (obfsproxy does, I guess.)

Yeah, we should make sure of this.

Should I try and produce a possible patch for pt-spec.txt? Not confident about wording things there re: this.

comment:14 in reply to:  8 Changed 4 years ago by wfn

Replying to asn:

As another thought, this "Send a notice to log_notice, but send the actually useful information to log_info" is a new workflow for Tor users. If we decide we like this, maybe we could make it easier for users to detect the proper info logs by using a log prefix and suggesting it in the log_notice message? So that users can just grep for that prefix? Maybe overengineering.

I see what you mean. But we now have logs like

Apr 19 06:46:45.000 [info] launch_managed_proxy(): Managed proxy at '/usr/local/bin/obfsproxy' has spawned with PID '2426'.
Apr 19 06:46:50.000 [notice] Managed proxy '/usr/local/bin/obfsproxy' is giving some output over the standard error stream (stderr). This usually means that it has encountered some error that I won't be able to understand. You should enable INFO-level tor log to see what it is saying.
Apr 19 06:46:50.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' reports a possible error over the standard error stream (stderr) - stderr output follows:
Apr 19 06:46:50.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "No handlers could be found for logger \"obfslogger\""
Apr 19 06:46:51.000 [notice] Managed proxy '/usr/local/bin/obfsproxy' is giving some output over the standard error stream (stderr). This usually means that it has encountered some error that I won't be able to understand. You should enable INFO-level tor log to see what it is saying.
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' reports a possible error over the standard error stream (stderr) - stderr output follows:
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "Traceback (most recent call last):"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "  File \"/usr/local/bin/obfsproxy\", line 9, in <module>"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "    load_entry_point(\'obfsproxy==0.2.6\', \'console_scripts\', \'obfsproxy\')()"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "  File \"/usr/local/lib/python2.7/dist-packages/obfsproxy/pyobfsproxy.py\", line 168, in run"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "    pyobfsproxy()"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "  File \"/usr/local/lib/python2.7/dist-packages/obfsproxy/pyobfsproxy.py\", line 127, in pyobfsproxy"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "    consider_cli_args(args)"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "  File \"/usr/local/lib/python2.7/dist-packages/obfsproxy/pyobfsproxy.py\", line 100, in consider_cli_args"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "    log.set_log_file(args.log_file)"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "  File \"/usr/local/lib/python2.7/dist-packages/obfsproxy/common/log.py\", line 48, in set_log_file"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "    log_handler = logging.FileHandler(filename)"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "  File \"/usr/lib/python2.7/logging/__init__.py\", line 897, in __init__"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "    StreamHandler.__init__(self, self._open())"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "  File \"/usr/lib/python2.7/logging/__init__.py\", line 916, in _open"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "    stream = open(self.baseFilename, self.mode)"
Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "IOError: [Errno 13] Permission denied: \'/root/fail/to/write/here\'"
Apr 19 06:46:51.000 [warn] The communication stream of managed proxy '/usr/local/bin/obfsproxy' is 'closed'. Most probably the managed proxy stopped running. This might be a bug of the managed proxy, a bug of Tor, or a misconfiguration. Please enable logging on your managed proxy and check the logs for errors.
Apr 19 06:46:51.000 [notice] Failed to terminate process with PID '2426' ('No such process').

So grepping for report_proxy_stderr() will do the thing just fine, unless we want to group more PT-things onto here. iac, yes, the "see NOTICE, then enable INFO to see more" workflow might be new, but including nasty python tracebacks doesn't seem like a NOTICE'y thing to do. But, this is only one way to do it, there could be others (iac moving on with #11542 would be nice, I suppose.)

(btw, you'll notice that the proxy name comes out to be the path to the python executable - but that's unavoidable in this case and happens at other parts in the log, too because pt->argv[0] - whoops, in this case I wasn't using a custom python executable, so doesn't even apply.)

Last edited 4 years ago by wfn (previous) (diff)

comment:15 Changed 4 years ago by wfn

Rebased once again (same branch) - to include an additional change which includes the report_proxy_stderr keyword that a user can look for when inspecting INFO-level tor log:

https://github.com/wfn/tor/compare/bug_9957_2 ->

Last edited 4 years ago by wfn (previous) (diff)

comment:16 in reply to:  15 ; Changed 4 years ago by asn

Status: needs_reviewneeds_revision

Replying to wfn:

Rebased once again (same branch) - to include an additional change which includes the report_proxy_stderr keyword that a user can look for when inspecting INFO-level tor log:

https://github.com/wfn/tor/compare/bug_9957_2 ->

Nice. This looks cleaner!

As a suggestion, to avoid needless nesting, maybe you would enjoy doing:

if (!proxy_err_output) {
    return
}
... do everything ...

instead of:

if (proxy_err_output) {
      ... do everything ...
}

Up to your preference :)

Also, AFAIK, we are using STATIC to mean "We should use static here, but we also need to unit test that function". Since you are not unittesting report_proxy_stderr() the function can be truly static like other functions in src/or/transports.c (for example handle_finished_proxy()).

Finally, we will need a changes file if we want this merged. I can write this for you, but you might want to write it on your own to get used to changes files for further Tor development :) As an example, see commit 71e0ca02b57f7945d922a8708a2c97815a9350ad.

comment:17 Changed 4 years ago by asn

    log_notice(LD_GENERAL, "Managed proxy '%s' is giving some output over "
               "the standard error stream (stderr). This usually means that "
               "it has encountered some error that I won't be able to "
               "understand. You should enable INFO-level tor log to see what "
               "it is saying - when INFO-level log is enabled, look for "
               "lines with 'report_proxy_stderr' (without quotes).",
               mp->argv[0]);

Hm, does this mean that the info-level logs will have the string report_proxy_stderr in them? Is this the case in the current code?

Also, do you think we should mention how to enable info-level logs in the log message? So that we avoid mails in tor-relays saying "I got this warning. How do I enable info-level logs?". But maybe that will make the log message too big/confusing.

comment:18 in reply to:  16 Changed 4 years ago by wfn

Replying to asn:

Replying to wfn:

Rebased once again (same branch) - to include an additional change which includes the report_proxy_stderr keyword that a user can look for when inspecting INFO-level tor log:

https://github.com/wfn/tor/compare/bug_9957_2 ->

Nice. This looks cleaner!

As a suggestion, to avoid needless nesting, maybe you would enjoy doing:

if (!proxy_err_output) {
    return
}
... do everything ...

instead of:

if (proxy_err_output) {
      ... do everything ...
}

Up to your preference :)

True, why have redundant nesting when you don't need to!

Also, AFAIK, we are using STATIC to mean "We should use static here, but we also need to unit test that function". Since you are not unittesting report_proxy_stderr() the function can be truly static like other functions in src/or/transports.c (for example handle_finished_proxy()).

Aha, looked around and understood tor's use of STATIC just now (I think.) Yes, so this is one of those functions that can safely reside only in transports.c for sure and which does not need a test. Ok.

(rebased again, fwiw - https://github.com/wfn/tor/compare/bug_9957_2)

Finally, we will need a changes file if we want this merged. I can write this for you, but you might want to write it on your own to get used to changes files for further Tor development :) As an example, see commit 71e0ca02b57f7945d922a8708a2c97815a9350ad.

For sure. :)

Does the following make sense, or should it be reworded in some way (also, is this a 'minor feature' or just 'bugfix'? I'm not even sure.) (Kept character count per line at < 75.) Is this too verbose/detailed?

  o Minor bugfixes (transport proxies):
    - Have Tor report stderr output of transport proxies to log.
      Previously we ignored standard error streams of transport proxies.
      This would sometimes cause confusion when they would fail
      prematurely (e.g. obfsproxy tracebacks get dumped to stderr.) We now
      make a notice when there's stderr output, and we log the output
      itself at INFO level. Implements ticket 9957.

comment:19 in reply to:  17 ; Changed 4 years ago by wfn

Replying to asn:

    log_notice(LD_GENERAL, "Managed proxy '%s' is giving some output over "
               "the standard error stream (stderr). This usually means that "
               "it has encountered some error that I won't be able to "
               "understand. You should enable INFO-level tor log to see what "
               "it is saying - when INFO-level log is enabled, look for "
               "lines with 'report_proxy_stderr' (without quotes).",
               mp->argv[0]);

Hm, does this mean that the info-level logs will have the string report_proxy_stderr in them? Is this the case in the current code?

Yes - e.g. look above at the log excerpt I pasted in.
So e.g.

Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "Traceback (most recent call last):"

Surely this is not platform-specific?

Also, do you think we should mention how to enable info-level logs in the log message? So that we avoid mails in tor-relays saying "I got this warning. How do I enable info-level logs?". But maybe that will make the log message too big/confusing.

Yeah, as I said before, I tried incorporating some kind of instruction/direction towards torrc, but it easily becomes 1) too verbose and 2) not universal advice. For example, I do Log info stdout - but most users don't launch tor by doing ./tor. And if you include a specific filename, will they be sure which directory it will be written to? Perhaps you could say Log info file <FILENAME>, but in that case I'd be compelled to include a notice "where <FILENAME> is some filename writable by tor". *If* having such a level of verbosity is OK, then sure, I can make something up. But for the advice to remain as universal as possible etc etc, it's somewhat hard. It is easy to confuse people even more.

But maybe a link to https://www.torproject.org/docs/tor-manual.html.en (or just the keywords "tor manual" (top result on startpage))? (imho current message is OK, though.)

comment:20 in reply to:  19 ; Changed 4 years ago by asn

Replying to wfn:

Replying to asn:

    log_notice(LD_GENERAL, "Managed proxy '%s' is giving some output over "
               "the standard error stream (stderr). This usually means that "
               "it has encountered some error that I won't be able to "
               "understand. You should enable INFO-level tor log to see what "
               "it is saying - when INFO-level log is enabled, look for "
               "lines with 'report_proxy_stderr' (without quotes).",
               mp->argv[0]);

Hm, does this mean that the info-level logs will have the string report_proxy_stderr in them? Is this the case in the current code?

Yes - e.g. look above at the log excerpt I pasted in.
So e.g.

Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "Traceback (most recent call last):"

Surely this is not platform-specific?

Ah, because of should_log_function_name(), I guess.

Changelog message looks good to me.

BTW, you don't need to declare the static function in transports.h. Just declare it on the top of transports.c along with handle_finished_proxy() etc.

Finally:

    /* Should we expect any output from stderr to contribute to the proxy
     * config process? (We assume not.) */
    log_info(LD_GENERAL, "Managed proxy '%s' says (over stderr): %s",
             mp->argv[0], escaped(line));
    /* (If we want to just output this stream in one go, we may use
     * get_string_from_pipe() - but this works, too.) */

Nitpick, but I'm not sure if the last comment is any useful.

Marking this as needs_revision for the function declaration and changes file.

comment:21 in reply to:  20 Changed 4 years ago by wfn

Replying to asn:

Replying to wfn:

Replying to asn:

    log_notice(LD_GENERAL, "Managed proxy '%s' is giving some output over "
               "the standard error stream (stderr). This usually means that "
               "it has encountered some error that I won't be able to "
               "understand. You should enable INFO-level tor log to see what "
               "it is saying - when INFO-level log is enabled, look for "
               "lines with 'report_proxy_stderr' (without quotes).",
               mp->argv[0]);

Hm, does this mean that the info-level logs will have the string report_proxy_stderr in them? Is this the case in the current code?

Yes - e.g. look above at the log excerpt I pasted in.
So e.g.

Apr 19 06:46:51.000 [info] report_proxy_stderr(): Managed proxy '/usr/local/bin/obfsproxy' says (over stderr): "Traceback (most recent call last):"

Surely this is not platform-specific?

Ah, because of should_log_function_name(), I guess.

Aha, I assume it's OK to rely on should_log_function_name() not changing in the foreseeable future (i.e. LOG_DEBUG and LOG_INFO-bound messages should always include function names. ref. log.c)

Changelog message looks good to me.

BTW, you don't need to declare the static function in transports.h. Just declare it on the top of transports.c along with handle_finished_proxy() etc.

Finally:

    /* Should we expect any output from stderr to contribute to the proxy
     * config process? (We assume not.) */
    log_info(LD_GENERAL, "Managed proxy '%s' says (over stderr): %s",
             mp->argv[0], escaped(line));
    /* (If we want to just output this stream in one go, we may use
     * get_string_from_pipe() - but this works, too.) */

Nitpick, but I'm not sure if the last comment is any useful.

Marking this as needs_revision for the function declaration and changes file.

Ok. Rebased as per your comments (the function declarations at the top of transports.c are not really in an line-they-are-defined-in-increasing-order, so placed the declaration where it seemed appropriate (nitpicking level > 9000, but hey)), included the changes file in commit.

=> https://github.com/wfn/tor/compare/bug_9957_2

let me know if I missed something.

comment:22 Changed 4 years ago by wfn

Status: needs_revisionneeds_review

comment:23 Changed 4 years ago by asn

Great. Some small tweaks in my branch bug_9957_2_tweaks.

I think this looks merge-ready to me.

Thanks!

comment:24 Changed 4 years ago by mcs

Cc: mcs added

comment:25 Changed 3 years ago by asn

Status: needs_reviewneeds_revision

It's worth noting that wfn's code only gets triggered during configure_proxy, that is while the managed proxy protocol is happening. So, if the managed proxy protocol completes, any stderr messages from the PT will be ignored.

It might be a good idea to keep an ear on PTs all the time, so that we can catch any exceptions that applications throw in the middle of their runtime (after configured as managed proxies).

Marking this as needs_revision, till we decide on behavior.

comment:26 Changed 3 years ago by wfn

I assume "keep an ear on PTs all the time" is currently not possible at all (handles are closed after configure_proxy())? (from the looks of it, that is indeed the case.)

asn: [19:58:18] Yawning: finding a good solution wrt logging, will probably involve implementing TransportControlPort[1] etc.
asn: [19:58:26] that is, some real time channel between PTs and Tor.
asn: [19:58:51] and people will need to implement it, etc.

[1]: something like this, i guess: https://lists.torproject.org/pipermail/tor-dev/2012-March/003364.html

Maybe a separate ticket might help? Because while this is probably a good long-term plan (and will prove to be very useful to people), I predict that the useful and relevant "having people be able to see tracebacks over stderr easily" functionality won't get to see the light of day for quite some time to come. :(

So "stderr report during configure_proxy()" in the short-ish term, and TransportControlPort (or related) in the long-er term makes sense. I can open a ticket if that would help (and if it would not further clutter things up.)

But i understand if there's some motivation to just Do It Right. I just think that stderr logging during PT init is a good standalone feature(/bugfix), too. (Granted, neither this ticket's original description, nor the bugfix itself makes it clear that this is all about/during PT initialization - this can be fixed, of course.)

*edit* typos, etc.

Last edited 3 years ago by wfn (previous) (diff)

comment:27 Changed 3 years ago by wfn

Just to summarize, I agree with yawning that the short-term idea would be to just fix/enhance this patch (proper/more documentation for functions; don't log_notice() the initial message if INFO-level logging is already enabled; unit test for report_proxy_stderr() and ideally for tor_process_get_stderr_pipe(), too), and have it be merged in 0.2.6.

(This short-term plan would not involve adding anything to main.c::run_scheduled_events() (somewhere next to pt_configure_remaining_proxies()). It's more simple and would be easier to get merged.)

comment:28 Changed 3 years ago by nickm

Keywords: 026-deferrable 026-triaged-1 added

comment:29 Changed 3 years ago by yawning

Owner: set to yawning
Status: needs_revisionassigned

comment:30 Changed 3 years ago by nickm

Milestone: Tor: 0.2.6.x-finalTor: 0.2.7.x-final

comment:31 Changed 3 years ago by nickm

Keywords: 027-triaged-1-in added

Marking some tickets as triaged-in for 0.2.7 based on early triage

comment:32 Changed 3 years ago by isabela

Keywords: SponsorS added
Points: small
Priority: minortrivial
Version: Tor: 0.2.7

comment:33 Changed 2 years ago by yawning

Keywords: orCoreTeam201508 added

comment:34 Changed 2 years ago by yawning

Keywords: TorCoreTeam201508 added; orCoreTeam201508 removed

comment:35 Changed 2 years ago by nickm

Keywords: TorCoreTeam201509 added; TorCoreTeam201508 removed

comment:36 Changed 2 years ago by nickm

Milestone: Tor: 0.2.7.x-finalTor: 0.2.8.x-final

comment:37 Changed 2 years ago by nickm

Keywords: SponsorS removed
Sponsor: SponsorS

Bulk-replace SponsorS keyword with SponsorS sponsor field in Tor component.

comment:38 Changed 2 years ago by yawning

Keywords: 028-triaged added
Type: defectenhancement
Version: Tor: 0.2.7Tor: unspecified

comment:39 Changed 2 years ago by nickm

Milestone: Tor: 0.2.8.x-finalTor: 0.2.???

Move a bunch of (but not all) low-priority items to 0.2.???. If you write a patch, it can still get into 0.2.8

comment:40 Changed 20 months ago by nickm

Keywords: TorCoreTeam201509 removed

Removing TorCoreTeam201509 from these tickets, since we do not own a time machine.

comment:41 Changed 18 months ago by nickm

Keywords: SponsorS-deferred added
Sponsor: SponsorS

Remove the SponsorS status from these items, which we already decided to defer from 0.2.9. add the SponsorS-deferred tag instead in case we ever want to remember which ones these were.

comment:42 Changed 12 months ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:43 Changed 11 months ago by nickm

Keywords: tor-03-unspecified-201612 added
Milestone: Tor: 0.3.???Tor: unspecified

Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.

comment:44 Changed 6 months ago by nickm

Keywords: tor-03-unspecified-201612 removed

Remove an old triaging keyword.

comment:45 Changed 6 months ago by nickm

Keywords: 027-triaged-in added

comment:46 Changed 6 months ago by nickm

Keywords: 027-triaged-in removed

comment:47 Changed 6 months ago by nickm

Keywords: 027-triaged-1-in removed

comment:48 Changed 6 months ago by nickm

Keywords: 026-triaged-1 removed

comment:49 Changed 6 months ago by nickm

Keywords: 028-triaged removed

comment:50 Changed 6 months ago by nickm

Keywords: 026-deferrable removed

comment:51 Changed 6 months ago by nickm

Keywords: tor-bridge added
Severity: Normal
Note: See TracTickets for help on using tickets.