log bootstrap tag name for easier troubleshooting

We might change what specific bootstrap progress numbers mean from time to time. We should log the tag name, to make troubleshooting easier, especially when users report problems. Right now we have to interpret the numeric progress numbers from users, which isn't great. We send the tag name to the control port, but we don't log it.

changed milestone to %Tor: 0.4.0.x-final

added component::core tor/tor milestone::Tor: 0.4.0.x-final owner::catalyst parent::28018 points::0.1 priority::medium resolution::implemented s8-bootstrap severity::normal sponsor::8-can status::closed type::defect labels

Trac:
Status: new to assigned
Owner: N/A to catalyst
Points: N/A to 0.1

Pull requests for 0.3.3 and 0.3.5. The 0.3.3 patch merges cleanly to 0.3.4.

Trac:
Status: assigned to needs_review
Milestone: Tor: 0.4.0.x-final to Tor: 0.3.5.x-final
Keywords: N/A deleted, 035-backport-maybe, 033-backport-maybe, 034-backport-maybe added

The 0.3.5 patch breaks TEST_STEM because stem currently wants to see a : after the % in the bootstrap log messages. stem probably should relax this pattern a little.

catalyst and I have been chatting on irc. Stem's launch_tor() method parses bootstrap messages to determine how far along with the launch process we are. From a cursory glance at other potential users...

• launch-tor uses the control port

• txtorcon mentions checking for a bootstrap message but I didn't spot anything that seemed to care about the format.

• Chutney simply sleeps. I didn't spot any bootstrap handling.

Is it a problem if Stem's launch_tor method breaks? Honestly I don't know. Nyx and DocTor don't use it so my codebases won't mind, but I wouldn't be surprised if others do.

Stem's tor-prompt command will break but that's mostly used by us so not the end of the would.

Honestly this feels like a lateral move to me so I'd lean against, but again I don't have much of a dog in this. Happy to defer to the network team.

Replying to atagar:

Honestly this feels like a lateral move to me so I'd lean against, but again I don't have much of a dog in this. Happy to defer to the network team.

My two cents. In my opinion, no third part application should consider tor logging as an "ABI" that is parsing a stream of text to learn the running status of tor. Tor has the control port for that.

HOWEVER, I wouldn't be surprised that some application do it for the NOTICE level logs (at least) since not all tor operators/clients want their control port open so I understand the decision to look for Bootstrapped [...] lines. There is literally a security argument that could be made to do that instead of requiring to open the control port.

We've never spec that out nor made it a stable ABI for the log notice. We've modified notice lines many times over the years and I think, at this point in time, it is still fine. It is really more flexible for the network team and allows us to improve over time the notice logs that can change due to new subsystems or changes of behaviors that require reporting new/modified values.

Ultimately, final decision comes down to our great maintainer, nickm :).

Code lgtm;

Trac:
Status: needs_review to merge_ready

Thanks! Note that CI will fail until stem's matching is relaxed.

Hi David, I agree with everything you said. Parsing the bootstrap lines is no bueno but is done anyway because it's the only game in town when the user hasn't opened a control port.

Quick food for thought: how about a '--bootstrap-status' argument to tor which, when provided, has tor provide machine parseable messages on stdout? This would allow the network team to freely update these human read messages at will, but also provide a formally speced message that scripts who lack a control port can use as well to get the bootstrapping status.

So here's my tentative opinion:

1. Log messages are not intended to be machine readable, and parsing them is always asking for something to break.

2. If you find yourself having to parse a log message, then we are missing some kind of feature to provide the information in some other way, so that you don't have to parse the log message. So the bug might be ours -- we should not assume that applications doing this are being wrong, but rather that we are forcing them to be risky.

3. We could make status events available even earlier, via the OwningControllerFd interface. We might want to have a new option that sets the initial events (like SETEVENTS) on the OwningControllerFd, if that would help.

