Vix 5.1.006. Time wrong

[Joe_90]

@birdman - do I need to run update-rc.d at all to get S11-time-setter to run? Everything currently in /etc/rc3.d is a link to scripts in /etc/init.d

 

[birdman]

@birdman - do I need to run update-rc.d at all to get S11-time-setter to run? Everything currently in /etc/rc3.d is a link to scripts in /etc/init.d

No. The scripts have been put in place "by-hand", rather than update-rc.d.
It's in only directly in rc3.d for testing. It should be one higher that the networking script.

 

[Joe_90]

@birdman - I'm getting issues:

timeset.log contains:

ntpdate-sync: called with
ntpdate-sync: ifup call ignored...
ntpdate-sync: called with
ntpdate-sync: ifup call ignored...
time-setter: start called
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
ntpdate-sync: called with
ntpdate-sync: ntpdate exit code 0
ntpdate-sync: calling ntpdate
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: giving up completely

syslog (partial) contains:

Jan 26 17:40:35 mutant51 daemon.warn avahi-daemon[1983]: WARNING: Failed to contact D-Bus daemon.
Jan 26 17:40:35 mutant51 daemon.info avahi-daemon[1983]: avahi-daemon 0.6.32 exiting.
Jan 26 17:40:35 mutant51 daemon.err ntpdate[2023]: no servers can be used, exiting
Jan 26 17:40:37 mutant51 daemon.err ntpdate[2036]: no servers can be used, exiting
Jan 26 17:40:39 mutant51 daemon.err ntpdate[2047]: no servers can be used, exiting
Jan 26 17:40:42 mutant51 daemon.crit automount[1951]: key "logs" not found in map source(s).
Jan 26 17:40:47 mutant51 daemon.err ntpdate[2075]: no servers can be used, exiting
Jan 26 17:41:06 mutant51 daemon.err ntpdate[2101]: no server suitable for synchronization found
Jan 26 17:41:24 mutant51 daemon.err ntpdate[2117]: no server suitable for synchronization found
Jan 26 17:41:42 mutant51 daemon.err ntpdate[2132]: no server suitable for synchronization found

This seems to indicate that my local server is not being found. It is up and active and being used as the primary timesource for my ubuntu system.
/etc/default/ntpdate contains "192.168.0.190" which is the IP address I always use.

 

[birdman]

@birdman - I'm getting issues:

Indeed - but it's odd...

