[tor-relays] What could cause a huge clock skew (9 days) across Tor restarts - anyone else experienced something like this?

s7r s7r at sky-ip.org
Sat Sep 7 11:13:57 UTC 2019


 teor wrote:
> Hi,
> 
>> On 7 Sep 2019, at 20:25, s7r <s7r at sky-ip.org> wrote:
>>
>> So, Tor had the time Sep 06 21:03:46.000 before restart.
>>
>> After restart, it thought it had Aug 28 07:40:07.000 and then Aug 28
>> 07:40:08.000 and then it healed and reported Sep 06 21:04:50.000.
>>
>> This is kind of odd. What could be the reason for this? The server is
>> just a Debian machine that runs Tor and nothing else.
> 
> Sounds like a bug in Tor's wallclock or log modules.
> Or a problem with your OS time APIs.
> 
> What version/commit of Tor were you running before and after the upgrade?

Before upgrade: 0.4.1.2-alpha-dev
Upgraded to: 0.4.2.0-alpha-dev (from deb.tpo -> tor-nightly-master-stretch)

Just to add something I missed in my first email:

-> after upgrading from 0.4.1.2 to 0.4.2.0, I did an entire system
reboot because I also updated some other stuff. So the entire OS
restarted, not just Tor daemon.

> What time did your OS show when this issue happened?

When I checked the log file and saw these anomalies, I immediately
checked the current time/date on my OS and it was accurate. But Tor was
already seeing an accurate time as well according to the logs, and it
was already "healed".

> 
> Can you please post all the logs from Tor's shutdown, startup with the wrong
> time, and correct time, and then a few more entries?
> 

Yes, sure.
Before reboot of server:

Sep 06 20:23:34.000 [notice] Bootstrapped 0% (starting): Starting
Sep 06 20:23:36.000 [notice] This version of Tor (0.4.2.0-alpha-dev) is
newer than any recommended version, according to the directory
authorities. Recommended versions are:
0.2.9.15,0.2.9.16,0.2.9.17,0.3.5.8,0.4.0.5,0.4.0.6,0.4.1.2-alpha,0.4.1.3-alpha,0.4.1.4-rc,0.4.1.5
Sep 06 20:23:59.000 [notice] Starting with guard context "default"
Sep 06 20:23:59.000 [notice] Signaled readiness to systemd
Sep 06 20:24:00.000 [notice] Bootstrapped 5% (conn): Connecting to a relay
Sep 06 20:24:00.000 [notice] Bootstrapped 10% (conn_done): Connected to
a relay
Sep 06 20:24:00.000 [notice] Bootstrapped 14% (handshake): Handshaking
with a relay
Sep 06 20:24:01.000 [notice] Bootstrapped 15% (handshake_done):
Handshake with a relay done
Sep 06 20:24:01.000 [notice] Bootstrapped 56% (loading_descriptors):
Loading relay descriptors
Sep 06 20:24:01.000 [notice] Bootstrapped 61% (loading_descriptors):
Loading relay descriptors
Sep 06 20:24:01.000 [notice] Opening Control listener on /run/tor/control
Sep 06 20:24:01.000 [notice] Opened Control listener on /run/tor/control
Sep 06 20:24:02.000 [notice] Self-testing indicates your ORPort is
reachable from the outside. Excellent.
Sep 06 20:24:02.000 [notice] Bootstrapped 66% (loading_descriptors):
Loading relay descriptors
Sep 06 20:24:03.000 [notice] Bootstrapped 71% (loading_descriptors):
Loading relay descriptors
Sep 06 20:24:03.000 [notice] Bootstrapped 75% (enough_dirinfo): Loaded
enough directory info to build circuits
Sep 06 20:24:03.000 [notice] Bootstrapped 80% (ap_conn): Connecting to a
relay to build circuits
Sep 06 20:24:03.000 [notice] Bootstrapped 85% (ap_conn_done): Connected
to a relay to build circuits
Sep 06 20:24:03.000 [notice] Bootstrapped 89% (ap_handshake): Finishing
handshake with a relay to build circuits
Sep 06 20:24:04.000 [notice] Bootstrapped 90% (ap_handshake_done):
Handshake finished with a relay to build circuits
Sep 06 20:24:04.000 [notice] Bootstrapped 95% (circuit_create):
Establishing a Tor circuit
Sep 06 20:24:04.000 [notice] Bootstrapped 100% (done): Done
Sep 06 20:25:01.000 [notice] Self-testing indicates your DirPort is
reachable from the outside. Excellent. Publishing server descriptor.
Sep 06 20:25:03.000 [notice] Performing bandwidth self-test...done.
Sep 06 21:03:16.000 [notice] Interrupt: we have stopped accepting new
connections, and will shut down in 30 seconds. Interrupt again to exit now.
Sep 06 21:03:17.000 [notice] Delaying directory fetches: We are
hibernating or shutting down.
Sep 06 21:03:46.000 [notice] Clean shutdown finished. Exiting.



