Opened 6 months ago

Closed 5 months ago

#25511 closed enhancement (implemented)

Expose TZ info on control port for better debugging of time errors

Reported by: nickm Owned by: neel
Priority: Medium Milestone: Tor: 0.3.4.x-final
Component: Core Tor/Tor Version:
Severity: Normal Keywords: roadmap, controller, 034-roadmap-master, 034-triage-20180328, 034-included-20180328, s8-errors, tor-spec
Cc: catalyst, mikeperry, neel@…, mcs, brade Actual Points:
Parent ID: Points:
Reviewer: catalyst Sponsor: Sponsor8

Description (last modified by catalyst)

When we tell people that their clocks are wrong, it's frequently because they've set up their systems with the wrong time zone. It would be helpful to tell torbrowser (or some other controller) about this information, so that it can give more useful error messages on time-related bootstrapping failures.

One complication here is (IIUC) TB runs, and runs tor, with its TZ set to UTC.

Further investigation suggests that TB might not set TZ for the first time it starts tor. Opened #25823 for the Tor Launcher behavior inconsistency.

Child Tickets

Attachments (6)

b25511-001.patch (3.9 KB) - added by neel 6 months ago.
Patch (Revision 1)
b25511-002.patch (6.4 KB) - added by neel 6 months ago.
Patch (Revision 2)
b25511-003.patch (8.8 KB) - added by neel 6 months ago.
Patch (Revision 3)
b25511-004.patch (8.5 KB) - added by neel 5 months ago.
Patch (Revision 4)
b25511-torspec-001.patch (874 bytes) - added by neel 5 months ago.
Torspec patch (Revision 1)
b25511-torspec-002.patch (874 bytes) - added by neel 5 months ago.
Torspec patch (Revision 1)

Download all attachments as: .zip

Change History (61)

comment:1 Changed 6 months ago by nickm

Keywords: 034-roadmap-master added

comment:2 Changed 6 months ago by nickm

Keywords: 034-triage-20180328 added

comment:3 Changed 6 months ago by nickm

Keywords: 034-included-20180328 added

comment:4 Changed 6 months ago by neel

Cc: neel@… added
Owner: set to neel
Status: newassigned

comment:5 Changed 6 months ago by neel

I am interested in taking this ticket and am thinking about additional GETINFO options. Namely, GETINFO time-local for the local computer time and GETINFO time-consensus for the consensus time. Would this work? Is there something I should do instead?

comment:6 Changed 6 months ago by nickm

current-time/local and current-time/utc sound useful. current-time/consensus is probably a misnomer, since that wouldn't tell you the current time, but only a lower-bound on the current time.

Probably just the first two, though, would be a good start.

comment:7 Changed 6 months ago by mcs

Cc: mcs brade added

comment:8 Changed 6 months ago by catalyst

My understanding from talking with Georg at the Rome meeting is that Tor Browser does change to UTC for fingerprinting resistance, but that doesn't affect the child tor process, which is started with a different environment.

comment:9 Changed 6 months ago by catalyst

Keywords: s8-errors added
Sponsor: Sponsor8

comment:10 in reply to:  6 Changed 6 months ago by catalyst

Replying to nickm:

current-time/local and current-time/utc sound useful. current-time/consensus is probably a misnomer, since that wouldn't tell you the current time, but only a lower-bound on the current time.

Probably just the first two, though, would be a good start.

