Tor log dates imprecise

Hi Nick. Tor's log file uses the local timezone and lacks the year in its log file entries...

Apr 06 11:03:39.000 [notice] Tor 0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) opening new log file.
Apr 06 11:03:39.832 [notice] Tor v0.2.7.0-alpha-dev (git-4247ce99e5d9b7b2) running on Linux with Libevent 2.0.16-stable, OpenSSL 1.0.1 and Zlib 1.2.3.4.
Apr 06 11:03:39.832 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning

This is fine, but has meant some hacks for arm which reads the log file to prepopulate that information. For instance, arm pretends the year is always 2012 to ensure log files made on leap years are readable (otherwise February 29th isn't a thing, see legacy/trac#5265 (closed)).

Feel free to close this as 'no plan to fix' if you'd like. Just thought I'd run this by you to see if iso8601 timestamps or something more complete would be preferable.

changed milestone to %Tor: unspecified in legacy/trac

added component::core tor/tor in Legacy / Trac log in Legacy / Trac milestone::Tor: unspecified in Legacy / Trac needs-design in Legacy / Trac priority::medium in Legacy / Trac severity::normal in Legacy / Trac status::needs-revision in Legacy / Trac tor-client in Legacy / Trac tor-relay in Legacy / Trac type::defect in Legacy / Trac usability in Legacy / Trac labels

Trac:
Summary: Tor log dates inprecise to Tor log dates imprecise

Trac:
Milestone: N/A to Tor: 0.2.???

I did some preliminary work to teach Tor to use RFC 3339 timestamps for logging. See the following branch:

• https://github.com/rl1987/tor/compare/bug15607_rfc3339

Now there are design decisions to be made!

1. Currently, my patch prints correct timezone offset only on systems that support gettimeofday(2). On other systems (e.g. Windows) getting timezone offset requires using platform-specific approach. If we fail to, what do we do? Is it okay, as a fallback, to print the local time with zero offset from UTC?
2. Users may not want to have their timezone information in the logs. Knowing timezone reduces uncertainty about geographic location, which might be dangerous for sensitive use cases. My proposition is to add ForceUTCTimestamps torrc option and to have it be enabled by default. The downside is that it might be confusing to users. Sounds valid?

Trac:
Status: new to needs_information

Thanks rl1987! Nick, what are your thoughts on this?

This seems like a breaking change for anything that expected the old format and knew how to parse it.

Also, do we really expect the timezone to chance so often that we need to reformat it every time that we log a message?

I thought about possible timezone issues and decided not to print it in every entry, even though we lose RFC3339 conformance.

• !https://github.com/rl1987/tor/compare/bug15607_no_tz

Trac:
Status: needs_information to needs_review

For nyx at least timezones aren't a concern (since I'm running locally, and can figure out what it is). Missing the year is the main trouble.

Thanks for digging into this!

[ asked on irc... ] 11:18 < rl1987> I guess we're not merging/doing anything about legacy/trac#15607 (moved), since we don't want existing nyx to break?

For my part I'm fine with merging. This isn't the first change to break a part of Nyx, it's in need of a rewrite (... and getting one). Nyx was built to be pretty tolerant of things like this so feel free to move forward.

18:39 < rl1987> oh, and there was #15607
18:40 < rl1987> maybe we should reach a decision on that?
18:40 -!- cicada [~cicada_33@80.82.64.92] has joined #tor-dev
18:41 < armadev> putting a year in every log line seems like crazy talk
18:41 < armadev> i was always confused about why nyx tried to parse the log 
                 files anyway
18:42 < armadev> i could be convinced about a config option, "make logs 
                 readable by nyx", off by default, and then nyx turns it on
18:42 < armadev> but if nyx is going to do that, maybe it should just listen 
                 for log controller events and be done with it
18:42 -!- cicada [~cicada_33@0001fdfc.user.oftc.net] has quit []
18:42 < armadev> i guess the use case is to present your logs from disk to you, 
                 even before nyx started
18:44 < rl1987> then, wontfix?
18:45 < armadev> rl1987: i haven't read the bug
18:48 < atagar> armadev: 'i was always confused about why nyx tried to parse 
                the log files anyway' => Nyx emits its own log messages, and I 
                read the date because I order the overall log by the 
                timestamps. That, and nyx groups messages by date with a 
                border. Tor lacking the year isn't an overly big whoop, but 
                it's something I need to hack around and introduces errors with 
                edge cases like leap years.
18:49 < armadev> i wonder if tor should put a year at the top of its log when 
                 it opens it?
18:49 < armadev> (is this related?)
18:49 < atagar> Sure, for my purposes think that would do the trick.
18:49 < armadev> i am not against admitting the year
18:49 < armadev> i just don't want it in every line
18:51 < atagar> Understandable. It's very strange that tor omits it (first 
                application logs I've seen that does that), but it makes sense 
                for cutting down on noise if you don't care about long term 
                logging.
18:51 < atagar> Personally I'd opt for emitting the year on stdout but 
                including it in the log file, but just my two cents.
18:52 < atagar> oops, s/emitting/omitting
18:55 < rl1987> atagar, armadev: so, we need to log a full timestamp every time 
                we start a new log file, but log timestamps without year for 
                every regular log entry?
18:57 < rl1987> can we agree on this?
19:02 < armadev> rl1987: works for me. it doesn't even need to be every time we 
                 open a new log file. it could be whatever log line tor puts 
                 into the log file first. i hope there is something like that 
                 already, for existing log files, where tor writes its version 
                 and stuff first.

Personally I don't think it's a great solution (it's quite a hack), but if this is what Nick and Roger prefer for tor then that's fine.

As mentioned at the end personally I think we should include full timestamps in the log, and omit the year for stdout. This reduces clutter where complete dates are irrelevant, and only includes complete dates where they're potentially useful.

Replying to rl1987:

2. Users may not want to have their timezone information in the logs. Knowing timezone reduces uncertainty about geographic location, which might be dangerous for sensitive use cases. My proposition is to add ForceUTCTimestamps torrc option and to have it be enabled by default. The downside is that it might be confusing to users. Sounds valid?

I opened ticket legacy/trac#18112 (moved) regarding this.

Trac:
Severity: N/A to Normal
Sponsor: N/A to N/A

Trac:
Cc: N/A to mcs

Trac:
Status: needs_review to needs_revision

Milestone renamed

Trac:
Milestone: Tor: 0.2.??? to Tor: 0.3.???

Finally admitting that 0.3.??? was a euphemism for Tor: unspecified all along.

Trac:
Milestone: Tor: 0.3.??? to Tor: unspecified
Keywords: N/A deleted, tor-03-unspecified-201612 added

Remove an old triaging keyword.

Trac:
Keywords: tor-03-unspecified-201612 deleted, N/A added

Trac:
Reviewer: N/A to N/A
Keywords: N/A deleted, tor-client tor-relay log usability needs-design added

mentioned in issue legacy/trac#18112 (moved)

moved from legacy/trac#15607 (moved)

added Bug label and removed 1 deleted label

added Client Relay Research + 1 deleted label and removed 1 deleted label

added First Contribution label

removed milestone

closed

added Deferred label

added BugSmashFund label