[tor-bugs] #9957 [Tor]: Tor should consider stderr output of transport proxies

[Tor Bug Tracker & Wiki]

#9957: Tor should consider stderr output of transport proxies
------------------------+--------------------------------
     Reporter:  wfn     |      Owner:
         Type:  defect  |     Status:  needs_review
     Priority:  minor   |  Milestone:  Tor: 0.2.6.x-final
    Component:  Tor     |    Version:
   Resolution:          |   Keywords:  tor-pt
Actual Points:          |  Parent ID:
       Points:          |
------------------------+--------------------------------

Comment (by wfn):

 Replying to [comment:8 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]`. Figuring out which
 argument is an actual argument and which one is part of the proxy call is
 probably a hairy thing, or impossible.)

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/9957#comment:14>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online