4. If there is not one already, there should be a GETINFO command that returns the current bootstrap status, so that you don't need to see all the previous bootstrap messages to learn how bootstrapped Tor is.

None of these feel like blockers to me, though. If folks don't disagree too strongly, I'll have a look at this code and probably merge it.

(The code lgtm, and I'll merge so long as there are no objections)

No objection from me. Again, this will likely break a few small applications such as OnionLauncher and TorNova (QT and GTK tor launchers), but I do not maintain those so I'm not saying this is a blocker - just that we might have some sad folks.

I would be happy to adjust Stem's regex but if we move forward with this I'd appreciate a ticket for the long term solution. Adjusting the regex will make us work but we'll still be relying on the log messages (which I think we all agree is bad).

The problem I'd like to address is simply: 'provide a way for applications to determine tor's bootstrap status without a ControlPort'. That's all. There's lots of ways for us to do that (writing a file to disk, stdout via something like the '--bootstrap-status' argument mentioned above, etc). They're all good by me. :)

Merged to 0.3.5 and forward. (Had a conflict in master, resolved with f8dac5c900856494867996f60da848b0111aad35.)

Marking for possible backport, though I would argue against: our boostrapping issues are mostly stuff we're going to fix in 0.4.0.x and beyond.

Trac:
Milestone: Tor: 0.3.5.x-final to Tor: 0.3.4.x-final

#28844 (closed) is the stem ticket for adjusting stem's bootstrap regex.

Quick note since it's relevant for this: Nick and I discussed hooks stem can use rather than bootstram messages and Stem will soon use tor's spiffy new OwningControllerFD capability instead...

https://gitweb.torproject.org/torspec.git/tree/control-spec.txt#n3396

Rather than reading bootstrap messages Stem will launch its tor instances with a temporary control socket that renounces its ownership and closes once bootstrapped. Nick is adding a 'DROPOWNERSHIP' command to make this work (thanks Nick!)...

https://trac.torproject.org/projects/tor/ticket/28843

nickm: Is it at all possible to revert this until Stem 1.8 is closer to be released. My concern is losing e.g. Tails as a platform if it upgrades Tor to 0.4.0 before the release of next Stem. As for Ubuntu etc., is it still possible to install 0.3.5 after the main repositories update to 0.4.0?

Trac:
Username: maqp

What's the schedule for stem 1.8? Tor 0.4.0.x won't release an alpha till January, and it won't have a stable release till April at the earliest.

For Ubuntu, I hope they stick with 0.3.5 for a long time; it's an LTS release.

Hi Nick. Stem had a release just a few weeks ago and generally accumulates enough changes to warrant another release annually.

I cautioned above that this will make folks sad. I see three options here...

1. Revert or punt this tor commit for a year. Stem aside, personally I don't understand why this change is desirable. That said, once we have DROPOWNERSHIP and Stem 1.8 is out I won't care what modifications you make to the bootstrap messages.

2. Release a Stem 1.7.1 hotfix release. This creates work for our packaging community and I avoid it unless there's a critical bug, but if this logging change is really important to you we can go this route.

3. Continue as-is and break callers of launch_tor(). This is the route the network team seemed to prefer on this ticket.

As it stands, a hotfix seems like the best option to me. So long as Stem still depends on any of Tor's log message formats, it is depending on an explicitly not-guaranteed behavior, and users IMO ought to expect that sometimes they need to upgrade to the latest Stem if they want support for the latest Tor.

But let's talk more here; I'd like a better sense of what we actually get from this change.

Summary -- I've talked with atagar a bit about this on IRC, and here's the plan:

1. We'll see whether this is something we want to keep. I'm 80% leaning towards yes.
2. If we say yes, or Damian hasn't heard from us by the end of the week, he puts out a hotfix next week.
3. We look for other places where Stem might depend on undocumented/unspecified tor output formats, and either document them, or provide stem another way to get that info. (#28889 (moved) was the only one we found.)