Agree that current-time/consensus is less useful. (and unlike the other two, it's best stored as a lower-bound offset between network time and our local idea of UTC) If instead we try to infer the correct time of day based on information we have from the Tor network, we could expose that as a GETINFO command. I think that should get its own ticket, because a subsystem to help a client model the Tor network's idea of the time of day seems tricky.

comment:11 Changed 6 months ago by neel

Right now, I am working on a patch. However, I do have one question: Should the time be in ISO format?

comment:12 Changed 6 months ago by nickm

I think ISO makes the most sense; it's very easy to parse -- especially the iso_nospace variant we use in some places.

Changed 6 months ago by neel

Attachment: b25511-001.patch added

Patch (Revision 1)

comment:13 Changed 6 months ago by neel

I have a patch which should add these commands. The filename is b25511-001.patch.

comment:14 Changed 6 months ago by teor

Status: assignedneeds_review

comment:15 in reply to:  13 Changed 6 months ago by catalyst

Replying to neel:

I have a patch which should add these commands. The filename is b25511-001.patch.

Hi! Thanks for working on the patch. Would you be willing to submit it as a GitHub pull request at https://github.com/torproject/tor ? That would allow us to run Travis CI on it and make it easier to review. Thanks.

comment:16 Changed 6 months ago by asn

Reviewer: catalyst

comment:17 Changed 6 months ago by neel

I have uploaded a GitHub pull request: https://github.com/torproject/tor/pull/38

Also, it seems all tests have passed.

comment:18 Changed 6 months ago by mcs

I am trying to understand how Tor Browser or Tor Launcher should use this new capability. This may be a dumb question, but can someone explain what they have in mind? How are the values that will be returned by current-time/local and/or current-time/utc determined?

comment:19 in reply to:  18 Changed 6 months ago by arma

Replying to mcs:

I am trying to understand how Tor Browser or Tor Launcher should use this new capability. This may be a dumb question, but can someone explain what they have in mind?

Great question. I think the vision was something like "Tor browser, when it gets a clock skew warning, would tell the user that there might be a problem with their clock, and as part of that telling, it would try to walk them through figuring out if they have their time zone wrong. For example, plenty of users have their time seem correct ("it's 2pm and my clock says it's 2pm") yet their time zone is wrong so their time is actually secretly wrong. And the hope was that having these two strings from Tor would be useful in that user interaction.

How are the values that will be returned by current-time/local and/or current-time/utc determined?

I expect it is simply "print time to string using TZ" and "print time to string using UTC".

comment:20 in reply to:  18 Changed 6 months ago by neel

Replying to mcs:

I am trying to understand how Tor Browser or Tor Launcher should use this new capability. This may be a dumb question, but can someone explain what they have in mind? How are the values that will be returned by current-time/local and/or current-time/utc determined?

The first is already answered in previous messages. About the second one, tor_gettimeofday() is used to return the time, and then it is formatted into ISO format via format_iso_time_nospace() or format_local_iso_time_nospace()` (the latter is being added with this bug).

comment:21 in reply to:  17 Changed 6 months ago by catalyst

Replying to neel:

I have uploaded a GitHub pull request: https://github.com/torproject/tor/pull/38

Also, it seems all tests have passed.

Thanks! Looks good so far. Would you be willing to write unit tests and a changes file? (Please see doc/HACKING/CodingStandards.md and doc/HACKING/WritingTests.md for details. Existing tests for control port features seem to be in src/tests/test_controller.c.)

Changed 6 months ago by neel

Attachment: b25511-002.patch added

Patch (Revision 2)

comment:22 Changed 6 months ago by neel

I have uploaded a new patch (b25511-002.patch), it passes regression tests, and I have uploaded a new GitHub Pull request for CI (https://github.com/torproject/tor/pull/42) which seems it has compiled.

comment:23 Changed 6 months ago by catalyst

Status: needs_reviewmerge_ready

Looks good to me! Thanks!

comment:24 Changed 6 months ago by mikeperry

Thank you neel! I really appreciate this. This was originally going to fall to me or catalyst. More time for vanguards now :)

This looks good, but as a note, Tor Browser is going to have to remember not to overwrite the TZ environment variable before or while it launches Tor for current-time/local to not also be UTC. (This may mean saving the previous TZ value before we set it to UTC, and using that in the environ for tor).

comment:25 in reply to:  24 Changed 6 months ago by teor

Replying to mikeperry:

Thank you neel! I really appreciate this. This was originally going to fall to me or catalyst. More time for vanguards now :)

This looks good, but as a note, Tor Browser is going to have to remember not to overwrite the TZ environment variable before or while it launches Tor for current-time/local to not also be UTC. (This may mean saving the previous TZ value before we set it to UTC, and using that in the environ for tor).

Tor currently logs in UTC when launched by Tor Browser. If we use the OS TZ variable, it will log every message in the local timezone, and some messages also contain UTC times. Does this cause issues with disk traces, or does TBB avoid leaving tor logs around? Do we want users posting logs in their local timezone to trac? (Some timezone offsets are quite unique.)

comment:26 in reply to:  24 Changed 6 months ago by catalyst

Replying to mikeperry:

Thank you neel! I really appreciate this. This was originally going to fall to me or catalyst. More time for vanguards now :)

This looks good, but as a note, Tor Browser is going to have to remember not to overwrite the TZ environment variable before or while it launches Tor for current-time/local to not also be UTC. (This may mean saving the previous TZ value before we set it to UTC, and using that in the environ for tor).

On Tor Browser "8.0a5 (based on Mozilla Firefox 52.7.3) (64-bit)" on macOS, the logs from the tor daemon seem to be in UTC (at least when using the "Copy Tor Log To Clipboard" button).

On the other hand, Georg told me at the Rome meeting that Tor Browser sets TZ to UTC for anti-fingerprinting but starts the tor process in the local time zone. This seems to match what I've seen in the past, but I don't have a working older Tor Browser to check that right now.

comment:27 Changed 6 months ago by catalyst

On Linux, Tor Browser "7.5a8 (based on Mozilla Firefox 52.5.0) (64-bit)" with a custom config to log to a file on disk, the log file shows local time stamps but the "Copy Tor Log To Clipboard" button shows UTC time stamps. The disk files have log levels in lowercase, while the clipboard logs have them in uppercase. These imply that Tor Launcher might be postprocessing logs a little, or might be using control channel events to get log messages.

comment:28 Changed 6 months ago by catalyst

I just noticed that there might be a race condition if the time of day changes its seconds value between the calls to tor_gettimeofday() and getinfo_helper_current_time(). Maybe this happens rarely enough in practice that it won't be a problem.

If it is a problem, mocking tor_gettimeofday() to return a fixed value might be the best solution.

comment:29 Changed 6 months ago by nickm

+1 to catalyst's concern here -- this kind of failure will happen intermittently then the unit tests run on heavily loaded slow systems.

comment:30 Changed 6 months ago by neel

I can understand the race condition.

Should we do this? If so, how should we mock the tor_gettimeofday()?

comment:31 in reply to:  27 ; Changed 6 months ago by mcs

Replying to catalyst:

On Linux, Tor Browser "7.5a8 (based on Mozilla Firefox 52.5.0) (64-bit)" with a custom config to log to a file on disk, the log file shows local time stamps but the "Copy Tor Log To Clipboard" button shows UTC time stamps. The disk files have log levels in lowercase, while the clipboard logs have them in uppercase. These imply that Tor Launcher might be postprocessing logs a little, or might be using control channel events to get log messages.

Tor Launcher gets this info via the control port. It uses SETEVENTS to monitor NOTICE, WARN, and ERR events. When an event is received, Tor Launcher records the current timestamp (by creating a new JavaScript Date() object). When the user asks to copy the log to the clipboard, timestamps are converted to strings. Because the entire browser is running with UTC as the timezone, the timestamps that are output are UTC. But I am a little surprised that tor is not started with TZ=UTC (we patch the Firefox code to set TZ to UTC early during browser startup).

comment:32 in reply to:  31 Changed 6 months ago by catalyst

Replying to mcs:

But I am a little surprised that tor is not started with TZ=UTC (we patch the Firefox code to set TZ to UTC early during browser startup).

Thanks for the confirmation of the control port usage. These next observations are for Tor Browser "8.0a5 (based on Mozilla Firefox 52.7.3) (64-bit)" on Linux. It seems that when Tor Launcher starts a tor subprocess for the first time, the TZ environment variable is unset. For me, this results in tor logging to a file in local time (probably because of my /etc/localtime symlink). If that tor subprocess dies for some reason, Tor Browser seems to restart tor with TZ=UTC set explicitly, so it logs to a file in UTC. I determined these by inspecting the TZ environment variable by calling getenv() within the process while attached with gdb.

comment:33 in reply to:  30 Changed 6 months ago by catalyst

Status: merge_readyneeds_revision

Replying to neel:

I can understand the race condition.

Should we do this? If so, how should we mock the tor_gettimeofday()?

In doc/HACKING/WritingTests.md are some instructions about how to make a function mockable and how to later mock it in a test. Right now I think tor_gettimeofday() isn't mockable, but that should be easily fixed.

Please let us know if you have additional questions or would like any help with this.

Changed 6 months ago by neel

Attachment: b25511-003.patch added

Patch (Revision 3)

comment:34 Changed 6 months ago by neel

New patch: b25511-003.patch.

I also mocked tor_gettimeofday() here.

comment:35 Changed 6 months ago by nickm

Status: needs_revisionneeds_review

comment:36 Changed 6 months ago by catalyst

Description: modified (diff)

comment:37 Changed 5 months ago by catalyst

Description: modified (diff)

Please direct further discussion about Tor Launcher's setting of TZ for tor to #25823.

comment:38 in reply to:  34 Changed 5 months ago by catalyst

Status: needs_reviewneeds_revision

Replying to neel:

New patch: b25511-003.patch.

I also mocked tor_gettimeofday() here.

Thanks! I think that's most of what we need.

A few small changes, and I think we'll be good:

  • mock_tor_gettimeofday() can be in src/test/test_controller.c because nothing else uses it
  • mock_tor_gettimeofday() doesn't have to be declared with MOCK_DECL() nor defined with MOCK_IMPL(); it can be defined as static in src/test/test_controller.c

Please feel free to force-push your updated changes to your GitHub pull request.

Changed 5 months ago by neel

Attachment: b25511-004.patch added

Patch (Revision 4)

comment:39 Changed 5 months ago by neel

I have a new patch: b25511-004.patch.

It also passes CI: https://github.com/torproject/tor/pull/51.

comment:40 Changed 5 months ago by nickm

Status: needs_revisionneeds_review

comment:41 in reply to:  39 Changed 5 months ago by catalyst

Status: needs_reviewmerge_ready

Replying to neel:

I have a new patch: b25511-004.patch.

It also passes CI: https://github.com/torproject/tor/pull/51.

Thanks! Looks good; setting to merge_ready.

comment:42 Changed 5 months ago by dgoulet

Keywords: tor-spec added

Quick note. We can't merge this (or at least release) without a control spec change. Would be important to get a control-spec.txt branch for this as well.

comment:43 in reply to:  42 ; Changed 5 months ago by catalyst

Replying to dgoulet:

Quick note. We can't merge this (or at least release) without a control spec change. Would be important to get a control-spec.txt branch for this as well.

Thanks, I think I agree.

neel: would you be willing to work on that spec change?

comment:44 in reply to:  43 Changed 5 months ago by neel

Replying to catalyst:

Replying to dgoulet:

Quick note. We can't merge this (or at least release) without a control spec change. Would be important to get a control-spec.txt branch for this as well.

Thanks, I think I agree.

neel: would you be willing to work on that spec change?

Well, yes. I haven't started yet but will get to it.

Changed 5 months ago by neel

Attachment: b25511-torspec-001.patch added

Torspec patch (Revision 1)

comment:45 Changed 5 months ago by neel

I have a patch for torspec: b25511-torspec-001.patch.

comment:46 Changed 5 months ago by catalyst

Status: merge_readyneeds_review

comment:47 in reply to:  45 Changed 5 months ago by catalyst

Status: needs_reviewneeds_revision

Replying to neel:

I have a patch for torspec: b25511-torspec-001.patch.

Thanks! It might be good to say it's specifically the ISOTime2 because that's what we call the T-separated version in control-spec.txt.

I did notice that in control-spec.txt we currently only use ISOTime2 to define ISOTime2Frac, and don't actually use plain ISOTime2 in the existing control protocol. Maybe we want to reconsider using ISOTime (the one with the space, as used in consensus/valid-after and similar) instead of ISOTime2 for consistency?

nickm: do you have any opinions on this?

Changed 5 months ago by neel

Attachment: b25511-torspec-002.patch added

Torspec patch (Revision 1)

comment:48 Changed 5 months ago by neel

Assuming you want ISOTime2, I have a new patch with the filename b25511-torspec-002.patch.

comment:49 Changed 5 months ago by nickm

I think I'd prefer that new things be ISOTime2 (the one that is YYYY-MM-DDTHH:MM:SS) -- I consider the older format (YYYY-MM-DD HH:MM:SS) to be legacy. The rationale for the newer format is that, when possible, it's often nice to have no spaces inside data items.

comment:50 Changed 5 months ago by catalyst

Status: needs_revisionneeds_review

comment:51 Changed 5 months ago by mikeperry

Status: needs_reviewmerge_ready

Spec change looks good.

comment:52 Changed 5 months ago by dgoulet

Spec patches need the tor version when it was added. This is for 034 so "tor-0.3.4.1-alpha" will be the first release with this.

comment:53 in reply to:  52 Changed 5 months ago by catalyst

Status: merge_readyneeds_review

Replying to dgoulet:

Spec patches need the tor version when it was added. This is for 034 so "tor-0.3.4.1-alpha" will be the first release with this.

Sorry about that. Fix in https://github.com/torproject/torspec/pull/5

comment:54 Changed 5 months ago by dgoulet

Status: needs_reviewmerge_ready

comment:55 Changed 5 months ago by nickm

Resolution: implemented
Status: merge_readyclosed

Merged the main implementation too!

Note: See TracTickets for help on using tickets.