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

2019-09-07 Thread teor
Hi,

> On 7 Sep 2019, at 20:25, s7r  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
___
tor-relays mailing list
tor-relays@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays


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

2019-09-07 Thread s7r
 teor wrote:
> Hi,
> 
>> On 7 Sep 2019, at 20:25, s7r  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 [noti

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

2019-09-07 Thread s7r
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:

ronqtorrel...@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  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.



signature.asc
Description: OpenPGP digital signature
___
tor-relays mailing list
tor-relays@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays


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

2019-09-08 Thread ronqtorrelays

> On Sep 7, 2019, at 04:13, s7r  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
___
tor-relays mailing list
tor-relays@lists.torproject.org
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays