Superb quality and spec AB-Com PULSe 4K SE. Crazy offer! Only £99! FREE UK DELIVERY! 4K UHD, Enigma 2, Multiboot 4 images & more!...
Superb quality and spec AB-Com PULSe 4K Rev II Twin Satellite tuner only £149! FREE UK DELIVERY! 4K UHD, Enigma 2, SATA HDD facility, Multiboot 4 images & more!...

[Zgemma H9S] Deep standby time? Startup EPG problem

My router is configured as a time server in the home network and is using 2.europe.pool.ntp.org as the time server.

That's ok, I use a GPS time server on my local LAN also. The cron job (which is not the issue here) will run ntpdate at 30 minutes past the hour, while the default NTP time settings (which I use, but you don't) will run ntpdate every 30 minutes from boot time. Because I use NTP server, I usually disable that cron job. The issue here is that multiple instances of ntpdate are running at startup and are stepping the time into the future. Beyond my pay grade to say why this is happening - @birdman or @huevos may know!
 
Last edited:
Please post the /var/log/messages file (not just the Enigma2 debug log).
That will show what is happening to the system time before enigma2 starts.

EDIT: Although when I look at the startup scripts for my system (et8000) it doesn't seem to call ntpdate to set the time at all! I was sure it did. Although i do have a script (not in use) that gets the time from a local system, which would seem to indicate that ntpdate has never been called.

So, perhaps it is being run during your system start-ups(?), as well as by Enigma2 starting, and if they wait for the network to finalize they could both be running at the same time?
 
Last edited:
Please post the /var/log/messages file (not just the Enigma2 debug log).
That will show what is happening to the system time before enigma2 starts.

I posted both the messages and debug files in post 15


Question 1: Would any Enigma2 boxes work correctly at all if there was no network connection to get the time from a NTP server?
Question 2: Why doesn't a transponder time configuration negate the need for the NTP option?
 
Last edited:
Is it possible the time in the on-screen banner was 3:31 (not 3:13)? The reason I ask is that if ntpdate runs twice at startup, it can cause the clock to be advanced to double the time difference between shutdown time and boot time. Your box was shut down at 23:45 and booted at 01:37 which requires ntpdate to make a step adjustment of 1 hour and 52 minutes. If it ran twice it would briefly step the time twice, making it 03:31.

Although this may appear to be happening (the difference between current time and switch off time being added twice to the switch off time) isn't the logic behind this kind of correction deeply flawed? Shouldn't an interrogation of a NTP server actually result in only the current time being established - it now 1:37! Telling the "box" that its 1:37 once sets 1:37 and telling the box that it's 1:37 twice sets 1:37. Why should there be any reference to the time the box is shut down as that may have been in error and completely irrelevant to setting a new absolute time.
 
Wouldn't a zap timer work? So you end up on th requested channel, but don't do any recording at all?

A zap timer switches the box fully on, zaps to a channel and leaves the box fully on forever*. A recording timer can be configured to switch the box back into deep standby once the recording has finished.

*I do have power timers to switch the box into standby/deep standby after not touching the remote but this is set for 2 hours for normal viewing and not the required <10minutes for fetching the EPG daily.
 
I'm paraphrasing as this is way more complex, but originally the boxes would boot with a date which is the start of the unix epoch (1/1/1970). Vix log files would always be named with 1/1/1970 in the filename. There was code in enigma which checked the time to see if it had been set to something reasonable (much greater than 1/1/1970) before checking recording timers, power timers, epg load etc. etc. enigma essentially waited until a transponder sync or an NTP sync had been done. The process essentially "worked", although the log files always contained 1/1/1970 and some seconds in the filename, so it was tricky to distinguish one from another.

Fast forward to late 2017, when "fake hwclock" was implemented. This routine stores in a file the date/time the box is placed in deep standby. At startup, the file is read and the time is used to establish a "reasonable" date/time before an actual time is obtained from NTP or a transponder/multiplex stream. It's similar to the procedure used in Raspberry Pi models which don't have a realtime clock. Initially I thought that this was a great improvement over the old scheme as the log files now have a "reasonable" date and time in the filename, but I found an issue shortly afterwards (January 2018) on my test machine - a mutant HD51 connected via wifi. I was using NTP sync on that box and found it pushed the system time into the future on some occasions. I reverted to transponder time and it seemed to resolve the issue for a while. @birdman helped me greatly over that period and we tried various tweaks to get my NTP syncs to work reliably without success. In the end, I just disabled the "fake-hwclock" script entirely and reinstated NTP sync. I occasionally get log files with 1/1/1970 date, but 95+% of the time, the logfiles are correctly named and 100% the enigma code always waits for a proper time sync before testing for record timers, autotimers etc.

The thinking behind running ntpdate at startup, I believe, is that ntp will provide a more reliable system time than depending on a transponder time value. On 28.2E the transponder data is mostly very accurate. Other satellites and DVB-T systems may not be so reliable.

