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

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 (moved) for the Tor Launcher behavior inconsistency.

changed milestone to %Tor: 0.3.4.x-final

added 034-included-20180328 034-roadmap-master 034-triage-20180328 component::core tor/tor controller milestone::Tor: 0.3.4.x-final owner::neel priority::medium resolution::implemented reviewer::catalyst roadmap s8-errors severity::normal sponsor::8 status::closed tor-spec type::enhancement labels

Trac:
Keywords: N/A deleted, 034-roadmap-master added

Trac:
Keywords: N/A deleted, 034-triage-20180328 added

Trac:
Keywords: N/A deleted, 034-included-20180328 added

Trac:
Status: new to assigned
Owner: N/A to neel
Cc: catalyst, mikeperry to catalyst, mikeperry, neel@neelc.org

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?

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.

Trac:
Cc: catalyst, mikeperry, neel@neelc.org to catalyst, mikeperry, neel@neelc.org, mcs, brade

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.

Trac:
Sponsor: N/A to Sponsor8
Keywords: N/A deleted, s8-errors added

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.

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

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

Trac:
b25511-001.patch

Patch (Revision 1)

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

Trac:
Status: assigned to needs_review

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.

Trac:
Reviewer: N/A to catalyst

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

Also, it seems all tests have passed.

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?

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

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

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

Trac:
b25511-002.patch

Patch (Revision 2)

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.

Looks good to me! Thanks!

Trac:
Status: needs_review to merge_ready

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

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

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.

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.

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.

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

I can understand the race condition.

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

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

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.

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.

Trac:
Status: merge_ready to needs_revision

Trac:
b25511-003.patch

Patch (Revision 3)

New patch: b25511-003.patch.

I also mocked tor_gettimeofday() here.

Trac:
Status: needs_revision to needs_review

Trac:
Description: 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.

to

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.

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

Trac:
Description: 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.

to

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 (moved) for the Tor Launcher behavior inconsistency.

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.

Trac:
Status: needs_review to needs_revision

Trac:
b25511-004.patch

Patch (Revision 4)

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

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

Trac:
Status: needs_revision to needs_review