-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Could you show the log? Can you rebuild you kernel with debug option and check what kernel events have the same timestamps On 18.02.2014 23:39, Zenaan Harkness wrote:

On 2/18/14, Alexander Makarov <ice.turbulent@gmail.com> wrote:

...

On 18.02.2014 22:02, Zenaan Harkness wrote:

...

My tor logs (running on Debian) are showing this warning: [WARN] Your system clock just jumped 100 seconds forward; assuming established circuits no longer work.

I tried running openntpd as well as ntp packages (debian), and both display the same problem - once or twice a day I get this jump in time of in the order of a couple of minutes.

Any idea why?

...

Maybe problem with hardware clocks?

OK, I just checked that the time is very close to correct local time (within a couple seconds as best I can tell), and ran hwclock --systohc

But, surely the log warning would only happen once? - that's the whole point of running ntp I thought...

See how my node goes over the next day or two, Thanks Zenaan _______________________________________________ tor-relays mailing list tor-relays@lists.torproject.org https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-relays

- -- Best regards, Alexander Makarov -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.22 (GNU/Linux) Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/ iQIcBAEBAgAGBQJTA1nlAAoJEBuTDJZeb03VbSkQALF56FA/x/PjHFdsqeHMismS OwaQXDEp9LwnMhTwy+sl67FTZqGegKy/eY/elfTV35Tz2J2zEraj05CoiJMIIN1z Sw9/PH2OexWsGPO6ZrfnhwcO1e+lgso2ayQNYeAkV2o2xy+87hJmlKUq5Zf+3SBJ xGziNJ8WKq9ttArMwkXy26SsuG6hWGPRSU/CE//CDdanqiufp5t1qEiv5OnkmcdN ji0MqwVjwJz7ccJnyAS/6KgoCeROkntxuu8PrSmpFhlkcGr+lugtOK2ccBALeomX EjMVMg3qbC9ZeCVm6LCKSL43LNjjptkXQPumS8w/hLD6LwNZO3pmPIAB2wMqIs7w TALp2psg1cJnl6wiYqt9b/x3gQc3iTcFq0ME0C41wohoRL8fFyVCOZ3Shcyi27Vp zJzfkKJAzAoLPiZa3R0t1/v9z/vp0kYQSUlIaVlNgBF4w+BlS2S1WypVrc0G+rsu SATj0C9JXpMe8T3QtZByIOGoLWbuBKsCbeSTvuYLrKRPIgDTk6XOeQefXraYWbtz K+9MjaIRy7nEq4rgOz9MxwyabBegnaBQhk/nAkpVIpQJwhBRcTRMFwtmRz/Fuu/I o2TUFghlfRSD1exWmROUHKm9wTl8Nop6JN0nNuXtybca4Hze4LuG+hwQQ29OUvr5 eJ7QRxdPLJnNWwk0iPR5 =duvg -----END PGP SIGNATURE-----

Iinet are having some sort of problem this morning which was just resolved a short while ago.

On 2/19/14, Zenaan Harkness <zen@freedbms.net> wrote:

On 2/19/14, Alexander Makarov <ice.turbulent@gmail.com> wrote:

...

Could you show the log?

