Deep standby time? Startup EPG problem

[ccs]

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

As I mentioned in my previous post, you appear to be storing epg.dat in /etc/enigma2/epg.dat (not the usb stick you said in #1). Is this deliberate?

Shows again in your last debug log.

My ntp looks like this, using pool.ntp.org...

May  6 14:45:24 vuultimo4k daemon.notice ntpdate[1616]: step time server 185.83.169.27 offset +2.068287 sec

Yours appears to be accessing a box on your LAN.

[adm]

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

As I mentioned in my previous post, you appear to be storing epg.dat in /etc/enigma2/epg.dat (not the usb stick you said in #1). Is this deliberate?

It wasn't deliberate. It should have been set to my usb stick but I've just checked and the setting seems to have changed. I've set it back to the usb stick.

My ntp looks like this, using pool.ntp.org...

May  6 14:45:24 vuultimo4k daemon.notice ntpdate[1616]: step time server 185.83.169.27 offset +2.068287 sec

Yours appears to be accessing a box on your LAN.

I'm using transponder time so the option to set pool.ntp.org is no longer available as an option. The box on the LAN is my router.

[ccs]

I use transponder time as well, but still see this cron job running by default......

ntp.jpg

[adm]

I use transponder time as well, but still see this cron job running by default......

ntp.jpg

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

[Joe_90]

Sorry about the delayed response, but was away in the real world for several hours

There's definitely something odd happening at boot time (similar to my issue - also on wifi). From your dmesg file:

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

At startup, ntpdate is stepping the time twice, thus propelling your box into the future! This is exactly what happens on my mutant HD51 and occasionally on my ax61HD, both of which are connected via wifi.

[Joe_90]

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!

[birdman]

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?

[adm]

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?

[adm]

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.

[adm]

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.

[Joe_90]

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.

[birdman]

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.

[birdman]

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?".

[birdman]

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?

[birdman]

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....