Opened 10 months ago

Closed 9 months ago

Last modified 6 months ago

#28731 closed defect (implemented)

log bootstrap tag name for easier troubleshooting

Reported by: catalyst Owned by: catalyst
Priority: Medium Milestone: Tor: 0.4.0.x-final
Component: Core Tor/Tor Version:
Severity: Normal Keywords: s8-bootstrap
Cc: Actual Points:
Parent ID: #28018 Points: 0.1
Reviewer: Sponsor: Sponsor8-can

Description

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.

Child Tickets

Change History (24)

comment:1 Changed 10 months ago by catalyst

Owner: set to catalyst
Points: 0.1
Status: newassigned

comment:2 Changed 9 months ago by catalyst

Keywords: 033-backport-maybe 034-backport-maybe 035-backport-maybe added
Milestone: Tor: 0.4.0.x-finalTor: 0.3.5.x-final
Status: assignedneeds_review

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

comment:3 Changed 9 months ago by catalyst

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.

comment:4 Changed 9 months ago by atagar

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

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

comment:5 in reply to:  4 Changed 9 months ago by dgoulet

Status: needs_reviewmerge_ready

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;

comment:6 Changed 9 months ago by catalyst

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

comment:7 Changed 9 months ago by atagar

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.

comment:8 Changed 9 months ago by nickm

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

comment:9 Changed 9 months ago by nickm

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

comment:10 Changed 9 months ago by atagar

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

comment:11 Changed 9 months ago by nickm

Milestone: Tor: 0.3.5.x-finalTor: 0.3.4.x-final

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.

comment:12 Changed 9 months ago by catalyst

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

comment:13 Changed 9 months ago by atagar

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

comment:14 Changed 9 months ago by maqp

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?

comment:15 Changed 9 months ago by nickm

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.

comment:16 Changed 9 months ago by atagar

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.
  1. 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.
  1. Continue as-is and break callers of launch_tor(). This is the route the network team seemed to prefer on this ticket.

comment:17 Changed 9 months ago by nickm

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.

comment:18 Changed 9 months ago by nickm

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 was the only one we found.)

comment:19 Changed 9 months ago by maqp

Awesome! Thank you so much!

comment:20 Changed 9 months ago by nickm

Also, I see that this had been backported to 0.3.5.x. I think we should revert that backport, and let this be a change in 0.4.0.x.

comment:21 Changed 9 months ago by nickm

Milestone: Tor: 0.3.4.x-finalTor: 0.3.5.x-final

Reverted in 0.3.5 with c61cd5775c137ef45f5449b9f996c05c63c21acf.

comment:22 Changed 9 months ago by atagar

I've issues a Stem 1.7.1 hotfix release with this regex adjustment and notified our packaging community.

https://gitweb.torproject.org/stem.git/commit/?id=991291c
https://pypi.org/project/stem/

comment:23 Changed 9 months ago by nickm

Milestone: Tor: 0.3.5.x-finalTor: 0.4.0.x-final
Resolution: implemented
Status: merge_readyclosed

Going to call this "no backport"; 0.4.0 will be the one that has this change.

comment:24 Changed 6 months ago by teor

Keywords: 033-backport-maybe 034-backport-maybe 035-backport-maybe removed

No backport.

Note: See TracTickets for help on using tickets.