Vix 5.1.006. Time wrong

[twol]

So your build will contain all current OEA „time fix“ commits - and you still have issues.

So would be nice if SpaceRat could layout a strategy for fixing this issue or at least layout what he is planning.

[Joe_90]

So your build will contain all current OEA „time fix“ commits - and you still have issues.

So would be nice if SpaceRat could layout a strategy for fixing this issue or at least layout what he is planning.

Yes - I waited to see his posts on GitHub before I kicked off the build yesterday and checked that he had updated OE 4.2 branch.

[birdman]

So would be nice if SpaceRat could layout a strategy for fixing this issue or at least layout what he is planning.

I think the current strategy is that I'm going to write a ntpdate-sync that optionally does the sync synchronously when a network comes up (that option being defined within the settings file).

The biggest issue here seems to be how long it takes for a Wifi interface to become usable (since wpa_supplicant needs to achieve that). I'll need to do some tests on a Wifi interface for that....

It would be nice if if-up.d scripts weren't run until an interface were up, running and usable - it may only check the first two.

[birdman]

Thanks @birdman. It did confuse me, but I thought it was maybe a "style" thing. I'm an old-school programmer from the time before object-oriented languages. I haven't programmed since the early 80's as my job description changed over time.

I did the reverse. Having done some programming in the early 70s I stopped, then ended up "accidentally" moving into programming in 1983, where I stayed for >30 years.

The log shows ntpdate-sync being kicked off at 23.212 seconds and returning some 81 seconds later and the system time of 10:46:29 being set. Subsequent updates of ntpdate-sync (at 30 minute intervals) return within about 6 seconds.

I can't figure out that original 81s, although it is the second one to run that takes this time (i.e. the first one run by enigma2, rather than the earlier one run by the network interface star-up).

I've just been testing out adding a Wifi interface to my MBtwin. When I bring it up it is pingable (and usable) in ~2s. Likewise on my laptop (which send more info the the system logs) the Wifi seems to take 1.5s to get associated and ready (oddly, the Ethernet connexion takes 3s). Your syslog also shows your interface being ready quite quickly.

There is an ntpdate update shown at 10:45:59 which is some 30 seconds before the update shown in the debug log. It would appear to me that ntpdate is being fired twice at least during the boot phase.

As I've noted, there will be one ntpdate-sync as the network interface is brought up (and since you are running this in the background syslogd will be running by the time it completes, so it gets recorded). Then enigma2, as it start up, also runs a sync if you have configured the time to be set by ntp rather than from the transponders. I reckon this one is unneeded, given that the system will have just done one.

I agree with you that somehow the clock setting needs to be synchronous and that checks for ABM and recording timers need to wait until the time is established.

[Joe_90]

I changed the NTP server entry to my local address (192.168.0.190) yesterday evening, just to get back to my "usual" configuration. This morning, I had the usual delayed setting of the system time. Snip from the syslog shows three time settings by ntpdate at start time. Only one setting (using ntpdate-sync) shown in the debug log with the same 80 second delay between call and return. Subsequent calls of ntpdate-sync seem to take about six seconds, but that may be because of the external pinging of google servers as an online check.

Jan 21 17:10:16 mutant51 user.info kernel: [   12.518925] wlan0: authenticate with f4:f2:6d:9b:fd:5a
Jan 21 17:10:16 mutant51 user.info kernel: [   12.547264] wlan0: send auth to f4:f2:6d:9b:fd:5a (try 1/3)
Jan 21 17:10:16 mutant51 user.info kernel: [   12.568581] wlan0: authenticated
Jan 21 17:10:16 mutant51 user.info kernel: [   12.572457] wlan0: associate with f4:f2:6d:9b:fd:5a (try 1/3)
Jan 21 17:10:16 mutant51 user.info kernel: [   12.582250] wlan0: RX AssocResp from f4:f2:6d:9b:fd:5a (capab=0x431 status=0 aid=4)
Jan 21 17:10:16 mutant51 user.info kernel: [   12.692383] wlan0: associated
Jan 21 17:10:16 mutant51 user.info kernel: [   12.695482] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan 21 17:10:16 mutant51 daemon.info avahi-daemon[1982]: Found user 'avahi' (UID 999) and group 'avahi' (GID 999).
Jan 21 17:10:16 mutant51 daemon.info avahi-daemon[1982]: Successfully dropped root privileges.
Jan 21 17:10:16 mutant51 daemon.info avahi-daemon[1982]: avahi-daemon 0.6.32 starting up.
Jan 21 17:10:16 mutant51 daemon.err avahi-daemon[1982]: dbus_bus_get_private(): Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
Jan 21 17:10:16 mutant51 daemon.warn avahi-daemon[1982]: WARNING: Failed to contact D-Bus daemon.
Jan 21 17:10:16 mutant51 daemon.info avahi-daemon[1982]: avahi-daemon 0.6.32 exiting.
Jan 21 17:10:23 mutant51 daemon.crit automount[1950]: key "logs" not found in map source(s).
Jan 22 10:54:06 mutant51 daemon.notice ntpdate[2083]: step time server 192.168.0.190 offset 63785.191245 sec
Jan 22 10:54:20 mutant51 daemon.notice ntpdate[2093]: adjust time server 192.168.0.190 offset -0.000026 sec
Jan 22 10:54:49 mutant51 daemon.notice ntpdate[2113]: adjust time server 192.168.0.190 offset -0.000274 sec

