Opened 4 years ago

Last modified 22 months ago

#16608 new defect

"time published in the consensus network status" seems to be wrong

Reported by: toralf Owned by:
Priority: Medium Milestone: Tor: unspecified
Component: Core Tor/Tor Version: Tor: 0.2.6.10
Severity: Normal Keywords: unsolved needs-diagnosis tor-relay time
Cc: Actual Points:
Parent ID: Points: 3
Reviewer: Sponsor:

Description

I setup a watch dog script which informs me immediately about such log messages.
I checked immediately the time. The time at my server was the same at my desktop and both seems to be accurate (set by ntpd).

That's why I do assume that this log

Jul 17 10:58:58.000 [warn] Our clock is 1 minutes, 2 seconds behind the time published in the consensus network status document (2015-07-17 09:00:00 UTC).  Tor needs an accurate clock to work correctly. Please check your time and date settings!

points to an issue which has nothing to do with a wrong local clock of my server (F1BE15429B3CE696D6807F4D4A58B1BFEC45C822)

Child Tickets

Change History (18)

comment:1 Changed 3 years ago by toralf

Severity: Normal

occurred today in 0.2.8.2-alpha-dev again - same picture

comment:2 Changed 3 years ago by teor

Keywords: easy log added

Please check your time, and the time on your NTP server.

Given that 9 authorities must agree on the time before they can sign a consensus, is unlikely that a relay can receive a signed consensus signed by 9 authorities who think the time is 16:00:00 (or later), when global time is 15:58:58.

It is far more likely that your relay's clock has drifted, or your NTP server's clock has drifted.

comment:3 Changed 3 years ago by teor

Keywords: easy log removed

comment:4 Changed 3 years ago by teor

(Oops, the time on your relay was 10:58:58, not 15:58:58.)

comment:5 in reply to:  2 Changed 3 years ago by toralf

Replying to teor:

It is far more likely that your relay's clock has drifted, or your NTP server's clock has drifted.

Yes.

OTOH I checked the time yesterday immediately after that occurred:

May 12 20:58:43.000 [warn] Our clock is 1 minutes, 17 seconds behind the time published in the consensus network status document (2016-05-12 19:00:00 UTC).  Tor needs an accurate clock to work correctly. Please check your time and date settings!
May 12 20:58:43.000 [notice] This version of Tor (0.2.8.2-alpha-dev) is newer than any recommended version, according to the directory authorities. Recommended versions are: 0.2.4.23,0.2.4.24,0.2.4.25,0.2.4.26,0.2.4.27,0.2.5.8-rc,0.2.5.9-rc,0.2.5.10,0.2.5.11,0.2.5.12,0.2.6.5-rc,0.2.6.6,0.2.6.7,0.2.6.8,0.2.6.9,0.2.6.10,0.2.7.1-alpha,0.2.7.2-alpha,0.2.7.3-rc,0.2.7.4-rc,0.2.7.5,0.2.7.6,0.2.8.1-alpha,0.2.8.2-alpha

with my desktop - and that with the TV - all the same.

And b/c the times at the authorities are correct too I do wonder about it.

FWIW here's the header of the monitoring email :

Return-path: <root@your-server.de>
Envelope-to: tor-relay@zwiebeltoralf.de
Delivery-date: Thu, 12 May 2016 20:58:56 +0200
Received: from tor-relay.zwiebeltoralf.de ([5.9.158.75] helo=www325.your-server.de)
	by www325.your-server.de with smtps (TLSv1.2:DHE-RSA-AES256-GCM-SHA384:256)
	(Exim 4.85_2)
	(envelope-from <root@your-server.de>)
	id 1b0voy-0006Mf-DX
	for tor-relay@zwiebeltoralf.de; Thu, 12 May 2016 20:58:56 +0200
Received: by www325.your-server.de (sSMTP sendmail emulation); Thu, 12 May 2016 20:58:44 +0200
From: "root" <root@your-server.de>
Date: Thu, 12 May 2016 20:58:44 +0200
To: tor-relay@zwiebeltoralf.de
Subject: /tmp/notice.log : May 12 20:58:43.000 [warn] Our clock is 1 minutes, 17 seconds behind the time published in the consensus network status document (2016-05-12 19:00:00 UTC).  Tor needs an accurate clock to work correctly. Please check your time and date settings!
X-Virus-Scanned: Clear (ClamAV 0.99/21533/Thu May 12 18:56:20 2016)
X-Spam-Score: 3.8 (+++)
Delivered-To: zwiebes-tor-relay@zwiebeltoralf.de

comment:6 Changed 3 years ago by cypherpunks

What was your git head at the time of the warning?

comment:7 Changed 3 years ago by toralf

I do usually do

git diff tor-0.2.8.2-alpha..origin/release-0.2.8 -- . ':!doc/contrib' ':!changes' ':!scripts' > /tmp/tor.patch

once a week or so, when I do update the linux kernel too.

comment:8 Changed 3 years ago by toralf

My home-brewed-email solution gave me today:

dry-run of ntpdate :
20 May 19:58:46 ntpdate[11383]: ntpdate 4.2.8p7@1.3265-o Fri Apr 29 17:56:26 UTC 2016 (1)
server 5.9.39.18, stratum 2, offset 0.000009, delay 0.02588
server 5.45.97.127, stratum 3, offset -0.002183, delay 0.02856
server 212.18.3.18, stratum 2, offset -0.000373, delay 0.03755
server 192.162.168.12, stratum 3, offset 0.002159, delay 0.02852
20 May 19:58:53 ntpdate[11383]: adjust time server 5.9.39.18 offset 0.000009 sec
...
May 20 19:58:46.000 [warn] Our clock is 1 minutes, 14 seconds behind the time published in the consensus network status document (2016-05-20 18:00:00 UTC).  Tor needs an accurate clock to work correctly. Please check your time and date settings!

