Opened 3 years ago

Last modified 3 days ago

#10059 new defect

capture tor log messages before control connection is opened

Reported by: mcs Owned by: nickm
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: unspecified
Severity: Normal Keywords: tbb-usability, extdev-interview, tor-03-unspecified-201612, tbb-wants
Cc: brade, mikeperry, atagar, karsten, asn, catalyst Actual Points:
Parent ID: #9675 Points:
Reviewer: Sponsor:

Description

While working on ticket #9675, 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.

Child Tickets

TicketSummaryOwner
#6938Log early log messages to log files
#12501"Tor unexpectedly exited" if there is a wrong line in torrcbrade
#21542use Subprocess.jsm to launch torbrade

Change History (21)

comment:1 Changed 3 years ago by mcs

  • Parent ID set to #9675

comment:2 Changed 3 years ago by arma

  • Cc atagar added

I think the way arm et al handle this is by reading Tor's stdout until it switches over to the control protocol.

Damian, can you clarify how arm does it and whether you're satisfied with that?

comment:3 follow-up: Changed 3 years ago by nickm

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?

comment:4 in reply to: ↑ 3 Changed 3 years ago by mcs

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 (tor fails to start because it cannot open torrc). Maybe we do need to find a way for Tor Launcher to capture stdout.

comment:5 Changed 3 years ago by mcs

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).

comment:6 follow-up: Changed 3 years ago by 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…

comment:7 in reply to: ↑ 6 Changed 3 years ago by mcs

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.

comment:8 Changed 3 years ago by karsten

  • Cc karsten added

comment:9 follow-up: Changed 3 years ago by 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.

comment:10 Changed 3 years ago by mikeperry

  • Keywords tbb-usability extdev-interview added

comment:11 Changed 3 years ago by nickm

  • Milestone set to Tor: 0.2.???

comment:12 in reply to: ↑ 9 ; follow-up: Changed 15 months ago by mcs

  • Severity set to Normal

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.

comment:13 Changed 5 months ago by teor

  • Milestone changed from Tor: 0.2.??? to Tor: 0.3.???

Milestone renamed

comment:14 Changed 4 months ago by nickm

  • Keywords tor-03-unspecified-201612 added
  • Milestone changed from Tor: 0.3.??? to Tor: unspecified

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

comment:15 Changed 2 months ago by gk

  • Keywords tbb-wants added

comment:16 Changed 2 months ago by mcs

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 to track this idea.

comment:17 in reply to: ↑ 12 Changed 10 days ago by arma

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.

comment:18 Changed 10 days ago by asn

  • Cc asn added

comment:19 Changed 7 days ago by nickm

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?

comment:20 Changed 3 days ago by catalyst

  • Cc catalyst added

comment:21 Changed 3 days ago by mcs

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 #21542 does not work out.

Note: See TracTickets for help on using tickets.