[birdman]

I changed the NTP server entry to my local address (192.168.0.190) yesterday evening, just to get back to my "usual" configuration......

I've been thinking more about this (before actually doing anything). There is an issue with systems with multiple active interfaces - they will do an ntpdate sync for each one, which makes no sense. You really want to do it just once, after all interfaces are up*, but you'll never know when that is when being called from ifup. The only reliable way you can run after all interfaces have been started is to run it from a separate sysvinit script run imediately after the network starter (S10networking).



*You might have your DNS resolver reachable via the first interface and your NTP server via the last one. Or vice versa....

[Joe_90]

Hmmm - I disable the ethernet port interface during the install network wizard, but it's still physically present of course, so it may be firing multiple ntpdate syncs, but the ethernet port is not cabled to anything, so there shouldn't be any reply. I just thought that the three ntpdate responses within the same minute as shown in syslog in post #155 was a bit odd as they could only be satisfied on the WiFi interface.

[birdman]

Hmmm - I disable the ethernet port interface during the install network wizard, but it's still physically present of course

No. it has to be configured to come up.

I just thought that the three ntpdate responses within the same minute as shown in syslog in post #155 was a bit odd as they could only be satisfied on the WiFi interface.

When ntpdate-sync is called for an interface coming up it sends the -b option to ntpdate, which steps the time (sets it absolutely). At other times this isn't set, so the system clock is sped up/slowed down slightly to move it towards the real time in a continuously forward-advancing time manner.
So the second two settings which you have are not from ifup.

I suppose its possible(?) that this is happening, bearing in mind that all of your ntpdate-sync run in the background (which is, I reckon, a big part of your problem, although oddly no-one else seems to see it).

1. ifup brings up an interface and ntpdate-sync(1) runs. For some reason it takes a while...
2. enigma2 starts and fires up ntpdate-sync(2). It also schedules another one in 30 mins.
3. ntpdate-sync(1) completes and sets the time absolutely (advancing it by 17h 40+m).
4. The enigma2 scheduler sees that it's next ntpdate-sync run has passed (some 17h 10+m ago...) so fires off ntpdate-sync(3).
5. ntpdate-sync(2) finishes and slews the time
6. ntpdate-sync(3) finishes and slews the time

This is dependent on enigma2 using absolute time for timers; not a good idea if the time can change underneath you, but I suspect that the expectation (given that it is meant to be scheduling recordings by absolute time) is that the time is always correct - hence the need to ensure this before enigma2 starts.

[Joe_90]

Thanks @birdman. What you say about E2 firing off an ntpdate-sync and then the scheduler seeing the time advance by >30 minutes and firing another makes sense. Where does enigma2 call the ntpdate-sync script?
I know the difference between stepping and slewing the time from using ntpd on my linux machines. The first call to ntpd steps the system clock by the calculated offset from its current value. Subsequently, ntpd slews the system clock toward the actual time by varying the oscillator frequency. ntpdate has similar functions but is not quite as sophisticated as ntpd. SpaceRat has changed the behaviour of ntpdate by using stepping on the first call and slewing thereafter which makes sense.

[twol]

Guys, I learn something from all these posts, but it doesnt move fat—tony forward.
There is obviously an issue, which (I guess ) is WiFi related and unless Birdman can come up with a solution (which would be great), I really expect more from SpaceRat than silence on this public thread

[ccs]

... I'm sure he's as keen as everyone else to find a solution to this problem.

[twol]

... I'm sure he's as keen as everyone else to find a solution to this problem.

Then he should rejoin the conversation ... I like a lot of the changes he has introduced to the OEA (a breath of fresh air), but one also needs to fix things as you move foreward

[SpaceRat]

There isn't really a problem anymore ...
With the latest changes, ntpdate will no longer run twice at the same time.
The log entry shows this:
One stepping, two slewings and several seconds in between.

It might look strange inside the syslog, but it works.

If one wants to get rid of the multiple runs in short sequence, there is no other option as really making the ifup sync synchronous, but that would slow down boot for everybody.
E2 on the other hand can handle a time change at boot, it occurs with the default DVB sync too, at least if the box isn't networked.

Gesendet von meinem SM-N910F mit Tapatalk

[twol]

There isn't really a problem anymore ...
With the latest changes, ntpdate will no longer run twice at the same time.
The log entry shows this:
One stepping, two slewings and several seconds in between.

It might look strange inside the syslog, but it works.

If one wants to get rid of the multiple runs in short sequence, there is no other option as really making the ifup sync synchronous, but that would slow down boot for everybody.
E2 on the other hand can handle a time change at boot, it occurs with the default DVB sync too, at least if the box isn't networked.

Gesendet von meinem SM-N910F mit Tapatalk

Thanks for the reply

[SpaceRat]

I already offered birdman to make the necessary changes to the recipe, so that OpenViX gets a synchronous NTP sync btw.


Some other possible optimization would be to have ntpdate-sync create/delete flagfiles that indicate success (or fail) of the sync.
Currently E2 simply assumes that the call to ntpdate-sync is successful and the time WAS synced, but in reality it might as well fail and even if it succeeds, it only WILL (in the future) adjust the clock, relative to the time of calling it.

Gesendet von meinem SM-N910F mit Tapatalk