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.