[Zgemma H9S] Deep standby time? Startup EPG problem

[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.
[COLOR="#FF0000"]May  8 16:20:26 ax61 daemon.notice ntpdate[2064]: step time server 89.234.64.77 offset +1295.399109 sec[/COLOR]
May  8 16:20:26 ax61 daemon.info automount[2089]: key "logs" not found in map source(s).
[COLOR="#FF0000"]May  8 16:20:28 ax61 daemon.notice ntpdate[2258]: adjust time server 89.234.64.77 offset +0.000414 sec[/COLOR]
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/commit/c58a6ce69b8369f146c23bb48d074a885a5cf783

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

 

[birdman]

In addition, at 30 minutes past each hour, a cron job runs ntpdate-sync and adjusts the time also!

Why is that there?!!!
And why is it a cronjob under root's account rather than a system one in /etc/cron.d?

 

[birdman]

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:

That's wrong.

PID 2064 is the one issued at time offset 19.9117 (aka 15:58:46.0095). This advances the time by +1295.399109 sec, stepping it to 16:20:26, which is the timestamp seen when this change gets logged.

PID 2258 runs 2 secs later and adjusts the clock (i.e. it slews the clock to run a little slow/fast) to adjust it by +0.281029 sec

 

[birdman]

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

Yes.
/etc/network/if-up.d has a symlink to ntpdate-sync.

However, we seem to be drifting away from the real problem, which is how ntpdate gets to run twice in parallel, when everything running it goes via ntpdate-sync, which supposedly has locking to prevent this.

 

[Joe_90]

My logic as regards the PIDs is that only one ntp setting is recorded as initiated in enigma, so I am surmising that it is the higher numbered PID, as the lower numbered PID would be from if-up.d (which would not be recorded in the enigma debug log). Therefore the initial stepping of the time is done from if-up.d and the second slew adjustment is coming from the enigma call to ntpdate-sync and the timing (8ish seconds) is consistent. Obviously the major issue is how, on occasion, the time gets stepped twice. As the ntpdate-syncscript uses a lock file to prevent such an occurrence, there must be another mechanism which may be calling the ntpdate program directly, perhaps?

I still can't see why ntpdate-sync is taking 8-9 seconds to run. I know there is an in-built "ping" to google but that should only take milliseconds.

I have my box set to boot from deep this afternoon and perform ABM and EPGrefresh tasks as a test. I think the fake clock time is going to "trip up" some of the initial checks when enigma starts and cause issues as it has done for me in the past.

 

[birdman]

My logic as regards the PIDs is that only one ntp setting is recorded as initiated in enigma, so I am surmising that it is the higher numbered PID, as the lower numbered PID would be from if-up.d (which would not be recorded in the enigma debug log).

Not if the network takes a few seconds to start (which Wifi ones often do) and the system start-up process has moved on leaving the if-up.d scripts to run in the background.
Anyway, the relevant thing is the time-stamps mentioned in the logs.

I still can't see why ntpdate-sync is taking 8-9 seconds to run.

And I don't know where you get this info from.

I think the fake clock time is going to "trip up" some of the initial checks when enigma starts and cause issues as it has done for me in the past.

It won't affect whether ntpdate runs (although it might affect the result).

 

[Joe_90]

...

And I don't know where you get this info from.

...

In relation to how long ntpdate-sync takes to run.

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

Every time the cron job kicks off at xx:30, it take 8 or 9 seconds before the time is stepped.

 

[Joe_90]

I've just had a jump in time setting myself. This is on my bog standard Release 6.1 build. ntpdate seems to have fired twice and stepped the time 6 hours into the future, then the transponder time kicked in and set the time back correctly. Rela time is 00:17 and fake-hwclock is 18:10. Messages file extract:

May  9 18:10:19 ax61 daemon.info avahi-daemon[2121]: Files changed, reloading.
May  9 18:10:19 ax61 daemon.info avahi-daemon[2121]: Loading service file /services/ftp.service.
May  9 18:10:19 ax61 cron.info crond[2131]: (CRON) STARTUP (1.5.7)
May  9 18:10:19 ax61 cron.info crond[2131]: (CRON) INFO (Syslog will be used instead of sendmail.)
May  9 18:10:19 ax61 cron.info crond[2131]: (CRON) INFO (RANDOM_DELAY will be scaled with factor 35% if used.)
May  9 18:10:20 ax61 daemon.info avahi-daemon[2121]: Server startup complete. Host name is ax61.local. Local service cookie is 2101134608.
May  9 18:10:20 ax61 kern.warn kernel: UDF-fs: warning (device mmcblk0p1): udf_fill_super: No partition found (2)
May  9 18:10:20 ax61 daemon.info avahi-daemon[2121]: Service "FTP file server on ax61" (/services/ftp.service) successfully established.
May  9 18:10:20 ax61 kern.warn kernel: UDF-fs: warning (device mmcblk0p1): udf_fill_super: No partition found (2)
May  9 18:10:20 ax61 kern.info kernel: yaffs: dev is 187695105 name is "mmcblk0p1" rw
May  9 18:10:20 ax61 kern.info kernel: yaffs: passed flags ""
May  9 18:10:20 ax61 kern.debug kernel: yaffs: yaffs: Attempting MTD mount of 179.1,"mmcblk0p1"
May  9 18:10:20 ax61 kern.debug kernel: yaffs: yaffs: MTD device 1 either not valid or unavailable
May  9 18:10:20 ax61 kern.info kernel: yaffs: dev is 187695105 name is "mmcblk0p1" rw
May  9 18:10:20 ax61 kern.info kernel: yaffs: passed flags ""
May  9 18:10:20 ax61 kern.debug kernel: yaffs: yaffs: Attempting MTD mount of 179.1,"mmcblk0p1"
May  9 18:10:20 ax61 kern.debug kernel: yaffs: yaffs: MTD device 1 either not valid or unavailable
May  9 18:10:20 ax61 kern.info kernel: tntfs info (device mmcblk0p1, pid 2168): ntfs_fill_super(): fail_safe is enabled.
May  9 18:10:20 ax61 kern.warn kernel: UDF-fs: warning (device mmcblk0p3): udf_fill_super: No partition found (2)
May  9 18:10:20 ax61 kern.warn kernel: UDF-fs: warning (device mmcblk0p3): udf_fill_super: No partition found (2)
May  9 18:10:20 ax61 kern.info kernel: yaffs: dev is 187695107 name is "mmcblk0p3" rw
May  9 18:10:20 ax61 kern.info kernel: yaffs: passed flags ""
May  9 18:10:20 ax61 kern.debug kernel: yaffs: yaffs: Attempting MTD mount of 179.3,"mmcblk0p3"
May  9 18:10:20 ax61 kern.debug kernel: yaffs: yaffs: MTD device 3 either not valid or unavailable
May  9 18:10:20 ax61 kern.info kernel: yaffs: dev is 187695107 name is "mmcblk0p3" rw
May  9 18:10:20 ax61 kern.info kernel: yaffs: passed flags ""
May  9 18:10:20 ax61 kern.debug kernel: yaffs: yaffs: Attempting MTD mount of 179.3,"mmcblk0p3"
May  9 18:10:20 ax61 kern.debug kernel: yaffs: yaffs: MTD device 3 either not valid or unavailable
May  9 18:10:20 ax61 kern.info kernel: tntfs info (device mmcblk0p3, pid 2207): ntfs_fill_super(): fail_safe is enabled.
May  9 18:10:24 ax61 daemon.err ntpdate[2259]: 185.103.119.60 rate limit response from server.
May 10 00:12:00 ax61 daemon.notice ntpdate[2064]: step time server 158.43.128.33 offset +21693.648083 sec
May 10 00:12:00 ax61 daemon.info automount[2089]: key "logs" not found in map source(s).
May 10 06:13:35 ax61 daemon.notice ntpdate[2259]: step time server 158.43.128.33 offset +21693.648682 sec
May 10 00:17:01 ax61 cron.info CROND[2290]: (root) CMD (cd / && run-parts /etc/cron.hourly)
May 10 00:17:01 ax61 cron.info CROND[2289]: (root) CMDEND (cd / && run-parts /etc/cron.hourly)

Debug log extract:

<    24.2152> 18:10:26.3192 getOEVersion             OE-Alliance 5.1
<    24.4122> 18:10:26.5162 [opentv_zapper] starting...
<    24.4151> 18:10:26.5191 [AutoTimer] Auto Poll Enabled
<    24.4229> 18:10:26.5268 [ABM-Scheduler][Scheduleautostart] reason(0), session None
<    24.4276> 18:10:26.5316 [CI_Assignment] activating ci configs:
<    24.4299> 18:10:26.5339 [SoftcamAutostart] config.misc.softcams.value=None
<    24.4300> 18:10:26.5340 [SoftcamManager] AutoStart Enabled
<    24.4316> 18:10:26.5356 [opentv_zapper][startSession] reason(0), session None
<    24.4318> 18:10:26.5358 [eInit] + (42) eServiceFactoryHisilicon
<    24.4356> 18:10:26.5396 [PowerTimer] PowerTimerEntry(type=wakeuptostandby, begin=Tue May 10 17:50:00 2022)
<    24.4373> 18:10:26.5412 [ABM-Scheduler][Scheduleautostart] reason(0), session <__main__.Session object at 0xb1242688>
<    24.4374> 18:10:26.5413 [ABM-Scheduler][Scheduleautostart] AutoStart Enabled
<    24.4376> 18:10:26.5415 [ABM-Scheduler][AutoScheduleTimer] Schedule Enabled at  Mon 09 May 2022 18:10:26 IST
<    24.4379> 18:10:26.5419 [ABM-Scheduler][scheduledate] Time set to Tue 10 May 2022 18:00:00 IST (now=Mon 09 May 2022 18:10:26 IST)
<    24.4561> 18:10:26.5601 [opentv_zapper][startSession] reason(0), session <__main__.Session object at 0xb1242688>
<    24.4602> 18:10:26.5642 [ImageManager] AutoStart Enabled
<    24.4604> 18:10:26.5644 [ImageManager] Backup Schedule Disabled at (now=Mon 09 May 2022 18:10:26 IST)
<    24.4605> 18:10:26.5645 [BackupManager] AutoStart Enabled
<    24.4606> 18:10:26.5646 [BackupManager] Backup Schedule Disabled at (now=Mon 09 May 2022 18:10:26 IST)
<    24.4682> 18:10:26.5722 [OpenWebif] loading external plugins...
<    24.4687> 18:10:26.5727 [OpenWebif] no plugins to load
<    24.4756> 18:10:26.5796 [OpenWebif] started on 80
<    24.4763> 18:10:26.5803 [Avahi] AvahiServiceEntry (null) (_http._tcp) 80
<    24.4764> 18:10:26.5804 [Avahi] Not running yet, cannot register type _http._tcp.
<    24.4788> 18:10:26.5828 [Skin] Processing screen 'Screensaver', position=(0, 0), size=(1920 x 1080) for module 'Screensaver'.
snip
<    24.8268> 18:10:26.9308 [Skin] Processing screen '<embedded-in-HideVBILine>', position=(0, 0), size=(1920 x 4) for module 'HideVBILine'.
<    24.8397> 18:10:26.9437 [Skin] Processing screen 'ChannelSelection', position=(0, 0), size=(1920 x 1080) for module 'ChannelSelection'.
<    24.8826> 00:12:00.6347 [Skin] Processing screen 'SlimChannelSelection' from list 'SlimChannelSelection, SimpleChannelSelection, ChannelSelection', position=(0, 0), size=(1920 x 1080) for module 'PiPZapSelection'.
<    24.8996> 00:12:00.6517 [Skin] Processing screen 'RdsInfoDisplay', position=(22, 90), size=(1920 x 300) for module 'RdsInfoDisplay'.
<    24.9020> 00:12:00.6541 [Skin] No skin to read or screen to display.
<    24.9024> 00:12:00.6544 [Skin] Processing screen '<embedded-in-RdsInfoDisplaySummary>', position=(?, ?), size=(? x ?) for module 'RdsInfoDisplaySummary'.
<    24.9040> 00:12:00.6561 [Skin] Processing screen 'UnhandledKey', position=(1856, 10), size=(34 x 45) for module 'UnhandledKey'.
<    24.9092> 00:12:00.6613 [Skin] Processing screen 'Dish', position=(30, 90), size=(195 x 303) for module 'Dish'.
<    24.9154> 00:12:00.6675 [Screen] Warning: Skin is missing element 'Tuner' in <class 'Screens.Dish.Dish'>.
<    24.9173> 00:12:00.6693 [Skin] Processing screen 'BufferIndicator', position=(660, 45), size=(600 x 48) for module 'BufferIndicator'.
<    24.9239> 00:12:00.6760 [Skin] Processing screen 'TimeshiftState', position=(150, 67), size=(1620 x 150) for module 'TimeshiftState'.
<    24.9393> 00:12:00.6913 [Screen] Warning: Skin is missing element 'eventname' in <class 'Screens.PVRState.TimeshiftState'>.
<    24.9394> 00:12:00.6915 [Screen] Warning: Skin is missing element 'state' in <class 'Screens.PVRState.TimeshiftState'>.
<    24.9558> 00:12:00.7079 [Screen] Warning: Skin is missing element 'PTSSeekBack' in <class 'Screens.PVRState.TimeshiftState'>.
<    24.9560> 00:12:00.7080 [Screen] Warning: Skin is missing element 'PTSSeekPointer' in <class 'Screens.PVRState.TimeshiftState'>.
<    24.9603> 00:12:00.7124 [Skin] Processing screen 'SubtitleDisplay', position=(0, 0), size=(1920 x 1080) for module 'SubtitleDisplay'.
<    24.9611> 00:12:00.7131 [Screen] Warning: Skin is missing element 'message' in <class 'Screens.SubtitleDisplay.SubtitleDisplay'>.
<    24.9621> 00:12:00.7141 [Notifications] RemovePopup, id = ZapError
<    24.9678> 00:12:00.7198 [Skin] Processing screen 'InfoBar', position=(0, 0), size=(1920 x 1080) for module 'InfoBar'.
<    25.0117> 00:12:00.7637 [Screen] Warning: Skin is missing element 'key_red' in <class 'Screens.InfoBar.InfoBar'>.
<    25.0118> 00:12:00.7639 [Screen] Warning: Skin is missing element 'key_yellow' in <class 'Screens.InfoBar.InfoBar'>.
<    25.0119> 00:12:00.7640 [Screen] Warning: Skin is missing element 'key_blue' in <class 'Screens.InfoBar.InfoBar'>.
<    25.0120> 00:12:00.7641 [Screen] Warning: Skin is missing element 'key_green' in <class 'Screens.InfoBar.InfoBar'>.
<    25.0239> 00:12:00.7759 [Skin] Processing screen 'InfoBarSummary', position=(0, 0), size=(1 x 1) for module 'InfoBarSummary'.
<    25.0389> 00:12:00.7909 [eDVBVolumecontrol] Setvolume: raw: 100 100, -1db: 0 0
<    25.0390> 00:12:00.7910 [eDVBVolumecontrol] Setvolume: raw: 90 90, -1db: 7 7
<    25.0396> 00:12:00.7916 [Skin] Processing screen 'Volume', position=(0, 360), size=(30 x 330) for module 'Volume'.
<    25.0436> 00:12:00.7956 [Screen] Warning: Skin is missing element 'VolumeText' in <class 'Screens.Volume.Volume'>.
<    25.0457> 00:12:00.7978 [Volume] Volume set to 90.
<    25.0463> 00:12:00.7983 [Skin] Processing screen 'Mute', position=(937, 15), size=(45 x 45) for module 'Mute'.
<    25.0507> 00:12:00.8028 [AVSwitch] portlist is ['HDMI']
<    25.0558> 00:12:00.8079 [Skin] Processing screen 'Scart', position=(0, 0), size=(1920 x 1080) for module 'Scart'.
<    25.0625> 00:12:00.8145 [Skin] Processing screen 'AutoVideoModeLabel', position=(1365, 60), size=(495 x 82) for module 'AutoVideoModeLabel'.
<    25.0667> 00:12:00.8188 [Avahi] timeout elapsed
<    25.0669> 00:12:00.8189 [Avahi] avahi_timeout_update
<    25.0670> 00:12:00.8190 [LogManager] Trash Poll Started
<    25.0694> 00:12:00.8215 [NetworkTime] setting E2 time: 1652137920.8214421
<    25.0698> 00:12:00.8218 [LogManager] probing folders
snip

<    26.3278> 00:12:02.0799 [eDVBSectionReader] DMX_SET_FILTER pid=18
<    26.4272> 00:12:02.1793 [Avahi] watch activated: 0x1
<    26.4273> 00:12:02.1794 [Avahi] avahi_timeout_update
<    26.4274> 00:12:02.1794 [Avahi] timeout elapsed
<    26.4274> 00:12:02.1794 [Avahi] avahi_timeout_update
<    26.5314> 06:13:35.9321 [Avahi] watch activated: 0x1
<    26.5315> 06:13:35.9322 [Avahi] avahi_timeout_update
<    26.5316> 06:13:35.9323 [Avahi] timeout elapsed
<    26.5316> 06:13:35.9323 [Avahi] REMOVE service 'gbquadplus' of type '_e2stream._tcp' in domain 'local'
<    26.5316> 06:13:35.9323 REMOVE Peer gbquadplus
<    26.5316> 06:13:35.9324 [Avahi] avahi_timeout_update
<    26.5317> 06:13:35.9324 [Avahi] watch activated: 0x1
<    26.5318> 06:13:35.9325 [Avahi] timeout elapsed
<    26.5318> 06:13:35.9325 [Avahi] REMOVE service 'ax61' of type '_e2stream._tcp' in domain 'local'
<    26.5318> 06:13:35.9325 REMOVE Peer ax61
<    26.5318> 06:13:35.9325 [Avahi] avahi_timeout_update
<    26.5319> 06:13:35.9326 [Avahi] timeout elapsed
<    26.5319> 06:13:35.9326 [Avahi] REMOVE service 'ax61' of type '_e2stream._tcp' in domain 'local'
<    26.5319> 06:13:35.9326 REMOVE Peer ax61
<    26.5319> 06:13:35.9326 [Avahi] avahi_timeout_update
<    26.5321> 06:13:35.9328 [Avahi] watch activated: 0x1
<    26.5322> 06:13:35.9329 [Avahi] avahi_timeout_update
<    26.5322> 06:13:35.9329 [Avahi] timeout elapsed
<    26.5322> 06:13:35.9330 [Avahi] REMOVE service 'ax61' of type '_e2stream._tcp' in domain 'local'
<    26.5323> 06:13:35.9330 REMOVE Peer ax61
<    26.5323> 06:13:35.9330 [Avahi] avahi_timeout_update
<    26.5337> 06:13:35.9344 [Avahi] watch activated: 0x1
<    26.5338> 06:13:35.9345 [Avahi] avahi_timeout_update
<    26.5338> 06:13:35.9345 [Avahi] timeout elapsed
<    26.5338> 06:13:35.9346 [Avahi] Resolving service 'ax61' of type '_e2stream._tcp'
<    26.5343> 06:13:35.9350 [Avahi] avahi_timeout_new
<    26.5349> 06:13:35.9356 [Avahi] avahi_timeout_free
<    26.5351> 06:13:35.9358 [Avahi] avahi_timeout_update
<    26.5352> 06:13:35.9359 [Avahi] avahi_timeout_update
<    26.5353> 06:13:35.9360 [Avahi] timeout elapsed
<    26.5353> 06:13:35.9360 [Avahi] Resolving service 'ax61' of type '_e2stream._tcp'
<    26.5355> 06:13:35.9363 [Avahi] avahi_timeout_new
<    26.5359> 06:13:35.9367 [Avahi] avahi_timeout_free
<    26.5361> 06:13:35.9368 [Avahi] avahi_timeout_update
<    26.5362> 06:13:35.9369 [Avahi] timeout elapsed
<    26.5362> 06:13:35.9369 [Avahi] Resolving service 'ax61' of type '_e2stream._tcp'
<    26.5364> 06:13:35.9371 [Avahi] avahi_timeout_new
<    26.5368> 06:13:35.9375 [Avahi] avahi_timeout_free
<    26.5369> 06:13:35.9376 [Avahi] avahi_timeout_update
<    26.5369> 06:13:35.9376 [Avahi] timeout elapsed
<    26.5371> 06:13:35.9378 [Avahi] avahi_timeout_new
<    26.5376> 06:13:35.9383 [Avahi] avahi_timeout_free
<    26.5376> 06:13:35.9383 [Avahi] avahi_timeout_update
<    26.5377> 06:13:35.9384 [Avahi] timeout elapsed
<    26.5378> 06:13:35.9385 [Avahi] avahi_timeout_new
<    26.5381> 06:13:35.9389 [Avahi] avahi_timeout_free
<    26.5382> 06:13:35.9389 [Avahi] avahi_timeout_update
<    26.5383> 06:13:35.9390 [Avahi] timeout elapsed
<    26.5384> 06:13:35.9391 [Avahi] avahi_timeout_new
<    26.5387> 06:13:35.9394 [Avahi] avahi_timeout_free
<    26.5388> 06:13:35.9395 [Avahi] avahi_timeout_update
<    26.6674> 06:13:36.0681 [Avahi] watch activated: 0x1
<    26.6675> 06:13:36.0683 [Avahi] avahi_timeout_update
<    26.6676> 06:13:36.0683 [Avahi] timeout elapsed
<    26.6676> 06:13:36.0683 [Avahi] Resolving service 'gbquadplus' of type '_e2stream._tcp'
<    26.6678> 06:13:36.0685 [Avahi] avahi_timeout_new
<    26.6684> 06:13:36.0691 [Avahi] avahi_timeout_free
<    26.6684> 06:13:36.0692 [Avahi] avahi_timeout_update
<    26.6688> 06:13:36.0695 [Avahi] watch activated: 0x1
<    26.6688> 06:13:36.0696 [Avahi] avahi_timeout_update
<    26.6689> 06:13:36.0696 [Avahi] timeout elapsed
<    26.6689> 06:13:36.0696 [Avahi] ADD Service 'gbquadplus' of type '_e2stream._tcp' at gbquadplus.local:8001
<    26.6689> 06:13:36.0696 ADD Peer gbquadplus=gbquadplus.local:8001
<    26.6691> 06:13:36.0698 [Avahi] avahi_timeout_new
<    26.6697> 06:13:36.0705 [Avahi] avahi_timeout_free
<    26.6698> 06:13:36.0705 [Avahi] avahi_timeout_update
<    26.7143> 06:13:36.1150 [eDVBVideo0] VIDEO_GET_EVENT SIZE_CHANGED 1440x1080 aspect 3
<    26.7243> 06:13:36.1251 [eDVBVideo0] VIDEO_GET_EVENT PROGRESSIVE_CHANGED 0
<    26.7663> 06:13:36.1670 [eDVBVideo0] VIDEO_GET_EVENT SIZE_CHANGED 1440x1080 aspect 3
<    26.7728> 06:13:36.1735 [eDVBVideo0] VIDEO_GET_EVENT FRAME_RATE_CHANGED 25000 fps
<    26.7731> 06:13:36.1743 [eDVBVideo0] VIDEO_GET_EVENT GAMMA_CHANGED 0
<    26.9701> 06:13:36.3708 [eDVBLocalTimerHandler] dont have correction.. set Transponder Diff
<    26.9705> 06:13:36.3712 [eDVBLocalTimerHandler] update RTC
<    26.9705> 06:13:36.3712 [eDVBLocalTimerHandler] time update to 00:12:01
<    26.9705> 06:13:36.3712 [eDVBLocalTimerHandler] m_time_difference is -21695
<    26.9706> 00:12:01.3713 [eDVBLocalTimerHandler] stepped Linux Time to 00:12:01
<    26.9719> 00:12:01.3726 [eDVBChannel] getDemux cap=00
<    27.2752> 00:12:01.6759 [AVSwitch] setting aspect: 16:9
<    27.2756> 00:12:01.6763 [AVSwitch] setting wss: auto
<    27.2759> 00:12:01.6765 [AVSwitch] setting policy: panscan
<    27.2763> 00:12:01.6770 [AVSwitch] setting policy2: letterbox
<    27.7909> 00:12:02.1916 [eEPGChannelData] start reading events(1652137922)
<    27.7910> 00:12:02.1917 [eDVBSectionReader] DMX_SET_FILTER pid=3842
<    27.7912> 00:12:02.1919 [eDVBSectionReader] DMX_SET_FILTER pid=3003
<    27.7914> 00:12:02.1921 [eDVBSectionReader] DMX_SET_FILTER pid=18
<    27.7917> 00:12:02.1923 [eDVBSectionReader] DMX_SET_FILTER pid=18
<    27.7919> 00:12:02.1925 [eDVBSectionReader] DMX_SET_FILTER pid=18

 

[birdman]

I've just had a jump in time setting myself.

I think we're all agreed that ntpdate-sync can be running twice at the same time by now.

So the questions we should be looking at are:

• how the ntpdate command within that script is running twice at the same time (assuming that is what causes the double jump) and
• why the script isn't written such that the second concurrent run just aborts, rather than tries to wait.

 

[Joe_90]

Is it possible that it's not the ntpdate-sync script running twice, but that it is running once and something else is calling ntpdate directly at the same time? The double set of ntpdate happened just now to me again. I'm going to take ntpdate-sync out of the background and see if it happens on subsequent boots.

 

[birdman]

Is it possible that it's not the ntpdate-sync script running twice, but that it is running once and something else is calling ntpdate directly at the same time? The double set of ntpdate happened just now to me again. I'm going to take ntpdate-sync out of the background and see if it happens on subsequent boots.

Adding a logger call in ntpdate-sync would solve the problem of knowing where the ntpdate runs come from.

Juts needs:

 logger ntpdate-sync running

to be added and an entry will show up in the messages file.

 

[Joe_90]

At the moment I'm experimenting by commenting out the backgrounding in ntpdate-sync. I have run a boot from deep several times now. What happens is that enigma start is delayed by about 8-10 seconds, but, importantly the debug log is named with the correct time and all the initial startup checks for various scheduled events (PowerTimer, ABM-Scheduler, ImageManager, BackupManager, etc.) are based on the correct clock time, not the fake-hwclock time. I don't see the initial ntpdate time step being logged anywhere in the messages file. A couple of seconds into the debug log I see ntpdate-sync being triggered with PID 2252.

<    26.2062> 12:15:27.4194 [Console] command: /usr/bin/ntpdate-sync
<    26.2064> 12:15:27.4195 [eConsoleAppContainer] Starting /bin/sh
<    26.2068> 12:15:27.4199 [Console] pid = 2252

At 12:15:34 I can see ntpdate adjusting (slewing) the time with PID 2255. See the messages file extract below. This would seem to confirm my previous post that the ntpdate-sync coming from enigma is adjusting the time and comes after the initial stepping (or double stepping) of the time which is happening in the boot process but previously was backgrounded. I just can't see the initial time stepping logged anywhere now.

May 10 12:15:26 ax61 kern.debug kernel: yaffs: yaffs: MTD device 3 either not valid or unavailable
May 10 12:15:26 ax61 kern.info kernel: tntfs info (device mmcblk0p3, pid 2204): ntfs_fill_super(): fail_safe is enabled.
[COLOR="#FF0000"]May 10 12:15:34 ax61 daemon.notice ntpdate[2255]: adjust time server 188.125.64.6 offset -0.001396 sec[/COLOR]
May 10 12:15:39 ax61 daemon.info automount[2087]: key "logs" not found in map source(s).
May 10 12:17:01 ax61 cron.info CROND[2272]: (root) CMD (cd / && run-parts /etc/cron.hourly)
May 10 12:17:01 ax61 cron.info CROND[2271]: (root) CMDEND (cd / && run-parts /etc/cron.hourly)

 

[Joe_90]

With the ntpdate-sync script still "foregrounded", I have done another boot from deep, but I added the logger call to the script as suggested. Apart from the console command to ntpdate-sync, I don't see the initial stepping call recorded anywhere.

May 10 13:05:27 ax61 user.notice root: ntpdate-sync running
May 10 13:05:34 ax61 daemon.notice ntpdate[2259]: adjust time server 193.1.12.167 offset +0.000374 sec
May 10 13:05:39 ax61 daemon.info automount[2089]: key "logs" not found in map source(s).

The "foregrounding" seems to continually work for me, with the correct date/time set prior to enigma start so that the filename is correct and the initial schedule timer checks all working based on a real clock time.

I am going to monitor the box for about an hour, so I see the cron job running at 13:30 and I check the 30 minute ntp adjustment which seems to run from within enigma. I will then revert my edits to ntpdate-sync, so that it runs in background and see what transpires.

 

[Joe_90]

I monitored the box and could see the cron job running ntpdate-sync at 13:30 as expected and was logged in /var/log/messages.

The [NetworkTime] process ran just after enigma start and 30 minutes afterwards, again as expected (due to the default setting of 30 minutes in Time menu). This process must call ntpdate directly as this is not logged in /var/log/messages. The debug entries for these updates are:

<    38.5163> 13:05:39.6467 [NetworkTime] setting E2 time: 1652184339.6466897
<  1838.5180> 13:35:40.3850 [NetworkTime] setting E2 time: 1652186140.3849752

After backgrounding ntpdate-sync again, I booted the box. The fake time was 13:42, real time was 13:45. After boot the time was stepped twice - once to 13:45 and then briefly to 13:48, which is the usual twice the difference from fake time. After that the transponder corrected the time.

The debug log shows the usual console call to ntpdate-sync.

<    19.9117> 13:42:25.0149 [eEPGCache] time updated.. but cache file not set yet.. dont start epg!!
<    19.9125> 13:42:25.0157 [Console] command: /usr/bin/ntpdate-sync
<    19.9126> 13:42:25.0158 [eConsoleAppContainer] Starting /bin/sh
<    19.9131> 13:42:25.0163 [Console] pid = 2257

The messages file shows:

May 10 13:42:25 ax61 user.notice root: ntpdate-sync running
May 10 13:45:25 ax61 daemon.notice ntpdate[2067]: step time server 85.91.1.164 offset +175.733991 sec
May 10 13:45:26 ax61 daemon.info automount[2092]: key "logs" not found in map source(s).
May 10 13:48:24 ax61 daemon.notice ntpdate[2262]: step time server 85.91.1.164 offset +175.733705 sec

Note that there is only one "ntpdate-sync running" message. I believe that this is from the console command issued at 13:42:25 (fake time) which has a PID of 2257. The actual ntpdate update associated with this call is PID 2262 which is stepping the time wrongly. I believe the ntpdate time step from PID 2067 is coming from an earlier call which is not logged as it starts before debug and messages files begin, but the ntpdate update happens at about the same time as PID 2262 is finishing. This would be consistent with earlier runs with ntpdate-sync foregrounded which never show the initial time "step" being logged, only the subsequent "slew" from the console command noted in the debug log.

So, my question is - what is actually issuing the console command call to ntpdate-sync noted in the debug log? Is there a reason why the if-up.d call to ntpdate-sync is not being logged anywhere? I don't know how these logs are actually managed.

What I do know, is that foregounding ntpdate-sync by commenting out lines 55 and 79 seems to resolve date handling issues on my AX61, at the expense of a little delay to the time the channel appears on-screen.

 

[Joe_90]

Question for @birdman. Does the following code in ntpdate-sync check that it is being called by if-up.d?

# This is a heuristic: Interfaces are usually brought up during boot, so this is
# the right time to quickly step to the right time, rather than slewing to it.
if [ "$0" = "/etc/network/if-up.d/ntpdate-sync" ]; then
	DELAY="check_online"
	OPTS="-b"
fi

if [ "$METHOD" = loopback ]; then
	exit 0
fi

It is setting the ntpdate option "-b" which forces a time step rather than a slew. I'm presuming calls to ntpdate-sync from other than if-up.d would/should just slew the time?

 

[adm]

Possibly a red herring, but there are three adjustments if the box is booted from power off

May 10 12:22:56 zgemmah9s daemon.info avahi-daemon[1660]: Server startup complete. Host name is zgemmah9s.local. Local service cookie is 3000839176.
May 10 12:22:56 zgemmah9s daemon.info avahi-daemon[1660]: Service "FTP file server on zgemmah9s" (/services/ftp.service) successfully established.
May 10 14:48:54 zgemmah9s daemon.notice ntpdate[1602]: step time server 192.168.178.1 offset +8752.236760 sec
May 10 14:48:56 zgemmah9s daemon.info automount[1628]: key "logs" not found in map source(s).
May 10 14:48:58 zgemmah9s daemon.notice ntpdate[1714]: adjust time server 192.168.178.1 offset +0.000590 sec
May 10 14:49:02 zgemmah9s daemon.notice ntpdate[1729]: adjust time server 192.168.178.1 offset -0.000143 sec