Your syslog shows 7 failed attempts (although "no servers can be used" changes to "no server suitable for synchronization found".

But timeset.log shows 8 calls - one of them with no parameters, and that one succeeded (which will have been logged in the enigma2 debug log - vide infra).

So it looks as though the boot-time time-setter script was retrying in the background but something else fired off a ntpdate-sync. Now enigma2 can do this, but it's not supposed to fire one up until after [FONT=courier\ new]/tmp/ntp_time_set[/FONT] has been created. And that's my fault - a bug in where I placed the files. The [FONT=courier\ new]NetworkTime.py[/FONT] file is supposed to be one level lower (in Components). (I've corrected the posting and the attachment ther - just in case...).

However, this has (inadvertently) shown that there is a problem running "ntpdate-sync -fg -q -abs" on your system as compared to just "ntpdate-sync" - the former failing while the latter succeeds.

I presume you've set the files back to their originals.

Would you be able to run some ntpdate tests by hand:

ntpdate -q -p 1 192.168.0.190 
ntpdate -q -p 2 192.168.0.190 
ntpdate -q -p 4 192.168.0.190

and post the output?

It might also be that your network is slow to become usable - that would need some more logging.

 

[birdman]

Your syslog shows 7 failed attempts (although "no servers can be used" changes to "no server suitable for synchronization found".

"no servers can be used" occurs if you have no network (or if you don't actually supply any servers to use, but that's not the case here).
"no server suitable for synchronization found" occurs when you have a network, but it can't reach an NTP server.

 

[Joe_90]

@birdman - I missed your posts at 1am as I had gone to bed shortly before 01:00. I did a brief test at that time and the time set correctly just after the system came up!

I did some more testing this morning and I attach some more syslog output:

Jan 27 01:33:35 mutant51 daemon.info avahi-daemon[1990]: Successfully dropped root privileges.
Jan 27 01:33:35 mutant51 daemon.info avahi-daemon[1990]: avahi-daemon 0.6.32 starting up.
Jan 27 01:33:35 mutant51 daemon.err avahi-daemon[1990]: dbus_bus_get_private(): Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
Jan 27 01:33:35 mutant51 daemon.warn avahi-daemon[1990]: WARNING: Failed to contact D-Bus daemon.
Jan 27 01:33:35 mutant51 daemon.info avahi-daemon[1990]: avahi-daemon 0.6.32 exiting.
Jan 27 01:33:37 mutant51 daemon.err ntpdate[2030]: no server suitable for synchronization found  <-------------------------------------fail1
Jan 27 01:33:42 mutant51 daemon.crit automount[1958]: key "logs" not found in map source(s).
Jan 27 01:33:44 mutant51 daemon.err ntpdate[2056]: no server suitable for synchronization found  <-----------------------------------fail2 (1+7secs)
Jan 27 01:33:54 mutant51 daemon.err ntpdate[2083]: no server suitable for synchronization found  <-----------------------------------fail3 (1+17secs)
Jan 27 08:51:59 mutant51 daemon.notice ntpdate[2097]: step time server 192.168.0.190 offset 26265.866698 sec <--------------- success1 (fail1+37secs)
Jan 27 08:52:01 mutant51 daemon.notice ntpdate[2107]: step time server 192.168.0.190 offset -0.000876 sec <-------------------success2
Jan 27 08:54:02 mutant51 daemon.crit automount[1958]: key "logs" not found in map source(s).
Jan 27 08:54:04 mutant51 daemon.notice ntpdate[2200]: adjust time server 192.168.0.190 offset -0.000376 sec  <----- success 3 after ABM crash
Jan 27 08:54:13 mutant51 daemon.notice ntpdate[2231]: adjust time server 192.168.0.190 offset 0.000081 sec   <------ success 4 after ABM crash
Jan 27 09:24:19 mutant51 daemon.notice ntpdate[3210]: adjust time server 192.168.0.190 offset -0.011357 sec   <------ normal 30min update
Jan 27 09:54:25 mutant51 daemon.notice ntpdate[4188]: adjust time server 192.168.0.190 offset -0.001958 sec   <------- normal 30min update
Jan 27 10:24:31 mutant51 daemon.notice ntpdate[5162]: adjust time server 192.168.0.190 offset -0.006156 sec   <--------normal 30min update
Jan 27 10:54:39 mutant51 daemon.err ntpdate[6164]: no server suitable for synchronization found               <--------failed normal 30min update
Jan 27 11:24:47 mutant51 daemon.err ntpdate[7147]: no server suitable for synchronization found               <--------failed normal 30min update
Jan 27 11:54:53 mutant51 daemon.notice ntpdate[8128]: adjust time server 192.168.0.190 offset -0.019584 sec   <--------normal 30min update

Now this syslog shows failed initial NTP server attempts followed by successfully reaching the server. Ignore the 08:54 entries as I had run ABM and it crashed and the GUI restarted at that point.
At 10:54 and 11:24 there are further failures of the 30 minute NTP updates, so either a network issue or the adapter had gone to sleep or something else flaky.

I've lost the timeset log that matches the syslog unfortunately, as I shut the machine down without checking I had a copy saved

I spotted yesterday evening that NetworkTime.py should have been in the Components subfolder (I put it in both in case there was a dependency elsewhere).

I'll run those manual tests now.

 

[Joe_90]

@birdman - some manual tests as requested:

~$ ssh [email protected]
root@mutant51:~# ntpdate -q -p 1 192.168.0.190
server 192.168.0.190, stratum 1, offset -0.005766, delay 0.03233
27 Jan 13:14:15 ntpdate[2907]: adjust time server 192.168.0.190 offset -0.005766 sec

root@mutant51:~# ntpdate -q -p 2 192.168.0.190
server 192.168.0.190, stratum 1, offset -0.008391, delay 0.02972
27 Jan 13:14:36 ntpdate[2919]: adjust time server 192.168.0.190 offset -0.008391 sec

root@mutant51:~# ntpdate -q -p 4 192.168.0.190
server 192.168.0.190, stratum 1, offset -0.008938, delay 0.03053
27 Jan 13:14:55 ntpdate[2927]: adjust time server 192.168.0.190 offset -0.008938 sec

I booted the machine again for the above tests. Definitely some slowness at startup. Syslog details:

Jan 27 12:14:17 mutant51 user.info kernel: [   12.557380] wlan0: RX AssocResp from f4:f2:6d:9b:fd:5a (capab=0x431 status=0 aid=2)
Jan 27 12:14:17 mutant51 user.info kernel: [   12.668124] wlan0: associated
Jan 27 12:14:17 mutant51 user.info kernel: [   12.671279] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan 27 12:14:17 mutant51 daemon.info avahi-daemon[1987]: Found user 'avahi' (UID 999) and group 'avahi' (GID 999).
Jan 27 12:14:17 mutant51 daemon.info avahi-daemon[1987]: Successfully dropped root privileges.
Jan 27 12:14:17 mutant51 daemon.info avahi-daemon[1987]: avahi-daemon 0.6.32 starting up.
Jan 27 12:14:17 mutant51 daemon.err avahi-daemon[1987]: dbus_bus_get_private(): Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
Jan 27 12:14:17 mutant51 daemon.warn avahi-daemon[1987]: WARNING: Failed to contact D-Bus daemon.
Jan 27 12:14:17 mutant51 daemon.info avahi-daemon[1987]: avahi-daemon 0.6.32 exiting.
Jan 27 12:14:20 mutant51 daemon.err ntpdate[2026]: no server suitable for synchronization found <------------fail1
Jan 27 12:14:24 mutant51 daemon.crit automount[1955]: key "logs" not found in map source(s).
Jan 27 12:14:26 mutant51 daemon.err ntpdate[2052]: no server suitable for synchronization found <------------ fail2 (fail1+6 seconds) + 6
Jan 27 12:14:36 mutant51 daemon.err ntpdate[2080]: no server suitable for synchronization found <-------------fail3 (fail2+10 seconds)+16
Jan 27 12:14:57 mutant51 daemon.err ntpdate[2094]: no server suitable for synchronization found <-------------fail4 (fail3+21 seconds)+37
Jan 27 12:15:09 mutant51 daemon.err ntpdate[2109]: no server suitable for synchronization found <-------------fail5 (fail4+12 seconds)+49
Jan 27 12:15:27 mutant51 daemon.err ntpdate[2125]: no server suitable for synchronization found <-------------fail6 (fail5+18 seconds)+67
Jan 27 12:50:51 mutant51 daemon.notice ntpdate[2140]: step time server 192.168.0.190 offset 2108.116446 sec   <<<<<< timestamp 12:15:43 (fail6+ 16 sec)+83

Your script is trying at intervals but ntpdate is failing to get to my server. The total time elapsed before a successful sync was 83 seconds. This is somewhat similar to the times reported in the posts earlier in the thread where SpaceRat was commenting.

The timeset.log which matches the above syslog:

ntpdate-sync: called with
ntpdate-sync: ifup call ignored...
ntpdate-sync: called with
ntpdate-sync: ifup call ignored...
time-setter: start called
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: called with
ntpdate-sync: ntpdate exit code 0
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
ntpdate-sync: calling ntpdate
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate exit code 1
time-setter: retrying
ntpdate-sync: called with -fg -q -abs
ntpdate-sync: calling ntpdate
ntpdate-sync: ntpdate succeeded
ntpdate-sync: ntpdate exit code 0

For reference - the box boots from deep standby to initial channel tune in about 25 seconds. The TV is activated by HDMI CEC at about 20 seconds into the boot and actually displays the tuned channel at bout 35-40 seconds.

 

[Joe_90]

I have my doubts about the "delay" figure reported by ntpdate. Is this supposed to be network delay? Expressed in seconds? It would imply 29 - 32ms delay. I see similar 26 - 35ms delays reported by ntpdate on my desktop machine which is hardwired to the LAN. The delay figure is similar for my local NTP server and for NTP servers on the WAN. The ntp daemon (ntpq) reports delays of sub millisecond on the LAN and 7 - 9ms on the WAN, typically. Delay/offset/jitter figures are in millisecond units.

ntpq -pn
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 3.ie.pool.ntp.o .POOL.          16 p    -   64    0    0.000    0.000   0.000
*192.168.0.190   .PPS.            1 u  227  256  377    0.352    0.201   0.031
-54.229.222.210  193.190.230.65   2 u  100  512  377    6.956   -0.926   0.175
-52.48.113.20    89.101.218.6     2 u  152  512  377    7.344   -1.368   0.102
-93.107.252.81   193.1.31.66      2 u  130  512  377    8.476    0.652   0.230
-193.1.219.116   .PPS.            1 u  221  256  377    7.352    3.217   0.349
-193.1.12.167    230.0.204.150    2 u  228  256  377    9.170    1.431   0.198
+52.17.30.119    89.101.218.6     2 u  263  256  377    7.136   -1.075   0.129
+193.1.31.66     .PPS.            1 u  189  256  377    9.238    0.504   0.082
-52.17.231.73    185.75.123.35    2 u  100  256  377    6.859    0.118   0.062

 

[birdman]

Progress of a sort.
I switched one of my boxes to use a Wifi interface rather than an Ethernet one.
It now takes ~24s to get the time (I've added date calls to the logging, which I meant to do before....), so at least I now have something more like what you are seeing to play with.

Strangely, there is 24s between the two "ignored" calls at the start (bringing up lo and wlan0) - and that's before the time-setter script gets called. So it's oddly slow. It only takes 6s to get a (fully) working wlan0 when the box is already up and running.

 

[Joe_90]

@birdman - see my posts #207 and #208 where I ran the tests manually as well as reporting on the boot-up. I've had no issues running ntpdate manually with the extra parameters. The "delay" value is odd, though. Maybe it's some internal delay between calls to the server, rather than the round-trip delay? Round-trip should be < 10ms on WAN, unless one has crap internet.

 

[birdman]

@birdman - see my posts #207 and #208 where I ran the tests manually as well as reporting on the boot-up. I've had no issues running ntpdate manually with the extra parameters. The "delay" value is odd, though. Maybe it's some internal delay between calls to the server, rather than the round-trip delay? Round-trip should be < 10ms on WAN, unless one has crap internet.

Well, the round-trip delay will include the time it takes the server to handle the request, so will be longer that any ping time reporting (which is a very low level thing).
I think I deleted the source, so will have to find it again to check what it is reporting.
At the moment I;m more interested in the 24s gap between bringing up localhost an the Wifi interface. If that were because it was waiting for wlan0 to be usable then that might be OK< but it isn't, as I can't set the time for further 24s after that.

 

[birdman]

At the moment I;m more interested in the 24s gap between bringing up localhost an the Wifi interface. If that were because it was waiting for wlan0 to be usable then that might be OK< but it isn't, as I can't set the time for further 24s after that.

So immediately after writing that I booted the box and got this in the reporting log:

ntpdate-sync [Sun Jan 28 13:59:51 GMT 2018]: called with
ntpdate-sync [Sun Jan 28 13:59:51 GMT 2018]: ifup call ignored...
ntpdate-sync [Sun Jan 28 13:59:56 GMT 2018]: called with
ntpdate-sync [Sun Jan 28 13:59:56 GMT 2018]: ifup call ignored...
time-setter [Sun Jan 28 13:59:56 GMT 2018]: start called
ntpdate-sync [Sun Jan 28 13:59:57 GMT 2018]: called with -fg -q -abs
ntpdate-sync [Sun Jan 28 13:59:57 GMT 2018]: calling ntpdate
ntpdate-sync [Sun Jan 28 21:48:47 GMT 2018]: ntpdate succeeded
ntpdate-sync [Sun Jan 28 21:48:47 GMT 2018]: ntpdate exit code 0

Just 5s between lo and wlan0, with the first call to ntpdate from time-setter setting the correct time.
Hmmm....random weirdness.

 

[Joe_90]

@birdman - re #211 - it's not a ping time being reported by ntpd, it's the round trip delay. NTP messages are short, just responding with system time. ntpd (and ntpdate) timestamp on the request and again on the response and compare with the contents of the reply and calculate the delay. 9 - 10ms would not be unusual on a good internet connection. 30ms would be quite long which is why I thought the ntpdate delay reports were odd (unless it was some other delay factor internal to ntpdate).

 

[birdman]

(unless it was some other delay factor internal to ntpdate).

That's what I was wondering. A ping response is very low-level and immediate, but an NTP response requires some work by the server, and that work takes time (possibly a specific amount...).

Anyway, I've added another logging script (and minorly-updated the earlier ones). I'm still seeing just a 5s gap between the ifup calls to for lo and wlan0, and the wlan0 interface is fully up (IP address assigned) by the time ntpdate-sync is called.

ntpdate-sync [Mon Jan 29 01:46:43 GMT 2018]: called with
ntpdate-sync [Mon Jan 29 01:46:43 GMT 2018]: ifup call ignored (loopback/lo)...
ntpdate-sync [Mon Jan 29 01:46:48 GMT 2018]: called with
ntpdate-sync [Mon Jan 29 01:46:48 GMT 2018]: ifup call ignored (dhcp/wlan0)...
time-setter [Mon Jan 29 01:46:48 GMT 2018]: start called
ntpdate-sync [Mon Jan 29 01:46:48 GMT 2018]: called with -fg -q -abs
ntpdate-sync [Mon Jan 29 01:46:48 GMT 2018]: calling ntpdate
ntpdate-sync [Mon Jan 29 01:54:27 GMT 2018]: ntpdate succeeded
ntpdate-sync [Mon Jan 29 01:54:27 GMT 2018]: ntpdate exit code 0
ntpdate-sync [Mon Jan 29 01:55:35 GMT 2018]: called with
ntpdate-sync [Mon Jan 29 01:55:35 GMT 2018]: ntpdate exit code 0
ntpdate-sync [Mon Jan 29 01:55:35 GMT 2018]: calling ntpdate
ntpdate-sync [Mon Jan 29 01:55:42 GMT 2018]: ntpdate succeeded

I'll prepare another zip file, if you're interested in running it on your system?

View attachment timeset2.zip

This adds date stamps to the [FONT=courier\ new]timeset.log[/FONT] (and which ifup call was ignored).
It also adds:

• etc/rc3.d/S00-OV-monitor
  which runs top and ifconfig for a minute (30 x 2s intervals), putting the output into [FONT=courier\ new]/var/tmp/top_info.log[/FONT] and [FONT=courier\ new]/var/tmp/ifconfig_info.log[/FONT]. This gives some idea of which processes are running and what state the network is in.

This might give us some idea of why your system takes 80s+ to be able to set the time.

EDIT: later updated to display the full ntpdate command in the log (and to add a "start" clause to the S00-OV-monitor script, for neatness).

 

[birdman]

That's what I was wondering. A ping response is very low-level and immediate, but an NTP response requires some work by the server, and that work takes time (possibly a specific amount...

It is the delay time for the packet, but there's some processing being done before it get the current time,. so I expect that is why it's longer than ping times.

I managed to get this one:

 [parent]: ntpdate -q -p 1 pool.ntp.org
server 178.79.160.57, stratum 2, offset 0.002943, delay 0.04663
server 178.79.162.34, stratum 3, offset 0.002931, delay 0.04620
server 129.215.160.240, stratum 2, offset 0.001690, delay 0.05643
[COLOR=#ff0000]server 178.62.250.107, stratum 0, offset 0.000000, delay 0.00000[/COLOR]
29 Jan 02:11:38 ntpdate[8209]: adjust time server 178.79.160.57 offset 0.002943 sec

So unless I managed to make the speed of light infinite the value is clearly only a guide to something.

 

[Joe_90]

It is the delay time for the packet, but there's some processing being done before it get the current time,. so I expect that is why it's longer than ping times.

I managed to get this one:

 [parent]: ntpdate -q -p 1 pool.ntp.org
server 178.79.160.57, stratum 2, offset 0.002943, delay 0.04663
server 178.79.162.34, stratum 3, offset 0.002931, delay 0.04620
server 129.215.160.240, stratum 2, offset 0.001690, delay 0.05643
[COLOR=#ff0000]server 178.62.250.107, stratum 0, offset 0.000000, delay 0.00000[/COLOR]
29 Jan 02:11:38 ntpdate[8209]: adjust time server 178.79.160.57 offset 0.002943 sec

So unless I managed to make the speed of light infinite the value is clearly only a guide to something.

Will use your zip file and re-test, thanks.

Something wrong with that log entry highlighted in red. You can't (shouldn't) respond on the network as stratum zero. Stratum zero is reserved for primary time sources (like atomic clocks and national laboratory/time signal sources). Primary NTP servers which receive their time from stratum zero time source are themselves stratum 1. My RPi runs a kernel-level GPS PPS (pulse per second) time source which is stratum zero and has effectively a zero delay internally, but its responses to requests indicate that it is stratum 1.

Sorry to labour the point about delay times - the delay times reported by ntpd are not ping times but time server packet response times. I can get ping times of about 6ms from Google DNS. Local national time servers respond with time packets in about 6 - 10ms as reported by ntpq. 40 - 50ms delays reported by ntpdate in your example above are quite lengthy, which is why I thought they were maybe the total time for polling several servers.

ntpq -pn
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 3.ie.pool.ntp.o .POOL.          16 p    -   64    0    0.000    0.000   0.000
*192.168.0.190   .PPS.            1 u    5  128  377    0.343    0.710   0.167
-54.229.222.210  193.190.230.65   2 u  215  256  377    6.581    0.780   0.210
-54.194.18.100   216.239.35.8     2 u  156  256  377    6.851    0.206   1.982
+52.17.30.119    89.101.218.6     2 u   80  128  377    6.883    0.796   0.193
-93.107.252.81   193.1.31.66      2 u   73  128  377    8.332    0.505   0.263
+193.1.219.116   .PPS.            1 u   90  128  377    7.145    3.838   0.442
 52.209.118.149  89.101.218.6     2 u  105  128  177    6.724    0.711   0.156
 52.17.231.73    185.75.123.35    2 u   93  128  177    6.570    1.094   0.365
 52.214.117.37   89.101.218.6     2 u   31  128   77    6.680    1.047   0.148

 

[birdman]

Sorry to labour the point about delay times - the delay times reported by ntpd are not ping times but time server packet response times.

I know. They include some ntp(d) processing time.

I can get ping times of about 6ms from Google DNS.

I get ~24ms. Even pinging my ISPs DNS servers I only get down to 17ms.

 

[Joe_90]

Right - here is the updated set of tests. The stored time on the system was 12:55. I started the boot at 13:00 actual and kept an eye on the time displayed in the GUI (12:55ish) until it changed to the actual time of 13:01:26

timeset.log

date-sync [Mon Jan 29 12:55:11 GMT 2018]: called with 
ntpdate-sync [Mon Jan 29 12:55:11 GMT 2018]: ifup call ignored (loopback/lo)...
ntpdate-sync [Mon Jan 29 12:55:15 GMT 2018]: called with 
ntpdate-sync [Mon Jan 29 12:55:15 GMT 2018]: ifup call ignored (dhcp/wlan0)...
time-setter [Mon Jan 29 12:55:15 GMT 2018]: start called
ntpdate-sync [Mon Jan 29 12:55:15 GMT 2018]: called with -fg -q -abs
ntpdate-sync [Mon Jan 29 12:55:15 GMT 2018]: calling ntpdate -p 1 -b -s 192.168.0.190
ntpdate-sync [Mon Jan 29 12:55:17 GMT 2018]: ntpdate exit code 1
time-setter [Mon Jan 29 12:55:19 GMT 2018]: retrying
ntpdate-sync [Mon Jan 29 12:55:19 GMT 2018]: called with -fg -q -abs
ntpdate-sync [Mon Jan 29 12:55:19 GMT 2018]: calling ntpdate -p 1 -b -s 192.168.0.190
ntpdate-sync [Mon Jan 29 12:55:21 GMT 2018]: called with 
ntpdate-sync [Mon Jan 29 12:55:21 GMT 2018]: ntpdate exit code 0
ntpdate-sync [Mon Jan 29 12:55:21 GMT 2018]: ntpdate exit code 1
time-setter [Mon Jan 29 12:55:25 GMT 2018]: retrying
ntpdate-sync [Mon Jan 29 12:55:25 GMT 2018]: called with -fg -q -abs
ntpdate-sync [Mon Jan 29 12:55:25 GMT 2018]: calling ntpdate -p 1 -b -s 192.168.0.190
ntpdate-sync [Mon Jan 29 12:55:27 GMT 2018]: ntpdate exit code 1
time-setter [Mon Jan 29 12:55:35 GMT 2018]: retrying
ntpdate-sync [Mon Jan 29 12:55:36 GMT 2018]: called with -fg -q -abs
ntpdate-sync [Mon Jan 29 12:55:36 GMT 2018]: calling ntpdate -p 1 -b -s 192.168.0.190
ntpdate-sync [Mon Jan 29 12:55:38 GMT 2018]: ntpdate exit code 1
ntpdate-sync [Mon Jan 29 12:55:51 GMT 2018]: calling ntpdate   -s 192.168.0.190
time-setter [Mon Jan 29 12:55:54 GMT 2018]: retrying
ntpdate-sync [Mon Jan 29 12:55:54 GMT 2018]: called with -fg -q -abs
ntpdate-sync [Mon Jan 29 13:01:24 GMT 2018]: ntpdate succeeded
ntpdate-sync [Mon Jan 29 13:01:26 GMT 2018]: calling ntpdate -p 1 -b -s 192.168.0.190
ntpdate-sync [Mon Jan 29 13:01:26 GMT 2018]: ntpdate succeeded
ntpdate-sync [Mon Jan 29 13:01:26 GMT 2018]: ntpdate exit code 0

The ifconfig log shows wlan0 up and receiving a packet (113 bytes) at 12:55:13. By 12:55:15 it had received 9(1.7KiB) and transmitted 11(1.6KiB) packets. And so on every two seconds up to 12:55:56 by which time it had received 15.7KiB and transmitted 4.4KiB with no errors or dropped frames or collisions. The next timestamp is 13:01:27 and every two seconds after that up to 13:01:37 at which time the log ends.


A section from the syslog:

Jan 29 12:55:18 mutant51 user.info kernel: [    9.353799] rtl8192cu: Chip version 0x11
Jan 29 12:55:18 mutant51 user.info kernel: [    9.450291] rtl8192cu: Board Type 0
Jan 29 12:55:18 mutant51 user.info kernel: [    9.454142] rtl_usb: rx_max_size 15360, rx_urb_num 8, in_ep 1
Jan 29 12:55:18 mutant51 user.info kernel: [    9.460168] rtl8192cu: Loading firmware rtlwifi/rtl8192cufw_TMSC.bin
Jan 29 12:55:18 mutant51 user.debug kernel: [    9.467038] ieee80211 phy0: Selected rate control algorithm 'rtl_rc'
Jan 29 12:55:18 mutant51 user.info kernel: [    9.467852] usbcore: registered new interface driver rtl8192cu
Jan 29 12:55:18 mutant51 user.info kernel: [    9.630305] EXT4-fs (mmcblk0p3): re-mounted. Opts: data=ordered
Jan 29 12:55:18 mutant51 user.notice kernel: [   10.556129] random: crng init done
Jan 29 12:55:18 mutant51 user.info kernel: [   10.814207] NET: Registered protocol family 10
Jan 29 12:55:18 mutant51 user.info kernel: [   10.819501] Segment Routing with IPv6
Jan 29 12:55:18 mutant51 user.info kernel: [   10.968141] rtl8192cu: MAC auto ON okay!
Jan 29 12:55:18 mutant51 user.info kernel: [   11.006173] rtl8192cu: Tx queue select: 0x05
Jan 29 12:55:18 mutant51 user.info kernel: [   11.486312] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jan 29 12:55:18 mutant51 user.info kernel: [   12.555300] wlan0: authenticate with xxx
Jan 29 12:55:18 mutant51 user.info kernel: [   12.578733] wlan0: send auth to xxx (try 1/3)
Jan 29 12:55:18 mutant51 user.info kernel: [   12.688450] wlan0: send auth to xxx (try 2/3)
Jan 29 12:55:18 mutant51 user.info kernel: [   12.721783] wlan0: authenticated
Jan 29 12:55:18 mutant51 user.info kernel: [   12.726422] wlan0: associate with xxx (try 1/3)
Jan 29 12:55:18 mutant51 user.info kernel: [   12.770411] wlan0: RX AssocResp from xxx (capab=0x431 status=0 aid=3)
Jan 29 12:55:18 mutant51 user.info kernel: [   12.784447] wlan0: associated
Jan 29 12:55:18 mutant51 user.info kernel: [   12.787591] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan 29 12:55:18 mutant51 daemon.info avahi-daemon[2010]: Found user 'avahi' (UID 999) and group 'avahi' (GID 999).
Jan 29 12:55:18 mutant51 daemon.info avahi-daemon[2010]: Successfully dropped root privileges.
Jan 29 12:55:18 mutant51 daemon.info avahi-daemon[2010]: avahi-daemon 0.6.32 starting up.
Jan 29 12:55:18 mutant51 daemon.err avahi-daemon[2010]: dbus_bus_get_private(): Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
Jan 29 12:55:18 mutant51 daemon.warn avahi-daemon[2010]: WARNING: Failed to contact D-Bus daemon.
Jan 29 12:55:18 mutant51 daemon.info avahi-daemon[2010]: avahi-daemon 0.6.32 exiting.
Jan 29 12:55:21 mutant51 daemon.err ntpdate[2052]: no server suitable for synchronization found
Jan 29 12:55:26 mutant51 daemon.crit automount[1978]: key "logs" not found in map source(s).
Jan 29 12:55:27 mutant51 daemon.err ntpdate[2093]: no server suitable for synchronization found
Jan 29 12:55:38 mutant51 daemon.err ntpdate[2141]: no server suitable for synchronization found
Jan 29 13:01:24 mutant51 daemon.notice ntpdate[2181]: step time server 192.168.0.190 offset 326.902025 sec
Jan 29 13:01:26 mutant51 daemon.notice ntpdate[2207]: step time server 192.168.0.190 offset -0.000044 sec

The timestamps in syslog show the wlan interface authenticating at 12:55:18 and the link becoming ready at that point, which is some seconds after ntpdate has been fired. I presume the syslog timestamps are ok, but they all show 12:55:18 (some 268 lines of syslog) until the ntpdate daemon error is logged at 12:55:21???

 

[birdman]

Right - here is the updated set of tests.

So, your link was reported as up and ready at "12:55:18"

 Jan 29 12:55:18 mutant51 user.info kernel: [   12.787591] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

but ntpdate continued to fail until "12:55:54".

There is also this odd sequence:

ntpdate-sync [Mon Jan 29 12:55:21 GMT 2018]: called with

which is probably the call from within enigma2 as it starts up. But the rest of this sequence appears to be:

ntpdate-sync [Mon Jan 29 12:55:21 GMT 2018]: ntpdate exit code 0

It's immediately backgrounded the work, so exits with 0.

ntpdate-sync [Mon Jan 29 12:55:51 GMT 2018]: calling ntpdate   -s 192.168.0.190
...
ntpdate-sync [Mon Jan 29 13:01:24 GMT 2018]: ntpdate succeeded

So why did it wait 30s before calling ntpdate?

If you could post the top_info.log (as a zip file) we could find out what else was running at the time.

 

[Joe_90]

Here you go!