The way ntpdate works is by examining the current system time and comparing it to the time received from the NTP server. It calculates the difference in the two values and either "steps" the system time immediately by the difference in value, which results in a jump in the system time, or it "slews" the system time by the new value, which results in a gradual correction of the system clock by varying its frequency. Normally ntpdate would only "step" the time on first run (because the time difference is large) and would always "slew" the time subsequently.

Theoretically, ntpdate should run just once at startup and step the time. Then, it should run either every 30 minutes by default if set, and/or if a cron job to run ntpdate is present and active. In my case, I can see ntpdate running every 30 minutes after startup and also at 30 minutes past the hour, because a system cron job is active.

However, for some reason, ntpdate seems to be running twice in quick succession at startup and is using the stored "fake-hwclock" value as the system time in both instances and then stepping the clock twice. I don't know why this is happening, but it may be due to some recent change. The dev gurus will have to look at the code and startup sequences.
 
A zap timer switches the box fully on, zaps to a channel and leaves the box fully on forever*. A recording timer can be configured to switch the box back into deep standby once the recording has finished.aily.
Fair point.
But you could also set a PowerTimer for Standby just after the Zap timer runs, and another for DeepStandby when the Zap timer would end.
 
I posted both the messages and debug files in post 15
Sorry, missed that.
So, you do have two ntp processes that run:

May 6 16:42:42 zgemmah9s daemon.notice ntpdate[1620]: step time server 192.168.178.1 offset +11067.907306 sec
May 6 19:47:14 zgemmah9s daemon.notice ntpdate[1776]: step time server 192.168.178.1 offset +11067.907504 sec
The question is, "Why?".
 
The thinking behind running ntpdate at startup, I believe, is that ntp will provide a more reliable system time than depending on a transponder time value.
But it should only be run once by enigma2 as it starts.
How is is being run twice?
 
But it should only be run once by enigma2 as it starts.
How is is being run twice?
Hmm...it seems that my et800 runs it twice too!

May 7 18:08:31 et8000 daemon.notice ntpdate[605]: step time server 80.87.128.222 offset +54221.343141 sec
...
May 7 18:08:48 et8000 daemon.notice ntpdate[804]: adjust time server 80.87.128.222 offset +0.002555 sec
The difference being that my first one has finished before the second starts.
But something to work with....
 
@birdman - if you revisit our long bug thread started on 16/01/2018, which is in the Vix bug threads (Unfixable or driver error), you will see similar issues arising over ntpdate-sync being fired several times at startup and subsequently stepping the time into the future.

I spent several hours this afternoon on my wifi connected AX61 trying to provoke that particular error without success. What I'm actually seeing on my system is that enigma is actually being started before the initial ntpdate-sync script achieves a successful ntp server hit. The enigma debug log then has a date of 1/1/1970 (as I'm not using fake-hwclock) and enigma waits until it gets a transponder sync if it doesn't get an ntp sync. In the end, I foregrounded the ntpdate-sync script and then it seemed to delay enigma start until it achieved a sync. There are too many variables for me to achieve a consistent result. Right now I'm using "time by NTP" (because I have a local NTP server) and have disabled fake-hwclock. I also run /etc/enigma2/startup.sh which will force a standalone ntpdate sync so that I get a properly named debug file.

I know you're saying that enigma should be running ntpdate, but I think the ntpdate-sync script is being invoked before enigma starts, which makes sense as it would be good to have a properly set clock before enigma starts its logging. But, there seems to be some timing issues as when these various ntpdate calls are made.
 
Last edited:
Sorry, missed that.
So, you do have two ntp processes that run:

The question is, "Why?".

The time reported in the message file appears to be that after the process took place and not when it was implemented.

May 6 16:42:42 zgemmah9s daemon.notice ntpdate[1620]: step time server 192.168.178.1 offset +11067.907306 sec
May 6 19:47:14 zgemmah9s daemon.notice ntpdate[1776]: step time server 192.168.178.1 offset +11067.907504 sec
 
The time reported in the message file appears to be that after the process took place and not when it was implemented.

May 6 16:42:42 zgemmah9s daemon.notice ntpdate[1620]: step time server 192.168.178.1 offset +11067.907306 sec
May 6 19:47:14 zgemmah9s daemon.notice ntpdate[1776]: step time server 192.168.178.1 offset +11067.907504 sec

When ntpdate first returned it set the system clock to 16:42.
On the second return (which was less than 200 microseconds later) it stepped the clock by a further 11067 seconds which made the time 19:47.
 
When ntpdate first returned it set the system clock to 16:42.
On the second return (which was less than 200 microseconds later) it stepped the clock by a further 11067 seconds which made the time 19:47.

I understand that but shouldn't the second ntp entry say it happened at 16:42 and not 19:47 because that correction (to 19:47) had not been made until after the process.

When checking the time when the picture appeared seconds later something set it back to 16:4x - wouldn't this also be shown somewhere in the logs.