After reboot (when systemd started Tor automatically):

Sep 06 21:03:46.000 [notice] Clean shutdown finished. Exiting.
Aug 28 07:39:54.000 [notice] Tor 0.4.2.0-alpha-dev opening log file.
Aug 28 07:39:54.198 [notice] We compiled with OpenSSL 101000af: OpenSSL
1.1.0j  20 Nov 2018 and we are running with OpenSSL 101000bf: OpenSSL
1.1.0k  28 May 2019. These two versions should be binary compatible.
Aug 28 07:39:54.223 [notice] Tor 0.4.2.0-alpha-dev running on Linux with
Libevent 2.0.21-stable, OpenSSL 1.1.0k, Zlib 1.2.8, Liblzma 5.2.2, and
Libzstd 1.1.2.
Aug 28 07:39:54.223 [notice] Tor can't help you if you use it wrong!
Learn how to be safe at https://www.torproject.org/download/download#warning
Aug 28 07:39:54.223 [notice] This version is not a stable Tor release.
Expect more bugs than usual.
Aug 28 07:39:54.224 [notice] Read configuration file
"/usr/share/tor/tor-service-defaults-torrc".
Aug 28 07:39:54.224 [notice] Read configuration file "/etc/tor/torrc".
Aug 28 07:39:54.244 [notice] Opening OR listener on xx.xx.xx.xx:xx
Aug 28 07:39:54.244 [notice] Opened OR listener on xx.xx.xx.xx:xx
Aug 28 07:39:54.244 [notice] Opening OR listener on
[xx:xx:xx:xx:xx:xx:xx]:xx
Aug 28 07:39:54.244 [notice] Opened OR listener on [xx:xx:xx:xx:xx:xx:xx]:xx
Aug 28 07:39:54.244 [notice] Opening Directory listener on xx.xx.xx.xx:xx
Aug 28 07:39:54.244 [notice] Opened Directory listener on xx.xx.xx.xx:xx
Aug 28 07:39:54.000 [notice] Bootstrapped 0% (starting): Starting
Aug 28 07:39:54.000 [warn] Received local state file with skewed time
(/var/lib/tor/state): It seems that our clock is behind by 9 days, 13
hours, 23 minutes, or that theirs is ahead. Tor requires an accurate
clock to work: please check your time, timezone, and date settings.
Aug 28 07:39:54.000 [warn] Problem bootstrapping. Stuck at 0%
(starting): Starting. (Clock skew -825832 in local state file from
/var/lib/tor/state; CLOCK_SKEW; count 1; recommendation warn; host ? at ?)
Aug 28 07:40:03.000 [notice] Parsing GEOIP IPv4 file /usr/share/tor/geoip.
Aug 28 07:40:04.000 [notice] Parsing GEOIP IPv6 file /usr/share/tor/geoip6.
Aug 28 07:40:05.000 [notice] Configured to measure statistics. Look for
the *-stats files that will first be written to the data directory in 24
hours from now.
Aug 28 07:40:06.000 [notice] Your Tor server's identity key fingerprint
is 'xxxxx xxxxxxxxxxxxxxxxxxxxxx'
Aug 28 07:40:07.000 [warn] Our clock is 9 days, 11 hours, 20 minutes
behind the time published in the consensus network status document
(2019-09-06 23:00:00 UTC).  Tor needs an accurate clock to work
correctly. Please check your time and date settings!
Aug 28 07:40:07.000 [warn] Received ns flavor consensus with skewed time
(CONSENSUS): It seems that our clock is behind by 9 days, 11 hours, 20
minutes, or that theirs is ahead. Tor requires an accurate clock to
work: please check your time, timezone, and date settings.
Aug 28 07:40:07.000 [warn] Problem bootstrapping. Stuck at 0%
(starting): Starting. (Clock skew -818406 in ns flavor consensus from
CONSENSUS; CLOCK_SKEW; count 2; recommendation warn; host ? at ?)
Aug 28 07:40:08.000 [warn] Our clock is 9 days, 12 hours, 20 minutes
behind the time published in the consensus network status document
(2019-09-07 00:00:00 UTC).  Tor needs an accurate clock to work
correctly. Please check your time and date settings!
Aug 28 07:40:08.000 [warn] Received microdesc flavor consensus with
skewed time (CONSENSUS): It seems that our clock is behind by 9 days, 12
hours, 20 minutes, or that theirs is ahead. Tor requires an accurate
clock to work: please check your time, timezone, and date settings.
Aug 28 07:40:08.000 [warn] Problem bootstrapping. Stuck at 0%
(starting): Starting. (Clock skew -822006 in microdesc flavor consensus
from CONSENSUS; CLOCK_SKEW; count 3; recommendation warn; host ? at ?)
Sep 06 21:04:50.000 [notice] Starting with guard context "default"
Sep 06 21:04:50.000 [notice] Signaled readiness to systemd
Sep 06 21:04:51.000 [notice] Self-testing indicates your ORPort is
reachable from the outside. Excellent.
Sep 06 21:04:51.000 [notice] Bootstrapped 5% (conn): Connecting to a relay
Sep 06 21:04:51.000 [notice] Opening Control listener on /run/tor/control
Sep 06 21:04:51.000 [notice] Opened Control listener on /run/tor/control
Sep 06 21:04:52.000 [notice] Bootstrapped 10% (conn_done): Connected to
a relay
Sep 06 21:04:52.000 [notice] Bootstrapped 14% (handshake): Handshaking
with a relay
Sep 06 21:04:52.000 [notice] Bootstrapped 15% (handshake_done):
Handshake with a relay done
Sep 06 21:04:52.000 [notice] Bootstrapped 75% (enough_dirinfo): Loaded
enough directory info to build circuits
Sep 06 21:04:52.000 [notice] Bootstrapped 90% (ap_handshake_done):
Handshake finished with a relay to build circuits
Sep 06 21:04:52.000 [notice] Bootstrapped 95% (circuit_create):
Establishing a Tor circuit
Sep 06 21:04:52.000 [notice] This version of Tor (0.4.2.0-alpha-dev) is
newer than any recommended version, according to the directory
authorities. Recommended versions are:
0.2.9.15,0.2.9.16,0.2.9.17,0.3.5.8,0.4.0.5,0.4.0.6,0.4.1.2-alpha,0.4.1.3-alpha,0.4.1.4-rc,0.4.1.5
Sep 06 21:04:52.000 [notice] Bootstrapped 100% (done): Done
Sep 06 21:06:00.000 [notice] Self-testing indicates your DirPort is
reachable from the outside. Excellent. Publishing server descriptor.
Sep 06 21:06:01.000 [notice] Performing bandwidth self-test...done.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 488 bytes
Desc: OpenPGP digital signature
URL: <http://lists.torproject.org/pipermail/tor-relays/attachments/20190907/af7a9447/attachment-0001.sig>


More information about the tor-relays mailing list