What could cause a huge clock skew (9 days) across Tor restarts - anyone else experienced something like this?
Hello,
I'd like to hear if anyone else experienced this and has an idea of what the cause might be.
I did not oped a ticket about this yet because I am not sure there is a problem in Tor, and it eventually healed by itself.
The relay was running just fine. Server had an accurate time before upgrade and time service ntp was running. I only did an upgrade to Tor from the latest nightly build and of course it does a service stop -> upgrade -> service start.
After Debian finished installing the new Tor, I did as usual: check the log file to see that all is OK and circuits were built and descriptors published, etc. I saw this:
The log before restart was reporting:
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.
[skipped boring part intentionally]
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 ?)
and then
Sep 06 21:04:50.000 [notice] Starting with guard context "default" ...proceed to normal start and everything as usual from now...
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.
Thanks!
Hi,
On 7 Sep 2019, at 20:25, s7r s7r@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? What time did your OS show when this issue happened?
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?
T
teor wrote:
Hi,
On 7 Sep 2019, at 20:25, s7r s7r@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.
On Sep 7, 2019, at 04:13, s7r s7r@sky-ip.org wrote:
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
It seems likely that your machine's hardware clock is off. During a reboot, the system will come up using the hardware clock, then (if configured to do so) eventually correct the time using NTP.
You can check the hardware clock by running 'hwclock' as root. If it's off, you can set it to your (presumed accurate) system time by executing 'hwclock --systohc'.
--Ron
s7r wrote:
teor wrote:
Hi,
[SNIP]
I have received the email below from Ron off-list, and it was very useful. Posting it here.
Ron, I have tried to email back but apparently your mail server treats me as spam and I get bounce back with permanent failure - hopefully you are still getting fro lists.torproject.org and you can read this:
ronqtorrelays@risley.net wrote:
Hi!
The torproject mailman server appears to have fallen over. Here's what
I've been trying to send to the list. Hope it helps.
-*"*-.,,.-*"*-.,,.-*"*-.,,.-*"*-.,,.-*"*-.,,.-*"*-.,,.-*"*-
On Sep 7, 2019, at 04:13, s7r s7r@sky-ip.org wrote:
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
It seems likely that your machine's hardware clock is off. During a
reboot, the system will come up using the hardware clock, then (if configured to do so) eventually correct the time using NTP.
You can check the hardware clock by running 'hwclock' as root. If it's
off, you can set it to your (presumed accurate) system time by executing 'hwclock --systohc'.
--Ron
Hey Ron,
Wow! Nice catch. You are right.
Here is what the OS where Tor is running is showing:
$ sudo hwclock 2019-08-28 22:42:11.880025-0400
$ date --utc Sat Sep 7 23:35:43 UTC 2019
So `date` is accurate while `hwclock` is obviously not.
The problem is I really don't know why. The server above (which reports skewed clock on hwclock) is a virtual machine.
The host (on which this virtual machine is running) also uses NTP and reports accurate clock on both `date` and `hwclock`. There is no skew at all anywhere on the host. So I am wondering where is it getting the inaccurate hwclock from. Most probably a bug in the virtualization software used I guess.
All other virtual machines (guests) on the same host report accurate time on both `hwclock` and `date`. Anyway, certainly the bug is not related to Tor.
Thanks for this.
tor-relays@lists.torproject.org
-
ronqtorrelays＠risley.net -
s7r -
teor