What that means (I got a similar thing few minutes ago), is that the servers's clock is right (or ntp is lying). So the received consensus document are not from the tor servers, or ?

Last edited 3 years ago by toralf (previous) (diff)

comment:9 Changed 3 years ago by toralf

Today I'm sitting at my desktop when I realized this message at the server:

Jun 10 11:58:29 ms-magpie Tor[1909]: Our clock is 1 minutes, 31 seconds behind the time published in the consensus network status document (2016-06-10 10:00:00 UTC).  Tor needs an accurate clock to work correctly. Please check your time and date settings! (nowdelta = 0 seconds)

I immediately compared the clock of the server with my desktop clock and a radio controlled clock here at home - it was definitely before 11:59 am - and it was exactly the same difference than the last time(s) before :91 sec.
The log message above it is the result of a slightly patched 0.2.8.3-alpha :

# cat /etc/portage/patches/net-misc/tor-0.2.8.3_alpha/nownow.patch 
diff --git a/src/or/networkstatus.c b/src/or/networkstatus.c
index 5a91dda..a360e12 100644
--- a/src/or/networkstatus.c
+++ b/src/or/networkstatus.c
@@ -1480,6 +1480,7 @@ networkstatus_set_current_consensus(const char *consensus,
   networkstatus_t *c=NULL;
   int r, result = -1;
   time_t now = time(NULL);
+  time_t nownow = -1;
   const or_options_t *options = get_options();
   char *unverified_fname = NULL, *consensus_fname = NULL;
   int flav = networkstatus_parse_flavor_name(flavor);
@@ -1732,16 +1733,20 @@ networkstatus_set_current_consensus(const char *consensus,
  * valid-after time, declare that our clock is skewed. */
 #define EARLY_CONSENSUS_NOTICE_SKEW 60

+       nownow = time(NULL);
   if (now < c->valid_after - EARLY_CONSENSUS_NOTICE_SKEW) {
     char tbuf[ISO_TIME_LEN+1];
     char dbuf[64];
+    char nowdbuf[64];
     long delta = now - c->valid_after;
+               long nowdelta = nownow - now;
     format_iso_time(tbuf, c->valid_after);
     format_time_interval(dbuf, sizeof(dbuf), delta);
+    format_time_interval(nowdbuf, sizeof(nowdbuf), nowdelta);
     log_warn(LD_GENERAL, "Our clock is %s behind the time published in the "
              "consensus network status document (%s UTC).  Tor needs an "
              "accurate clock to work correctly. Please check your time and "
-             "date settings!", dbuf, tbuf);
+             "date settings! (nowdelta = %s)", dbuf, tbuf, nowdbuf);
     control_event_general_status(LOG_WARN,
                     "CLOCK_SKEW MIN_SKEW=%ld SOURCE=CONSENSUS", delta);
   }

which was made in the hope to catch an extraterrestrial root cause.

So again, what is a good explanation for those log messages ?

For completeness, the additional audit mail from my home brewed solution told me, that ntp is fine :

dry-run of ntpdate :
10 Jun 11:58:29 ntpdate[2691]: ntpdate 4.2.8p8@1.3265-o Sat Jun  4 16:59:14 UTC 2016 (1)
server 38.229.71.1, stratum 2, offset 0.002621, delay 0.13054
server 80.82.244.120, stratum 2, offset 0.000593, delay 0.04356
server 87.233.197.123, stratum 3, offset -0.000858, delay 0.03699
server 139.162.23.6, stratum 2, offset 0.036595, delay 0.29028
10 Jun 11:58:37 ntpdate[2691]: adjust time server 80.82.244.120 offset 0.000593 sec
Last edited 3 years ago by toralf (previous) (diff)

comment:10 Changed 3 years ago by toralf

There's a detail which is worth to be reported - the logged time gap is mostly 1:01 min or 1:31 min

comment:11 Changed 3 years ago by nickm

Milestone: Tor: 0.2.???Tor: 0.2.9.x-final

Interesting. I think we should look at this as a bug in 0.2.9, to see if we can figure anything out. Right now I'm confused.

comment:12 Changed 3 years ago by nickm

Keywords: unsolved added
Points: 3

comment:13 Changed 3 years ago by isabela

Keywords: isaremoved added
Milestone: Tor: 0.2.9.x-finalTor: 0.2.???

comment:14 Changed 2 years ago by teor

Milestone: Tor: 0.2.???Tor: 0.3.???

Milestone renamed

comment:15 Changed 2 years ago by nickm

Keywords: tor-03-unspecified-201612 added
Milestone: Tor: 0.3.???Tor: unspecified

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

comment:16 Changed 2 years ago by nickm

Keywords: tor-03-unspecified-201612 removed

Remove an old triaging keyword.

comment:17 Changed 2 years ago by nickm

Keywords: isaremoved removed

comment:18 Changed 22 months ago by nickm

Keywords: needs-diagnosis tor-relay time added

Could it be that we're launching requests for a consensus before it's actually live?

Here's my theory: If we happen to start a directory cache after a new consensus is made and signed, but before it is live, the authorities give it to us anyway, and we get nervous because it's published in the future.

Note: See TracTickets for help on using tickets.