capture tor log messages before control connection is opened
While working on ticket #9675 (moved), 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).
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.
Activity
changed milestone to %Tor: unspecified
Trac:
Parent: N/A to #9675 (moved)
I think the way arm et al handle this is by reading Tor's stdout until it switches over to the control protocol.
According to mcs above, "the Mozilla process control APIs do not provide a way to capture stdout or stderr".
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.
Another related question to consider: what to do with log messages if Tor dies before a controller connection can be made?
-
Replying to nickm:
Another related question to consider: what to do with log messages if Tor dies before a controller connection can be made?
This exact issue just came up in #10416 (moved) (tor fails to start because it cannot open torrc). Maybe we do need to find a way for Tor Launcher to capture stdout.
-
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: http://hg.mozilla.org/ipccode/file/b22a621afdc5/modules And newer version here: http://sourceforge.net/p/enigmail/source/ci/master/tree/ipc/modules/
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 #6152 (moved)).
-
Replying to lunar:
Probably naive idea: is there a way to redirect these early error messages to a file in
Data/Tor? It could just then be read in case of errors…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.
-
Replying to nickm:
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.
(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.
Trac:
Sponsor: N/A to N/A
Severity: N/A to Normal -
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 #21542 (moved) to track this idea.
Replying to mcs:
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.
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.
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.
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.
Plausible?
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.
