Opened 14 months ago

Last modified 13 months ago

#25511 closed enhancement

Expose TZ info on control port for better debugging of time errors — at Version 36

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.

Child Tickets

Change History (39)

comment:1 Changed 14 months ago by nickm

Keywords: 034-roadmap-master added

comment:2 Changed 14 months ago by nickm

Keywords: 034-triage-20180328 added

comment:3 Changed 14 months ago by nickm

Keywords: 034-included-20180328 added

comment:4 Changed 14 months ago by neel

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

comment:5 Changed 14 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 14 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 14 months ago by mcs

Cc: mcs brade added

comment:8 Changed 14 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 14 months ago by catalyst

Keywords: s8-errors added
Sponsor: Sponsor8

comment:10 in reply to:  6 Changed 14 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 14 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 14 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 14 months ago by neel

Attachment: b25511-001.patch added

Patch (Revision 1)

comment:13 Changed 14 months ago by neel

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

comment:14 Changed 14 months ago by teor

Status: assignedneeds_review

comment:15 in reply to:  13 Changed 14 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 14 months ago by asn

Reviewer: catalyst

comment:17 Changed 14 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 14 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 14 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 14 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 14 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 14 months ago by neel

Attachment: b25511-002.patch added

Patch (Revision 2)

comment:22 Changed 14 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 14 months ago by catalyst

Status: needs_reviewmerge_ready

Looks good to me! Thanks!

comment:24 Changed 14 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 14 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 14 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 14 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 14 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 14 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 14 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 14 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 14 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 14 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 14 months ago by neel

Attachment: b25511-003.patch added

Patch (Revision 3)

comment:34 Changed 14 months ago by neel

New patch: b25511-003.patch.

I also mocked tor_gettimeofday() here.

comment:35 Changed 14 months ago by nickm

Status: needs_revisionneeds_review

comment:36 Changed 14 months ago by catalyst

Description: modified (diff)
Note: See TracTickets for help on using tickets.