Tor Bug Tracker & Wiki: Ticket #10059: capture tor log messages before control connection is openedhttps://trac.torproject.org/projects/tor/ticket/10059
<p>
While working on ticket <a class="assigned ticket" href="https://trac.torproject.org/projects/tor/ticket/9675" title="#9675: defect: Provide feedback mechanism for clock-skew and other bad problems (assigned)">#9675</a>, Kathy Brade and I discovered that the tor log warnings regarding clock skew are sometimes generated very early as tor starts up. Unfortunately, there is a known problem in Tor Launcher where tor log messages are not captured until Tor Launcher is able to connect to the control port and issue a SETEVENTS command (the Mozilla process control APIs do not provide a way to capture stdout or stderr).
</p>
<p>
One solution is for tor to provide a way to retrieve old log messages (e.g., a new getinfo command) or otherwise provide a way to capture messages that are generated before a control connection is opened. Another option for this specific scenario would be to modify tor to ensure that clock skew is always reported via the status/bootstrap-phase mechanism.
</p>
en-usTor Bug Tracker & Wiki/images/tor-logo.pnghttps://trac.torproject.org/projects/tor/ticket/10059
Trac 1.2mcsThu, 31 Oct 2013 14:46:09 GMTparent sethttps://trac.torproject.org/projects/tor/ticket/10059#comment:1
https://trac.torproject.org/projects/tor/ticket/10059#comment:1
<ul>
<li><strong>parent</strong>
set to <em>#9675</em>
</li>
</ul>
TicketarmaFri, 01 Nov 2013 06:27:19 GMTcc changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:2
https://trac.torproject.org/projects/tor/ticket/10059#comment:2
<ul>
<li><strong>cc</strong>
<em>atagar</em> added
</li>
</ul>
<p>
I think the way arm et al handle this is by reading Tor's stdout until it switches over to the control protocol.
</p>
<p>
Damian, can you clarify how arm does it and whether you're satisfied with that?
</p>
TicketnickmFri, 01 Nov 2013 14:35:06 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:3
https://trac.torproject.org/projects/tor/ticket/10059#comment:3
<blockquote class="citation">
<p>
I think the way arm et al handle this is by reading Tor's stdout until it switches over to the control protocol.
</p>
</blockquote>
<p>
According to mcs above, "the Mozilla process control APIs do not provide a way to capture stdout or stderr".
</p>
<p>
I'd agree that the stdout solution is inelegant, and I'd be happy to consider something better. It wouldn't be too hard to cache log messages that happen before the original log configuration, or the original controller connection. Perhaps it should be controlled by a command-line option; perhaps also there should be an upper-limit on the buffer size.
</p>
<p>
Another related question to consider: what to do with log messages if Tor dies before a controller connection can be made?
</p>
TicketmcsWed, 18 Dec 2013 15:19:59 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:4
https://trac.torproject.org/projects/tor/ticket/10059#comment:4
<p>
Replying to <a class="ticket" href="https://trac.torproject.org/projects/tor/ticket/10059#comment:3" title="Comment 3">nickm</a>:
</p>
<blockquote class="citation">
<p>
Another related question to consider: what to do with log messages if Tor dies before a controller connection can be made?
</p>
</blockquote>
<p>
This exact issue just came up in <a class="new ticket" href="https://trac.torproject.org/projects/tor/ticket/10416" title="#10416: defect: Tor won't start on Windows when path contains non-ascii characters (new)">#10416</a> (tor fails to start because it cannot open torrc). Maybe we do need to find a way for Tor Launcher to capture stdout.
</p>
TicketmcsWed, 18 Dec 2013 15:35:47 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:5
https://trac.torproject.org/projects/tor/ticket/10059#comment:5
<p>
There is a replacement for Mozilla's nsIProcess API that is used by the Enigmail Thunderbird extension. It supports useful features like setting the working directory and capturing stdout. See:
</p>
<blockquote>
<p>
<a class="ext-link" href="http://hg.mozilla.org/ipccode/file/b22a621afdc5/modules"><span class="icon">​</span>http://hg.mozilla.org/ipccode/file/b22a621afdc5/modules</a>
</p>
</blockquote>
<p>
And newer version here:
</p>
<blockquote>
<p>
<a class="ext-link" href="http://sourceforge.net/p/enigmail/source/ci/master/tree/ipc/modules/"><span class="icon">​</span>http://sourceforge.net/p/enigmail/source/ci/master/tree/ipc/modules/</a>
</p>
</blockquote>
<p>
We could incorporate this module into Tor Launcher. It is entirely dependent on js-ctypes though, which I know Mike has been trying to eliminate/avoid (see <a class="new ticket" href="https://trac.torproject.org/projects/tor/ticket/6152" title="#6152: enhancement: Remove Chrome JS direct vectors to arbitrary machine code (new)">#6152</a>).
</p>
TicketlunarTue, 14 Jan 2014 15:55:57 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:6
https://trac.torproject.org/projects/tor/ticket/10059#comment:6
<p>
Probably naive idea: is there a way to redirect these early error messages to a file in <code>Data/Tor</code>? It could just then be read in case of errors…
</p>
TicketmcsTue, 14 Jan 2014 17:08:14 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:7
https://trac.torproject.org/projects/tor/ticket/10059#comment:7
<p>
Replying to <a class="ticket" href="https://trac.torproject.org/projects/tor/ticket/10059#comment:6" title="Comment 6">lunar</a>:
</p>
<blockquote class="citation">
<p>
Probably naive idea: is there a way to redirect these early error messages to a file in <code>Data/Tor</code>? It could just then be read in case of errors…
</p>
</blockquote>
<p>
I don't know if there are privacy or performance concerns related to sending the tor log messages to a file. We could, assuming tor supports it, disable the file-based logging after Tor Launcher is able to successfully connect to the control port.
</p>
TicketkarstenWed, 15 Jan 2014 07:25:54 GMTcc changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:8
https://trac.torproject.org/projects/tor/ticket/10059#comment:8
<ul>
<li><strong>cc</strong>
<em>karsten</em> added
</li>
</ul>
TicketnickmFri, 17 Jan 2014 17:13:44 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:9
https://trac.torproject.org/projects/tor/ticket/10059#comment:9
<p>
I'm okay with doing an in-tor solution for this if you decide one is necessary; just let me know. It would probably involve adding a log type that lets you store the last N kb of log messages in a queue, and later query them via the control port.
</p>
TicketmikeperryFri, 24 Jan 2014 06:58:54 GMTkeywords sethttps://trac.torproject.org/projects/tor/ticket/10059#comment:10
https://trac.torproject.org/projects/tor/ticket/10059#comment:10
<ul>
<li><strong>keywords</strong>
<em>tbb-usability</em> <em>extdev-interview</em> added
</li>
</ul>
TicketnickmFri, 28 Feb 2014 14:15:45 GMTmilestone sethttps://trac.torproject.org/projects/tor/ticket/10059#comment:11
https://trac.torproject.org/projects/tor/ticket/10059#comment:11
<ul>
<li><strong>milestone</strong>
set to <em>Tor: 0.2.???</em>
</li>
</ul>
TicketmcsThu, 21 Jan 2016 20:36:18 GMTseverity sethttps://trac.torproject.org/projects/tor/ticket/10059#comment:12
https://trac.torproject.org/projects/tor/ticket/10059#comment:12
<ul>
<li><strong>severity</strong>
set to <em>Normal</em>
</li>
</ul>
<p>
Replying to <a class="ticket" href="https://trac.torproject.org/projects/tor/ticket/10059#comment:9" title="Comment 9">nickm</a>:
</p>
<blockquote class="citation">
<p>
I'm okay with doing an in-tor solution for this if you decide one is necessary; just let me know. It would probably involve adding a log type that lets you store the last N kb of log messages in a queue, and later query them via the control port.
</p>
</blockquote>
<p>
(I am revisiting some old tickets today.) For Tor Launcher, it would be convenient to have a mechanism in tor such as the one you described. One tricky thing is that we would want to be sure Tor Launcher receives the entire, correct stream of messages (without duplicates or gaps), so we would need to figure out how to merge the queued messages with the ones we receive in response to SETEVENTS NOTICE WARN ERR. I am not sure how to do that unless tor assigns a sequence number or something similar to each message. Or it might work for tor to provide an option to send the queued messages as events as soon as the SETEVENTS command is received.
</p>
TicketteorTue, 15 Nov 2016 02:19:57 GMTmilestone changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:13
https://trac.torproject.org/projects/tor/ticket/10059#comment:13
<ul>
<li><strong>milestone</strong>
changed from <em>Tor: 0.2.???</em> to <em>Tor: 0.3.???</em>
</li>
</ul>
<p>
Milestone renamed
</p>
TicketnickmThu, 15 Dec 2016 22:20:14 GMTkeywords, milestone changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:14
https://trac.torproject.org/projects/tor/ticket/10059#comment:14
<ul>
<li><strong>keywords</strong>
<em>tor-03-unspecified-201612</em> added
</li>
<li><strong>milestone</strong>
changed from <em>Tor: 0.3.???</em> to <em>Tor: unspecified</em>
</li>
</ul>
<p>
Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.
</p>
TicketgkMon, 20 Feb 2017 08:21:22 GMTkeywords changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:15
https://trac.torproject.org/projects/tor/ticket/10059#comment:15
<ul>
<li><strong>keywords</strong>
<em>tbb-wants</em> added
</li>
</ul>
TicketmcsThu, 23 Feb 2017 17:12:34 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:16
https://trac.torproject.org/projects/tor/ticket/10059#comment:16
<p>
Another solution would be for Tor Launcher to capture tor's stderr. Recently, Mozilla added a new "subprocess" module that may allow us to do that. I created <a class="new ticket" href="https://trac.torproject.org/projects/tor/ticket/21542" title="#21542: defect: use Subprocess.jsm to launch tor (new)">#21542</a> to track this idea.
</p>
TicketarmaMon, 17 Apr 2017 19:00:21 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:17
https://trac.torproject.org/projects/tor/ticket/10059#comment:17
<p>
Replying to <a class="ticket" href="https://trac.torproject.org/projects/tor/ticket/10059#comment:12" title="Comment 12">mcs</a>:
</p>
<blockquote class="citation">
<p>
For Tor Launcher, it would be convenient to have a mechanism in tor such as the one you described. One tricky thing is that we would want to be sure Tor Launcher receives the entire, correct stream of messages (without duplicates or gaps), so we would need to figure out how to merge the queued messages with the ones we receive in response to SETEVENTS NOTICE WARN ERR. I am not sure how to do that unless tor assigns a sequence number or something similar to each message. Or it might work for tor to provide an option to send the queued messages as events as soon as the SETEVENTS command is received.
</p>
</blockquote>
<p>
In discussions with catalyst today, I think we hit upon a plausible approach: you start Tor with a config setting to enable this behavior, and then there's a single atomic controller command that a) pastes out all the queued messages to the controller, and b) stops queueing messages.
</p>
<p>
So the controller would connect, issue SETEVENTS commands the way it wants, possibly getting a few new events, and then it would request the old events. It would know that the old events came before the new ones, and it would also know that there aren't any duplicates.
</p>
<p>
Then Tor could keep on logging, sending events, etc just as it does now, but it would keep copies of them for when the controller comes asking.
</p>
<p>
Plausible?
</p>
<p>
For simplicity, we probably want to hard-code the types of events that get queued, rather than having the config option be flexible enough to hear which events you wanted. Or we could queue them all, and let the controller pick through them, but that could potentially get really big really quickly if it includes e.g. debug log events.
</p>
TicketasnMon, 17 Apr 2017 23:08:33 GMTcc changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:18
https://trac.torproject.org/projects/tor/ticket/10059#comment:18
<ul>
<li><strong>cc</strong>
<em>asn</em> added
</li>
</ul>
TicketnickmThu, 20 Apr 2017 14:04:47 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:19
https://trac.torproject.org/projects/tor/ticket/10059#comment:19
<p>
Based on the way control events are queued today, I think it might be easiest to have tree command line option list which events are to be queued?
</p>
TicketcatalystMon, 24 Apr 2017 16:45:28 GMTcc changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:20
https://trac.torproject.org/projects/tor/ticket/10059#comment:20
<ul>
<li><strong>cc</strong>
<em>catalyst</em> added
</li>
</ul>
TicketmcsMon, 24 Apr 2017 17:43:21 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:21
https://trac.torproject.org/projects/tor/ticket/10059#comment:21
<p>
If this is only needed by Tor Browser / Tor Launcher, please do not spend any time on it yet. We will come back and explore this solution if <a class="new ticket" href="https://trac.torproject.org/projects/tor/ticket/21542" title="#21542: defect: use Subprocess.jsm to launch tor (new)">#21542</a> does not work out.
</p>
TicketcatalystThu, 11 May 2017 15:40:39 GMTpriority changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:22
https://trac.torproject.org/projects/tor/ticket/10059#comment:22
<ul>
<li><strong>priority</strong>
changed from <em>Medium</em> to <em>Low</em>
</li>
</ul>
<p>
Lowering priority for now; if <a class="new ticket" href="https://trac.torproject.org/projects/tor/ticket/21542" title="#21542: defect: use Subprocess.jsm to launch tor (new)">#21542</a> turns out to not be suitable, we can bump it back up.
</p>
TicketarmaThu, 11 May 2017 20:38:42 GMThttps://trac.torproject.org/projects/tor/ticket/10059#comment:23
https://trac.torproject.org/projects/tor/ticket/10059#comment:23
<p>
Replying to <a class="ticket" href="https://trac.torproject.org/projects/tor/ticket/10059#comment:9" title="Comment 9">nickm</a>:
</p>
<blockquote class="citation">
<p>
I'm okay with doing an in-tor solution for this if you decide one is necessary; just let me know. It would probably involve adding a log type that lets you store the last N kb of log messages in a queue, and later query them via the control port.
</p>
</blockquote>
<p>
For historical context, check out <a class="closed ticket" href="https://trac.torproject.org/projects/tor/ticket/6938" title="#6938: defect: Log early log messages to log files (closed: implemented)">#6938</a> where we built something quite similar. So a lot of the structure for this goal already exists, should we choose to proceed.
</p>
TicketnickmTue, 23 May 2017 15:05:34 GMTkeywords changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:24
https://trac.torproject.org/projects/tor/ticket/10059#comment:24
<ul>
<li><strong>keywords</strong>
<em>tor-03-unspecified-201612</em> removed
</li>
</ul>
<p>
Remove an old triaging keyword.
</p>
TicketnickmMon, 05 Jun 2017 14:30:17 GMTpriority, type, milestone changed; points sethttps://trac.torproject.org/projects/tor/ticket/10059#comment:25
https://trac.torproject.org/projects/tor/ticket/10059#comment:25
<ul>
<li><strong>priority</strong>
changed from <em>Low</em> to <em>Medium</em>
</li>
<li><strong>points</strong>
set to <em>3</em>
</li>
<li><strong>type</strong>
changed from <em>defect</em> to <em>enhancement</em>
</li>
<li><strong>milestone</strong>
changed from <em>Tor: unspecified</em> to <em>Tor: 0.3.2.x-final</em>
</li>
</ul>
<p>
If this is still tbb-wants, we can do it in 0.3.2.
</p>
TicketnickmTue, 12 Sep 2017 20:38:19 GMTmilestone changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:26
https://trac.torproject.org/projects/tor/ticket/10059#comment:26
<ul>
<li><strong>milestone</strong>
changed from <em>Tor: 0.3.2.x-final</em> to <em>Tor: 0.3.3.x-final</em>
</li>
</ul>
TicketnickmMon, 23 Oct 2017 15:44:24 GMTpriority changed; sponsor sethttps://trac.torproject.org/projects/tor/ticket/10059#comment:27
https://trac.torproject.org/projects/tor/ticket/10059#comment:27
<ul>
<li><strong>priority</strong>
changed from <em>Medium</em> to <em>High</em>
</li>
<li><strong>sponsor</strong>
set to <em>Sponsor8</em>
</li>
</ul>
TicketgkFri, 03 Nov 2017 08:47:30 GMTkeywords changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:28
https://trac.torproject.org/projects/tor/ticket/10059#comment:28
<ul>
<li><strong>keywords</strong>
<em>tbb-needs</em> added; <em>tbb-wants</em> removed
</li>
</ul>
<p>
Let's just use <code>tbb-needs</code> and use priority there to indicate how urgent we'd like to have those tickets fixed.
</p>
TicketnickmWed, 24 Jan 2018 20:53:05 GMTmilestone changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:29
https://trac.torproject.org/projects/tor/ticket/10059#comment:29
<ul>
<li><strong>milestone</strong>
changed from <em>Tor: 0.3.3.x-final</em> to <em>Tor: 0.3.4.x-final</em>
</li>
</ul>
<p>
Deferring various "new"-status enhancement tickets to 0.3.4
</p>
TicketnickmWed, 28 Mar 2018 19:21:47 GMTkeywords changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:30
https://trac.torproject.org/projects/tor/ticket/10059#comment:30
<ul>
<li><strong>keywords</strong>
<em>034-triage-20180328</em> added
</li>
</ul>
TicketnickmWed, 28 Mar 2018 19:25:28 GMTkeywords changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:31
https://trac.torproject.org/projects/tor/ticket/10059#comment:31
<ul>
<li><strong>keywords</strong>
<em>034-removed-20180328</em> added
</li>
</ul>
<p>
Per our triage process, these tickets are <strong>pending</strong> removal from 0.3.4.
</p>
TicketnickmThu, 05 Apr 2018 15:32:57 GMTkeywords changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:32
https://trac.torproject.org/projects/tor/ticket/10059#comment:32
<ul>
<li><strong>keywords</strong>
<em>034-removed-20180328</em> removed
</li>
</ul>
TicketnickmFri, 11 May 2018 18:12:08 GMTmilestone changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:33
https://trac.torproject.org/projects/tor/ticket/10059#comment:33
<ul>
<li><strong>milestone</strong>
changed from <em>Tor: 0.3.4.x-final</em> to <em>Tor: 0.3.5.x-final</em>
</li>
</ul>
<p>
These are still worth doing, but I don't see them as likely to happen before our freeze in 4 days, and nobody is currently assigned to them. Deferring them to 0.3.5
</p>
TicketnickmWed, 11 Jul 2018 11:19:53 GMTkeywords, milestone changedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:34
https://trac.torproject.org/projects/tor/ticket/10059#comment:34
<ul>
<li><strong>keywords</strong>
<em>035-removed-20180711</em> added
</li>
<li><strong>milestone</strong>
changed from <em>Tor: 0.3.5.x-final</em> to <em>Tor: unspecified</em>
</li>
</ul>
<p>
These tickets are being triaged out of 0.3.5. The ones marked "035-roadmap-proposed" may return.
</p>
TicketgabaFri, 11 Jan 2019 22:29:03 GMTsponsor deletedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:35
https://trac.torproject.org/projects/tor/ticket/10059#comment:35
<ul>
<li><strong>sponsor</strong>
<em>Sponsor8</em> deleted
</li>
</ul>
TicketnickmMon, 17 Jun 2019 19:00:33 GMTstatus changed; owner deletedhttps://trac.torproject.org/projects/tor/ticket/10059#comment:36
https://trac.torproject.org/projects/tor/ticket/10059#comment:36
<ul>
<li><strong>owner</strong>
<em>nickm</em> deleted
</li>
<li><strong>status</strong>
changed from <em>new</em> to <em>assigned</em>
</li>
</ul>
<p>
I am not actually working on these tickets, so they shouldn't be assigned to me.
</p>
Ticket