Deep standby time? Startup EPG problem

[Joe_90]

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

[adm]

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

[Joe_90]

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.

[adm]

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.

[Joe_90]

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):

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

[adm]

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

[Joe_90]

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.

[birdman]

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

[adm]

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.

[Joe_90]

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.

[Joe_90]

I thought perhaps I was confusing myself as, even with "transponder time", set in the Time menu, I was seeing NTP time adjustments every 30 minutes in the debug log. I thought, maybe, that some of my initial experiments with NTP server settings were somehow "stuck" in a file somewhere and enigma was ignoring that I wanted to use transponder time.

So, I flashed a clean Release 6.1 and started from there. No restores. Just setup my DVB-T and DVB-S and ran ABM and configured EPG. Left at default "transponder time" and left fake-hwclock as is. Didn't touch ntpdate-sync script.

I've established that an NTP time sync is done after enigma starts and every 30 minutes afterwards, irrespective of the fact that "transponder time" is set. Also, every 30 minutes the time is updated from the transponder. So you have both methods adjusting the clock. In addition, at 30 minutes past each hour, a cron job runs ntpdate-sync and adjusts the time also!

On my box (AX61), enigma starts about 17 seconds after the box is booted (real time of boot 16:20:00) and is using the timestamp from fake-hwclock (in this case 15:58:28 plus 15~17 seconds) . Approximately two seconds later this entry appears in the debug log

 19.9117> 15:58:46.0095 [Console] command: /usr/bin/ntpdate-sync

. The messages file contains the following:

May  8 15:58:44 ax61 kern.debug kernel: yaffs: yaffs: MTD device 3 either not valid or unavailable
May  8 15:58:44 ax61 kern.info kernel: tntfs info (device mmcblk0p3, pid 2206): ntfs_fill_super(): fail_safe is enabled.
May  8 16:20:26 ax61 daemon.notice ntpdate[2064]: step time server 89.234.64.77 offset +1295.399109 sec
May  8 16:20:26 ax61 daemon.info automount[2089]: key "logs" not found in map source(s).
May  8 16:20:28 ax61 daemon.notice ntpdate[2258]: adjust time server 89.234.64.77 offset +0.000414 sec
May  8 16:30:01 ax61 authpriv.info crond[2291]: pam_unix(crond:session): session opened for user root(uid=0) by (uid=0)
May  8 16:30:01 ax61 cron.info CROND[2292]: (root) CMD (/usr/bin/ntpdate-sync silent)
May  8 16:30:10 ax61 daemon.notice ntpdate[2296]: adjust time server 161.53.78.71 offset +0.281029 sec
May  8 16:30:10 ax61 cron.info CROND[2291]: (root) CMDEND (/usr/bin/ntpdate-sync silent)
May  8 16:30:10 ax61 authpriv.info CROND[2291]: pam_unix(crond:session): session closed for user root
May  8 17:17:01 ax61 cron.info CROND[2402]: (root) CMD (cd / && run-parts /etc/cron.hourly)
May  8 17:17:01 ax61 cron.info CROND[2401]: (root) CMDEND (cd / && run-parts /etc/cron.hourly)
May  8 17:30:01 ax61 authpriv.info crond[2426]: pam_unix(crond:session): session opened for user root(uid=0) by (uid=0)
May  8 17:30:01 ax61 cron.info CROND[2427]: (root) CMD (/usr/bin/ntpdate-sync silent)
May  8 17:30:09 ax61 daemon.notice ntpdate[2431]: step time server 85.91.1.180 offset +1.159089 sec
May  8 17:30:09 ax61 cron.info CROND[2426]: (root) CMDEND (/usr/bin/ntpdate-sync silent)
May  8 17:30:09 ax61 authpriv.info CROND[2426]: pam_unix(crond:session): session closed for user root

There are two entries for ntpdate, one with PID 2064 and one with PID 2258. I am surmising that PID 2258 is the ntpdate-sync command issued at offset time 19.9117 and is setting (adjusting) the time to 16:20:28. The reason for this is that the ntpdate-sync script seems to take 8 or 9 seconds to run and this time would agree with the offset. The PID 2064 steps the time before this at 16:20:26 and there is a corresponding entry in the debug log:

   25.1424> 16:20:26.6393 [NetworkTime] setting E2 time: 1652023226.6392548

I think this initial stepping of the time is coming from one of the networking checks (if-up.d) perhaps?

Subsequent ntp time updates are shown in the debug log (but not in the messages file) at 30 minute intervals.

<  1825.1441> 16:50:26.6410 [NetworkTime] setting E2 time: 1652025026.640918
<  3625.1450> 17:20:26.6419 [NetworkTime] setting E2 time: 1652026826.6418157
<  5425.1461> 17:50:27.8021 [NetworkTime] setting E2 time: 1652028627.8019857

The cronjob updates at 16:30 and 17:30 shown in the messages file above are not shown in the debug log.

That's all I can work out with my limited knowledge of the system!

I wonder why ntpdate-sync takes 8 or 9 seconds to complete, though? The actual ntp server check would take milliseconds usually. The longest delay I see on a ntp server grab is 28 ms.

pi@raspberrypiB:~ $ ntpq -pn
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
*127.127.28.0    .GPS.            2 l    1   16  377    0.000   -7.488   2.023
o127.127.22.0    .PPS.            0 l    -   16  377    0.000    0.001   0.004
 3.ie.pool.ntp.o .POOL.          16 p    -  512    0    0.000    0.000   0.004
+188.165.3.28    192.168.100.15   2 u  106  512  377   27.635    1.210   0.340
+89.234.64.77    193.120.142.71   2 u  270  512  377   10.171   -0.426   0.136
+162.159.200.1   10.52.9.36       3 u  403  512  377   10.739   -0.525   0.069
+85.91.1.180     217.53.21.92     2 u  507  512  377   10.200   -0.698   0.325
+149.202.156.97  192.168.100.15   2 u  267  512  377   28.075    1.425   0.303
+188.125.64.7    217.146.187.56   2 u   39  512  377   10.202   -0.395   0.082
+162.159.200.123 10.52.9.36       3 u  130  512  377   10.014   -0.881   0.156

[adm]

I wonder why ntpdate-sync takes 8 or 9 seconds to complete, though? The actual ntp server check would take milliseconds usually. The longest delay I see on a ntp server grab is 28 ms.

Perhaps waiting for a Wi-fi connection to be made at boot-up?

[Joe_90]

Perhaps waiting for a Wi-fi connection to be made at boot-up?

No - does every time. See -

May  8 17:30:01 ax61 cron.info CROND[2427]: (root) CMD (/usr/bin/ntpdate-sync silent)
May  8 17:30:09 ax61 daemon.notice ntpdate[2431]: step time server 85.91.1.180 offset +1.159089 sec

[Huevos]

https://github.com/OpenViX/enigma2/c...074a885a5cf783

I just fixed that but doubt it is related.

But to state the obvious, if you have a cronjob set to trigger a script to update from NTP server every 30 minutes, changing a setting in enigma that does not kill that cronjob is not going to affect NTP being fetched.

[birdman]

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.

It occurs to me that the locking in ntpdate-sync is logically incorrect.
What it does (or rather, what it is supposed to do) is to always let the script run, but prevent two processes run the actual ntpdate processing at the same time.
However, if a second process is trying to run ntpdate whilst an earlier one is already running it then the second script should just exit. There is no point in running a second ntpdate immediately after it's just been run.
That would require a different locking mechanism (which is trivial C code - I have the program to do it and have used it for years in my backup scrips specifically to avoid a second starting if there is already one running).