Vix 5.1.006. Time wrong

[ccs]

Maybe including PID's in the logs will help debugging?

 

[birdman]

Here you go!

Thanks.
What version of Vix are you running? Could you look at the top of the enigma2.sh script and see whether the call to ntpdate is commented out?

Also, I see you have the lockfile-create program installed. I suspect this is now delaying the time setting....but I have to look at what it actually does (it's usage is odd).

 

[birdman]

Maybe including PID's in the logs will help debugging?

I can't discover them in a shell script...

 

[ccs]

It's such a long time ago now, but isn't $$ set to the PID?

 

[birdman]

It's such a long time ago now, but isn't $$ set to the PID?

It's set to the pid of the current process, but I don't need to know that - I'm tracking other processes.

 

[ccs]

.. I just thought that the scripts which are producing debug logs could also include their PID, so if 2 ran concurrently the logs would show which was which, and top would also be able to identify them.

 

[birdman]

Also, I see you have the lockfile-create program installed. I suspect this is now delaying the time setting....but I have to look at what it actually does (it's usage is odd).

It's certainly incompatible with the way the script is now used.

lockfile-create will actually keep trying to get the lock, waiting for up to 3 mins to do so. This isn't what we want, and the script never bothers to check whether it reached the 3 mins without ever succeeding.
What this script needs is, "try to get the lock once and, if that fails, just exit".

 

[Joe_90]

Thanks.
What version of Vix are you running? Could you look at the top of the enigma2.sh script and see whether the call to ntpdate is commented out?

Also, I see you have the lockfile-create program installed. I suspect this is now delaying the time setting....but I have to look at what it actually does (it's usage is odd).

I'm running my own dev build from 4.2 (thus creating a Vix 5.2.000). This was done to incorporate all of SpaceRat's changes and to give me an absolutely clean build environment. I have to build my own because there are no official dev builds for the mutant HD51. SpaceRat amended the build files to include "lockfile-create" because it wasn't included by default in ViX, but is referenced in ntpdate-sync to ensure that ntpdate is not fired twice (which was causing an issue where time is stepped on the double and pushing the box into the future). I'm not sure why you would need a separate "lockfile-create" script, though? I've seen other uses where the calling script checks for the existence of a lockfile and if not present, just creates one by using the touch command and then deletes it when finished.

enigma2.sh script has the call to ntpdate commented out. This is why I have have asked several times in this thread where ntpdate is being called, apart from the ntpdate-sync script. I couldn't understand why there were multiple calls to ntpdate being made if there was a locking mechanism in place.

 

[birdman]

enigma2.sh script has the call to ntpdate commented out. This is why I have have asked several times in this thread where ntpdate is being called, apart from the ntpdate-sync script. I couldn't understand why there were multiple calls to ntpdate being made if there was a locking mechanism in place.

It (or rather, ntpdate-sync) is called by the enigma2 binary shortly after it starts, and every 30 mins thereafter if you are using NTP (rather than transponder) time.
However, the way it's been used is actually messing up trying to get the time set using NTP by adding unnecessary delays.

 

[birdman]

SpaceRat amended the build files to include "lockfile-create" because it wasn't included by default in ViX,

It isn't installed by default, but is available.
And, as noted above, you don't actually want it in place with the way it is used in the ntpdate-sync script.

but is referenced in ntpdate-sync to ensure that ntpdate is not fired twice

Unfortunetely that's not what the code actually does. All it does is queue calls, and doesn't abort an attempt that times out but rather lets it run on...

I'm not sure why you would need a separate "lockfile-create" script, though? I've seen other uses where the calling script checks for the existence of a lockfile and if not present, just creates one by using the touch command and then deletes it when finished.

That is not atomic (it has a trivial race condition) which is why you need to use a separate executable (to use the link() system call, which is atomic).

 

[birdman]

It isn't installed by default, but is available.

Ah. It wasn't installed the last time I looked, but it is now....

Anyway - here's an ntpdate-sync script that has been corrected to:

• Only try to take the lock once (zero retries) as if there is already one running there is no point in running a second one at all.
• If the attempt to take the lock fails then it sets an error exit code and exits.
• If the ntpdate call is backgrounded it sets the exit code to -1 for the original call

View attachment ntpdate-sync.zip

I think this may speed up your NTP syncing...

 

[birdman]

I think this may speed up your NTP syncing...

On further thinking it might not, but it will tidy things up.
I suspect we'll need more info on the state of your Wifi interface over time...

 

[Joe_90]

Ok - before I run further tests with your amended ntpdate-sync, here are the highlights from this morning's boot! ntpdate seemed to work first time because, as soon as the first channel was tuned (about 25 - 30 seconds after power on) and I could display the time on the GUI it was set correctly. ntpdate-sync was fired several times even though it had exited correctly according to the timeset log. Your new script may sort that out, though, thanks.

syslog:

Jan 29 17:12:52 mutant51 daemon.info avahi-daemon[2009]: Found user 'avahi' (UID 999) and group 'avahi' (GID 999).
Jan 29 17:12:52 mutant51 daemon.info avahi-daemon[2009]: Successfully dropped root privileges.
Jan 29 17:12:52 mutant51 daemon.info avahi-daemon[2009]: avahi-daemon 0.6.32 starting up.
Jan 29 17:12:52 mutant51 daemon.err avahi-daemon[2009]: dbus_bus_get_private(): Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
Jan 29 17:12:52 mutant51 daemon.warn avahi-daemon[2009]: WARNING: Failed to contact D-Bus daemon.
Jan 29 17:12:52 mutant51 daemon.info avahi-daemon[2009]: avahi-daemon 0.6.32 exiting.
Jan 30 10:34:25 mutant51 daemon.notice ntpdate[2055]: step time server 192.168.0.190 offset 62492.527261 sec
Jan 30 10:34:32 mutant51 daemon.crit automount[1977]: key "logs" not found in map source(s).
Jan 30 10:34:35 mutant51 daemon.notice ntpdate[2072]: adjust time server 192.168.0.190 offset -0.001282 sec
Jan 30 10:34:43 mutant51 daemon.notice ntpdate[2127]: adjust time server 192.168.0.190 offset 0.000312 sec
Jan 30 11:04:49 mutant51 daemon.notice ntpdate[3173]: adjust time server 192.168.0.190 offset -0.011923 sec
Jan 30 11:34:55 mutant51 daemon.notice ntpdate[4151]: adjust time server 192.168.0.190 offset -0.001563 sec
Jan 30 12:05:01 mutant51 daemon.notice ntpdate[5129]: adjust time server 192.168.0.190 offset -0.005702 sec
Jan 30 12:35:08 mutant51 daemon.notice ntpdate[6120]: adjust time server 192.168.0.190 offset -0.005411 sec

timeset.log:

ntpdate-sync [Mon Jan 29 17:12:44 GMT 2018]: called with 
ntpdate-sync [Mon Jan 29 17:12:44 GMT 2018]: ifup call ignored (loopback/lo)...
ntpdate-sync [Mon Jan 29 17:12:49 GMT 2018]: called with 
ntpdate-sync [Mon Jan 29 17:12:49 GMT 2018]: ifup call ignored (dhcp/wlan0)...
time-setter [Mon Jan 29 17:12:49 GMT 2018]: start called
ntpdate-sync [Mon Jan 29 17:12:49 GMT 2018]: called with -fg -q -abs
ntpdate-sync [Mon Jan 29 17:12:49 GMT 2018]: calling ntpdate -p 1 -b -s 192.168.0.190
ntpdate-sync [Mon Jan 29 17:12:51 GMT 2018]: ntpdate exit code 1
time-setter [Mon Jan 29 17:12:53 GMT 2018]: retrying
ntpdate-sync [Mon Jan 29 17:12:53 GMT 2018]: called with -fg -q -abs
ntpdate-sync [Mon Jan 29 17:12:53 GMT 2018]: calling ntpdate -p 1 -b -s 192.168.0.190
ntpdate-sync [Tue Jan 30 10:34:25 GMT 2018]: ntpdate succeeded
ntpdate-sync [Tue Jan 30 10:34:25 GMT 2018]: ntpdate exit code 0
ntpdate-sync [Tue Jan 30 10:34:27 GMT 2018]: called with 
ntpdate-sync [Tue Jan 30 10:34:27 GMT 2018]: calling ntpdate   -s 192.168.0.190
ntpdate-sync [Tue Jan 30 10:34:27 GMT 2018]: ntpdate exit code 0
ntpdate-sync [Tue Jan 30 10:34:32 GMT 2018]: called with 
ntpdate-sync [Tue Jan 30 10:34:32 GMT 2018]: ntpdate exit code 0
ntpdate-sync [Tue Jan 30 10:34:35 GMT 2018]: ntpdate succeeded
ntpdate-sync [Tue Jan 30 10:34:37 GMT 2018]: calling ntpdate   -s 192.168.0.190
ntpdate-sync [Tue Jan 30 10:34:43 GMT 2018]: ntpdate succeeded
ntpdate-sync [Tue Jan 30 11:04:43 GMT 2018]: called with 
ntpdate-sync [Tue Jan 30 11:04:43 GMT 2018]: ntpdate exit code 0
ntpdate-sync [Tue Jan 30 11:04:43 GMT 2018]: calling ntpdate   -s 192.168.0.190
ntpdate-sync [Tue Jan 30 11:04:49 GMT 2018]: ntpdate succeeded
ntpdate-sync [Tue Jan 30 11:34:49 GMT 2018]: called with 
ntpdate-sync [Tue Jan 30 11:34:49 GMT 2018]: ntpdate exit code 0
ntpdate-sync [Tue Jan 30 11:34:49 GMT 2018]: calling ntpdate   -s 192.168.0.190
ntpdate-sync [Tue Jan 30 11:34:55 GMT 2018]: ntpdate succeeded
ntpdate-sync [Tue Jan 30 12:04:55 GMT 2018]: called with 
ntpdate-sync [Tue Jan 30 12:04:55 GMT 2018]: ntpdate exit code 0
ntpdate-sync [Tue Jan 30 12:04:55 GMT 2018]: calling ntpdate   -s 192.168.0.190
ntpdate-sync [Tue Jan 30 12:05:01 GMT 2018]: ntpdate succeeded

Over the past day or two the system seems to be getting the correct time established eventually although it might take 80 or so seconds to do it.

The remaining "wrinkle" is that the debug log filename is still getting set from the stored last shutdown time (fake-hwclock time). Overall, there is a lot of code and checking gone in to the system subsequently to get it (nearly) to the point it was before any of the "fake hwclock" code was implemented in December. Before that, my system was behaving properly, obtaining NTP time at startup with correct log filenaming etc. It may have been doing so because of some happy "quirks" in the system, but it was working!

@birdman, you have put a lot of time and effort into helping identify various issues and work through them, thanks. Not sure where we go from here, though

 

[Joe_90]

Sort of surprised that there are NO new posts anywhere on the forum since last night!
Ran with the new ntpdate-sync this morning with no issues. In fact, on both boots this morning the time updated within the first 20 seconds of the boot and the logs have the correct current date and time in the filename.

 

[birdman]

Sort of surprised that there are NO new posts anywhere on the forum since last night!

Everyone filing tax returns at (almost) the last minute?

Ran with the new ntpdate-sync this morning with no issues. In fact, on both boots this morning the time updated within the first 20 seconds of the boot and the logs have the correct current date and time in the filename.

Not sure whether that's good or bad. I'd like to know why it was taking >80s before.
The odd thing is tat when I first switch over to Wifi it also took a long time - and has never repeated that (always now setting the time at the first attempt).

I'll tidy up what I have and discuss the results and way forward with SpaceRat.

I'll also check what I think is a bug that having changed you NTP server from pool.ntp.org you can never set it back. The fix would be to remove ~2 lines of code.

 

[birdman]

I'll also check what I think is a bug that having changed you NTP server from pool.ntp.org you can never set it back. The fix would be to remove ~2 lines of code.

Well, there is a bug there, but not quite the one I expected.
I was expecting that if you changed your NTP server to something other than [FONT=courier\ new]pool.ntp.org[/FONT] in the enigma2 menus then any attempt to reset it to [FONT=courier\ new]pool.ntp.org[/FONT] wouldn't do anything, as NTPserverChanged() in [FONT=courier\ new]mytest.py[/FONT] just returns for that case and doesn't edit [FONT=courier\ new]/etc/default/ntpdate[/FONT].
However, that's not what happens. In practice if you reset the menu item to [FONT=courier\ new]pool.ntp.org[/FONT] the [FONT=courier\ new]/etc/default/ntpdate[/FONT] file ends up with:

NTPSERVERS="pool.ntp.or"

i.e. the final "g" is missing!
No idea how that comes about....yet.

 

[birdman]

Well, there is a bug there, but not quite the one I expected.
I was expecting that if you changed your NTP server to something other than [FONT=courier\ new]pool.ntp.org[/FONT] in the enigma2 menus then any attempt to reset it to [FONT=courier\ new]pool.ntp.org[/FONT] wouldn't do anything, as NTPserverChanged() in [FONT=courier\ new]mytest.py[/FONT] just returns for that case and doesn't edit [FONT=courier\ new]/etc/default/ntpdate[/FONT].
However, that's not what happens. In practice if you reset the menu item to [FONT=courier\ new]pool.ntp.org[/FONT] the [FONT=courier\ new]/etc/default/ntpdate[/FONT] file ends up with:

NTPSERVERS="pool.ntp.or"

i.e. the final "g" is missing!
No idea how that comes about....yet.

Ahh!!!!
What is happening is that as you enter the NTP server setting then NTPserverChanged() gets called for EVERY character entered. So ntpdate is being called for every character change (with probably unresolvable names). This also means that if you forget to Save at the end your setting may be one less char than you typed (hence the missing "g") and if you decide to cancel then it won't actually reset the [FONT=courier\ new]/etc/default/ntpdate[/FONT] file to what it was before.
So, for a simple menu entry, it's a mess.

 

[Joe_90]

I've been thinking about my own particular setup and how come I wasn't having any issues up to December. My config hasn't changed and my wifi dongle and router haven't changed, so there must have been occasions pre-December when NTP sync didn't work during boot due to slow wifi or whatever. However, in the code pre-December there was no "fake-hwclock", therefore there was no plausible time set during boot. If (when) NTP sync failed, then the boot process fell back to transponder sync, which would always be ok in my case as I have the box set to tune to my local DVB-T multiplex. Since the changes in December, there is always a plausible date/time stored and I think that is used if you have "sync by NTP" set and it fails. There is no fallback to transponder time in this case. Then I had the issue of the time being set in the future due to glitches in the ntpdate coding and the system would never go back to the correct time because of the assumption that time could only go forwards, never backwards. I'm thinking that the root of the issue is the storing of the fake-hwclock data.

Using a stored clock time to be used during boot buys us nothing except getting rid of the 1/1/1970 log filenames. If the clock is an hour slow or a day slow or a week slow, then it is wrong when it comes to calculating zap or record or power timers, no matter how plausible it might look. I would vote to remove the fake-hwclock time and go back to the old epoch startup. The real solution is the implementation of a proper, battery-backed RTC in these boxes and that ain't going to happen anytime soon.

 

[birdman]

So, for a simple menu entry, it's a mess.

...for which I now have a fix.

EDIT:

https://github.com/OpenViX/enigma2/pull/211

 

[Joe_90]

... and I have another issue with fake-hwclock.

I have a PowerTimer set which puts the box in deep standby after 60 mins in standby. This is a recurring timer.
When my box boots at 16:50 (PowerTimer into standby mode) in order to run ABM at 17:00 and CrossEPG at 17:05, the standby PowerTimer gets checked during startup and is activated with a start time which is the fake-hwclock time (some hours earlier). Then ntpdate sets the correct time some seconds later. The standby powertimer runs past its 60 minute expiry, the box is already in standby so that check is passed and then the standby powertimer shuts the box down.