Opened 16 months ago

Last modified 12 months ago

#24455 new defect

messages out of order in the tor log due to stored logs

Reported by: darkk Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version:
Severity: Normal Keywords: security-low, 033-triage-20180320, 033-removed-20180320
Cc: karsten Actual Points:
Parent ID: Points: 0.5
Reviewer: Sponsor:

Description

While checking various data for #23838 I've found some cases of logs with clock ticking backwards a bit.

Oct 12 04:53:01.000 [notice] Tor 0.2.7.6 opening new log file.
Oct 12 04:53:00.963 [warn] OpenSSL version from headers does not match the version we're running with. If you get weird crashes, that might be why. (Compiled with 1000205f: OpenSSL 1.0.2e 3 Dec 2015; running with 1000208f: OpenSSL 1.0.2h  3 May 2016).
Oct 12 04:53:00.995 [notice] Tor v0.2.7.6 running on Darwin with Libevent 2.0.22-stable, OpenSSL 1.0.2h and Zlib 1.2.5.
Oct 12 04:53:00.995 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://www.torproject.org/download/download#warning
Oct 12 04:53:00.995 [notice] Configuration file "/non-existant" not present, using reasonable defaults.
Oct 12 04:53:00.999 [notice] Opening Socks listener on 127.0.0.1:16025
Oct 12 04:53:00.999 [notice] Opening Control listener on 127.0.0.1:4367
Oct 12 04:53:01.000 [notice] Parsing GEOIP IPv4 file /usr/local/Cellar/tor/0.2.7.6/share/tor/geoip.
Oct 12 04:53:01.000 [notice] Parsing GEOIP IPv6 file /usr/local/Cellar/tor/0.2.7.6/share/tor/geoip6.
Oct 12 04:53:02.000 [notice] Bootstrapped 0%: Starting

I looked at tor/src/common/log.c:log_prefix_() and, seems, this is NOT a bug in rounding. But maybe I'm wrong. Karsten, please, tell me if you need more logs like that to understand the issue better. Maybe it's really just OS clocks ticking backwards during the test, so feel free to close if you don't consider alike logs interesting.

Child Tickets

Change History (7)

comment:1 Changed 16 months ago by catalyst

Milestone: Tor: unspecified

I wonder if this is an artifact of the logging subsystem somehow.

comment:2 Changed 16 months ago by teor

Keywords: security-low added
Milestone: Tor: unspecifiedTor: 0.3.3.x-final
Points: 0.5
Summary: clock tick backwards in the tor logmessages out of order in the tor log due to stored logs

I think this is an artifact of our code that stores early logs, then loads the config, then opens a log file, and writes stored logs to this file.

There are two potential bugs here:

  1. Should "Tor 0.2.7.6 opening new log file." come after the stored logs? (Probably not?)
  2. Should the times on the stored logs be rounded to the configured LogTimeGranularity, or should we choose a safer default for LogTimeGranularity?

Let's think about this in 0.3.3, because LogTimeGranularity is meant to protect users, and it clearly isn't protecting the exact time they started Tor.

comment:3 Changed 16 months ago by darkk

Should "Tor 0.2.7.6 opening new log file." come after the stored logs?

IMHO it should. Another option is to have some obvious indication that it was an early log. Time ticking backwards in the log file always looks strange and attracts attention.

comment:4 Changed 12 months ago by nickm

Keywords: 033-triage-20180320 added

Marking all tickets reached by current round of 033 triage.

comment:5 Changed 12 months ago by nickm

Keywords: 033-removed-20180320 added

Mark all not-already-included tickets as pending review for removal from 0.3.3 milestone.

comment:6 Changed 12 months ago by nickm

Milestone: Tor: 0.3.3.x-finalTor: unspecified

These tickets were marked as removed, and nobody has said that they can fix them. Let's remember to look at 033-removed-20180320 as we re-evaluate our triage process, to see whether we're triaging out unnecessarily, and to evaluate whether we're deferring anything unnecessarily. But for now, we can't do these: we need to fix the 033-must stuff now.

comment:7 Changed 12 months ago by arma

I agree with darkk that having log lines with out-of-order times looks weird.

I wonder if we could resolve it by writing another message, something like "Replaying queued log items:" and "Done replaying queued log items"?

That way we can keep on writing our first log line as the 'opening log' one. After all, if we write the queued log items first and then write the 'opening new log file' line after that, somebody else will point out that *that's* a weird order.

All of this said, we're going to have some weird-looking behavior somewhere still. For example, for the controller events, I think we don't write that "opening new log file" event, so for the controller it just looks natural that we start up and output the queued events, and having the controller see stuff about replaying queued log items could confuse somebody too.

Hm!

Note: See TracTickets for help on using tickets.