When checking for the missing EPG the other day (rather than checking for time changes) I noticed that I still had missing EPG data when the time was configured for NTP rather than transponder. Today I changed back from transponder to NTP to see if the time stayed incorrect after booting. I assumed after reading the explanations in this thread that if the (double) NTP was putting my time into the future then as the box fully booted the transponder time was immediately correcting it, and if there was no third NTP at the time of boot there would be nothing to correct an incorrectly set time. Unfortunately with the time setting configured for transponder I cannot repeat the error seen with 3 attempts of leaving the box in deep standby for a couple of hours. It may be a rare occurrence as suggested by Joe_90 when time is configured as NTP. In the past couple of days I've seen the error multiple times with the time configured as transponder.
 
Last edited:
I understand that but shouldn't the second ntp entry say it happened at 16:42 and not 19:47 because that correction (to 19:47) had not been made until after the process.

No, because the result of the entry stepped the clock to the new time. Look at my messages file extract. I'm not using fake-hwclock, so my initial system time is 01:00:00 on 1/1/1970. I started my box exactly on the start of a minute, so this is recorded at 24 seconds (plus the initial 2-3 seconds it takes to register the button press at the start before linux starts to boot):

Code:
Jan  1 01:00:23 ax61 kern.info kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan  1 01:00:24 ax61 daemon.info avahi-daemon[2105]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::2e0:4cff:fe88:204f.
Jan  1 01:00:24 ax61 daemon.info avahi-daemon[2105]: New relevant interface wlan0.IPv6 for mDNS.
Jan  1 01:00:24 ax61 daemon.info avahi-daemon[2105]: Registering new address record for fe80::2e0:4cff:fe88:204f on wlan0.*.
May  7 13:26:27 ax61 daemon.notice ntpdate[2246]: step time server 192.168.0.190 offset +1651926361.480602 sec
May  7 13:26:28 ax61 daemon.info automount[2073]: key "logs" not found in map source(s).
 
I understand that but shouldn't the second ntp entry say it happened at 16:42 and not 19:47 because that correction (to 19:47) had not been made until after the process.

When checking the time when the picture appeared seconds later something set it back to 16:4x - wouldn't this also be shown somewhere in the logs.

When checking for the missing EPG the other day (rather than checking for time changes) I noticed that I still had missing EPG data when the time was configured for NTP rather than transponder. Today I changed back from transponder to NTP to see if the time stayed incorrect after booting. I assumed after reading the explanations in this thread that if the (double) NTP was putting my time into the future then as the box fully booted the transponder time was immediately correcting it, and if there was no third NTP at the time of boot there would be nothing to correct an incorrectly set time. Unfortunately with the time setting configured for transponder I cannot repeat the error seen with 3 attempts of leaving the box in deep standby for a couple of hours. It may be a rare occurrence as suggested by Joe_90 when time is configured as NTP. In the past couple of days I've seen the error multiple times with the time configured as transponder.

that should read
Unfortunately with the time setting configured for NTP I cannot repeat the error seen with 3 attempts of leaving the box in deep standby for a couple of hours.

Its not been good couple of days :( Not associated with the box but with a few minor "10 minute" DIY jobs taking hours :(
 
I have had this problem on and off for three years. I put it down to an "unusual" use case on my test box, where it lives in deep standby most of the time, but I then use a short window where it is booted from deep and then runs ABM and CrossEPG or some other EPG gathering method, depending on what I'm testing at the time. But, I have seen several threads recently where users have reported that boxes have set to a future date, so I thought that maybe something had changed in the startup routines. I'm sure that the devs will identify the root cause.
 
If it's always using ntpdate-sync (rather than ntpdate directly) then it would be a simple matter to add a locking mechanism to the script so that it was never running twice.

Oh wait - the ntpdate-sync script already has a lock file in place!!!!

So, why is it not working?

Or is something calling ntpdate directly....
 
that should read
Unfortunately with the time setting configured for NTP I cannot repeat the error seen with 3 attempts of leaving the box in deep standby for a couple of hours.

It's not been good couple of days :( Not associated with the box but with a few minor "10 minute" DIY jobs taking hours :(

:(:(:(:( sods law - my Zgemma refused to boot this Saturday evening. It stuck at the the third boot splash screen (left for an hour). I've now spent 2.5 hours first finding a suitable 8G USB stick and re-flashing from scratch. Too much time getting the wi-fi to connect, finding where I had recorded my password and not being able to get SAMBA to run (again). The latter I've given up with as I realised I haven't used it on this box. I've set up all the configuration from scratch as well as (re) initialising the large capacity USB stick.
 
If it's always using ntpdate-sync (rather than ntpdate directly) then it would be a simple matter to add a locking mechanism to the script so that it was never running twice.

Oh wait - the ntpdate-sync script already has a lock file in place!!!!

So, why is it not working?

Or is something calling ntpdate directly....

You and I checked out ntpdate-sync pretty thoroughly back in 2018. The suggestion you made to me at the time was to remove the backgrounding in the script. I have done that with the current version and it seems to delay the start of enigma, but it certainly gets the NTP sync done properly. There seems to be a difference in startup behaviour on my box (as regards ntpdate) depending on whether you have transponder sync or NTP sync set in the Time setup. In both cases it does an NTP sync at startup, but it seems to be doing it at a different time. I'll do some more experimenting today. Will report back later.
 

OpenViX Feeds Status

Back
Top