Current and previous tor logs attached. What is also interesting is IP address seems to change rather frequently from the ISP (iiNet in this case - a home ADSL2 connection, but off-net, so it's a resell of Telstra).

Telstra could be running carrier grade NAT or something perhaps? Looks like IP address changes may be coming faster until there's a 99% conversion to IPv6.

I also note an early morning torrc file read (log.1) - there are no changes in the torrc file since the 17th, so except that I run service tor reload, I do not expect tor to re-read the torrc file; is this normal?: Feb 19 07:35:19.000 [notice] Read configuration file "/etc/tor/torrc".

Guess I need to get into coding again - or at least code review... this doesn't make sense to me though - the log message should say a bit more than it does (eg "confirmed no change" or "changes to BLAH and BLAG"... the message as it reads is enigmatic to the point of consternation.

...

Can you rebuild you kernel with debug option and check what kernel events have the same timestamps

I could install a debug kernel - Debian makes them available. How would I "check kernel events" - just check the logs?

Happy to investigate... might need some hand holding on the process.

Installed Debian's ...-dbg kernel package. Apparently it's just symbols - no new kernel. I've asked on debian-user for assistance in the recommendation to check kernel events. Thanks Zenaan

On 2/20/14, grarpamp <grarpamp@gmail.com> wrote:

Since you say it repeats you oppurtunity to check the system clock first: - configure tor to syslog

added

- send an ntpdate -q pool to syslog every 5min, remove when solved.

Do you mean disable ntpd daemon, and run this instead? Sounds easy enough, I imagine: service ntp stop; while true; do ntpd -gqn -l /var/log/syslog; sleep 5m; done service ntp start Something like -L seems to be needed but -L doesn't stop, the following - I don't know what these sorts of lines are (reading docs now, but it might take a while to figure it out) - ie I don't know why ntpd listens on LAN: 20 Feb 18:31:26 ntpd[22655]: Listen normally on 3 eth1 192.168.5.2 UDP 123 BTW, looks like ntpd has the same options as ntpdate, intended for the same functions (at least on Debian, says ntpdate is deprecated). Now, here's the last short while of this ntpd script output: ntpd: time slew -0.015558s ntpd: time slew +0.062676s ntpd: time set +0.191404s ntpd: time set +0.187068s ntpd: time slew -0.029898s ntpd: time slew +0.027801s So it seems that the slew is somehow not being set properly, or rather, now that ntpd is being run every 5 minutes, it gets to add about .2 of a second pretty regularly (I'll continue to watch of course), so something definitely seems amiss. I'm not loading the system default ntpd config file. It looks like time could be running slow and being _not_ updated, except a few times a day, resulting in the 2-3minute jump.

- send *.* to /var/log/all

What's that mean? I need just a little more handholding sorry. Is this intended to be a torrc config? It sounds like a good idea to send everything to one log file for a while, till I debug this. I'll get back to this, but just for the moment, I notice some interesting repeating lines all over daemon.log re ntpd (but not recently): ... daemon.log:Feb 18 03:10:08 lt8 ntpd[2845]: peer 203.24.120.194 now valid daemon.log:Feb 18 03:15:37 lt8 ntpd[2845]: peer 203.59.9.110 now invalid daemon.log:Feb 18 03:28:34 lt8 ntpd[2843]: adjusting clock frequency by 18.354661 to 3.931566ppm daemon.log:Feb 18 04:08:41 lt8 ntpd[2845]: peer 203.59.9.110 now valid daemon.log:Feb 18 04:15:29 lt8 ntpd[2845]: peer 118.88.20.194 now invalid daemon.log:Feb 18 04:15:34 lt8 ntpd[2845]: peer 130.102.2.123 now invalid daemon.log:Feb 18 04:15:47 lt8 ntpd[2845]: peer 203.171.85.237 now invalid daemon.log:Feb 18 04:15:52 lt8 ntpd[2845]: peer 202.127.210.37 now invalid daemon.log:Feb 18 04:16:01 lt8 ntpd[2845]: peer 202.147.104.52 now invalid daemon.log:Feb 18 04:30:05 lt8 ntpd[2845]: peer 203.59.9.110 now invalid daemon.log:Feb 18 04:59:11 lt8 ntpd[2845]: 10 out of 20 peers valid daemon.log:Feb 18 04:59:11 lt8 ntpd[2845]: bad peer from pool 0.debian.pool.ntp.org (130.102.2.123) daemon.log:Feb 18 04:59:11 lt8 ntpd[2845]: bad peer from pool 0.debian.pool.ntp.org (202.127.210.37) daemon.log:Feb 18 04:59:11 lt8 ntpd[2845]: bad peer from pool 1.debian.pool.ntp.org (203.59.9.110) ... nothing similar in today's daemon.log though.

and see what you find around where the date lines start to slide or jump past each other. Graph it with rrd/gnuplot if you want. epoch format helps there. Your timekeeping is probably just broke somewhere,

sounds like it.

ie: your system has bad clock drift and also can't sync because there's a firewall blocking ntp, so off goes your time. Check that first.

Here's what I'm getting every 5 minutes: Feb 20 18:46:59 lt8 ntpd[22662]: ntpd 4.2.6p5@1.2349-o Sat May 12 09:07:18 UTC 2012 (1) 20 Feb 18:46:59 ntpd[22662]: proto: precision = 2.514 usec 20 Feb 18:46:59 ntpd[22662]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123 Feb 20 18:46:59 lt8 ntpd[22662]: logging to file /var/log/syslog 20 Feb 18:46:59 ntpd[22662]: Listen and drop on 1 v6wildcard :: UDP 123 20 Feb 18:46:59 ntpd[22662]: Listen normally on 2 lo 127.0.0.1 UDP 123 20 Feb 18:46:59 ntpd[22662]: Listen normally on 3 eth0 192.168.5.2 UDP 123 20 Feb 18:46:59 ntpd[22662]: Listen normally on 4 eth0 fe80::202:8aff:fe21:77f1 UDP 123 20 Feb 18:46:59 ntpd[22662]: Listen normally on 5 lo ::1 UDP 123 20 Feb 18:46:59 ntpd[22662]: peers refreshed 20 Feb 18:46:59 ntpd[22662]: Listening on routing socket on fd #22 for interface updates 20 Feb 18:47:12 ntpd[22662]: ntpd: time slew +0.027801 s again, I don't (yet) understand why ntpd is Listening as seen above. there appears to be no problems with firewall, that I can tell yet anyway (also eg the logs above - I've done some grepping etc over the last few days of logs and everything outgoing appears to work, and incoming ORPort DIRPort are successfully forwarded and the relay is chugging away nicely within its limits. Also Internet generally works (downloading debian boot cd for example) - and no ntp server connection failures I could spot in the logs just before.

It's not your isp since you say you're using ntpd against external debian pool and odds are not someone stuffing you bogus timedata. Though your ntp cli query may not be the same as the ntp daemon query re: udp/tcp port they use, stateful firewall timeout, etc... ie: somehow ntp blocked. Or stale/unwriteable startup drift files on disk. If ntpdate is set, then under ntpd running for 15min+, if ntpq -np does not show one asterisk(*) in front

I am running the 5-minutely script at the moment. But perhaps I should keep running the system ntpd at the same time, so I can do this suggested test?

of one of the nonlocal peers, you're not synced. And you'll be no luck until you are, fix that first.

Thank you so much for the pointers - I've a bit of monitoring and testing and reading to do it seems.

Not likely to be Tor or kernel, but you can then next - move the drive to another known good mobo/cpu box. - do the kernel event logging thing - bump tor's loglevel

Thanks again, Zenaan

On 2/20/14, grarpamp <grarpamp@gmail.com> wrote:

...

...

- configure tor to syslog

added

'Log syslog'

The example in etc/torrc is 'Log notice syslog' which I uncommented.

...

...

- send an ntpdate -q pool to syslog every 5min, remove when solved.

Do you mean disable ntpd daemon, and run this instead? Sounds easy enough, I imagine: service ntp stop; while true; do ntpd -gqn -l /var/log/syslog; sleep 5m; done service ntp start

I meant remove it when solved so you don't forget and you're banging on the pool every 5 for eternity.

-l /var/log/syslog - this is potentially overwriting or blocking this file which is managed by syslogd in syslog.conf, pick another new file, or just better to use ntp.conf logconfig option.

if you were running ntpd during problems, and ntpd was not working right, then ntpdate would be just a tool to separately query and print external pool time without impact to running system, for comparing with system time.

Thank you. Restarted ntpd, installed ntpdate, running this script: while true; do sleep 5m; ntpdate -qsv 3.debian.pool.ntp.org; echo "---"; done ...

ntpd disciplines kernel clock by calculating drift from the net and feeds back small rate deltas to kernel. no ntpd -> no discipline -> lots of drift... then these manual slews and jumpsets happen for people setting time manually, which is non ideal, get the daemon running right on its own. Tor said 100sec forward, so it maybe sees what look like the forward jumps above as accumulated. ntpd would not do that if running right, so check for some ntp thing in crontab maybe making your jump.

# cd etc; # grep -in ntp cron*/* cron.daily/ntp:3:# The default Debian ntp.conf enables logging of various statistics to cron.daily/ntp:4:# the /var/log/ntpstats directory. The daemon automatically changes cron.daily/ntp:9:statsdir=$(cat /etc/ntp.conf | grep -v '^#' | sed -n 's/statsdir \([^ ][^ ]*\)/\1/p') Nothing special at all - just standard debian ntp install. I've now gone and added some ntp servers from telstra, iinet and ntp.org.

...

So it seems that the slew is somehow not being set properly, or rather, now that ntpd is being run every 5 minutes, it gets to add about .2 of a second pretty regularly (I'll continue to watch of course), so something definitely seems amiss. I'm not loading the system default ntpd config file.

It looks like time could be running slow and being _not_ updated, except a few times a day, resulting in the 2-3minute jump.

Maybe ntpd is not working/running and cron is maybe doing manual sets.

I've restarted ntpd and running the above script as mentioned. Will post some output soon. # service ntp status NTP server is running.

...

...

- send *.* to /var/log/all

intended to be a torrc config? It sounds like a good idea to send everything to one log file for a while, till I debug this.

man syslog.conf

Thanks. Looks like debian defaults to rsyslog. Anyway, I know what you are referring to now, thanks (I'm a bit green, although have been reported to have at least 1.5 brain cells - though some dispute this as being biased sample).

...

interesting repeating lines all over daemon.log re ntpd (but not nothing similar in today's daemon.log though.

ntp automatically chooses who it thinks is best to listen to among given peers.

Good. Well now I have a number of ntp servers listed, hopefully it shall improve the situation.

...

...

If [system ntp]date is set, then under ntpd running for 15min+, if ntpq -np does not show one asterisk(*) in front

Only one of ntpd or ntpdate should be doing the actual timing. For most people that means 'ntpd -g' starting as daemon at boot, with 'ntpdate -q' and 'ntpq -np' as just cli checks.

Thanks. That's what I'm doing now. TOR relay docs should perhaps include, for debian "add your isp's ntp servers, and possibly a few from ntp.org, to your /etc/ntpd.conf (and check this file is sane)". OK, grepping logs time...: Feb 20 23:51:35 lt8 ntpdate[29233]: adjust time server 130.102.2.123 offset -0.024247 sec Feb 20 23:57:31 lt8 ntpdate[29289]: adjust time server 54.252.129.186 offset 0.018113 sec Feb 21 00:02:38 lt8 ntpdate[29329]: adjust time server 59.167.170.228 offset 0.025050 sec Feb 21 00:07:46 lt8 ntpdate[29377]: adjust time server 121.0.0.41 offset 0.017704 sec Feb 21 00:12:53 lt8 ntpdate[29380]: adjust time server 203.206.205.83 offset 0.004626 sec Feb 21 00:18:00 lt8 ntpdate[29395]: adjust time server 27.116.36.44 offset -0.003997 sec Feb 21 00:23:08 lt8 ntpdate[29411]: adjust time server 118.88.20.194 offset -0.003071 sec Looking very hopeful - convergence of time offset on the way. I guess something I did to ntpd.conf (probably adding servers above the default debian entries which are: server 0.debian.pool.ntp.org iburst server 1.debian.pool.ntp.org iburst server 2.debian.pool.ntp.org iburst server 3.debian.pool.ntp.org iburst I'll check it again in the morning. Next stop, looking into the cgnat issue (occasionally the IP change appears to cause all clients to disconnect, but only sometimes - I'll start another thread if I get back to checking this issue). Thank you so much, hopefully this TOR relay be stable and add to the security of the internet, Zenaan

On 2/21/14, grarpamp <grarpamp@gmail.com> wrote:

...

something I did to ntpd.conf (probably adding servers above the default debian entries which are: server 0.debian.pool.ntp.org iburst

The order doesn't matter. Though if DNS is not up before ntpd on boot, specified poolnames won't resolve and I think it's still a oneshot so only servers listed by ip would be loaded. see ntpq -np while listing a bogus hostname, a poolname, and an ip.

Well I have a couple of IP listings now, and I haven't seen the ~2minute jump since adding them. So things have definitely improved on that front. I still see rather wild deltas (upwards of a second sometime), but at least it doesn't get worse than that: Feb 22 11:26:38 lt8 ntpdate[4832]: step time server 192.189.54.17 offset 0.762756 sec Feb 22 11:31:48 lt8 ntpdate[4836]: adjust time server 203.59.7.248 offset -0.052660 sec Feb 22 11:37:00 lt8 ntpdate[4839]: adjust time server 203.23.237.200 offset 0.283965 sec Feb 22 11:42:11 lt8 ntpdate[4841]: adjust time server 203.23.237.200 offset 0.151871 sec Feb 22 11:47:26 lt8 ntpdate[4843]: adjust time server 150.101.247.149 offset 0.470046 sec Feb 22 11:52:35 lt8 ntpdate[4845]: adjust time server 27.106.200.45 offset 0.063318 sec Feb 22 11:57:46 lt8 ntpdate[4847]: adjust time server 130.102.128.23 offset 0.090110 sec Feb 22 12:03:00 lt8 ntpdate[4851]: step time server 192.189.54.17 offset 0.515640 sec Feb 22 12:08:12 lt8 ntpdate[4853]: adjust time server 192.189.54.17 offset 0.308896 sec Feb 22 12:13:20 lt8 ntpdate[4855]: adjust time server 118.88.20.194 offset -0.162371 sec Feb 22 12:18:33 lt8 ntpdate[4860]: adjust time server 128.184.218.53 offset 0.302422 sec Feb 22 12:23:44 lt8 ntpdate[4915]: adjust time server 203.161.12.165 offset 0.162629 sec Feb 22 12:28:54 lt8 ntpdate[4922]: adjust time server 203.161.12.165 offset 0.035504 sec Your comment above reminds me of something else I saw: log.3.gz:Feb 19 09:55:50.000 [warn] eventdns: All nameservers have failed log.3.gz:Feb 19 09:59:07.000 [warn] Your system clock just jumped 100 seconds forward; This only happened once or twice back then. What this leads me to is a couple of things - have a couple ntp servers listed as ip address in case there is dns problems, but also I think that one thing that may have affected me is I had essentially no throttling/bandwidth shaping on the tor relay - and if the uplink/upload gets satturated, this used to be a problem for bittorrent (still is I think) and probably for tor relay too - if certain outgoing packets don't make it out in a timely manner, then problems happen. So I have set my RelayBandwidthBurst to 90KB (KiB) (and non-burst to 80KB) - it's an ADSL2 connection pretty close to the exchange, so the full 1MiB upload is generally possible, I think. I'll see how I continue to go at 90KB. Thanks all, Zenaan